java.util.logging (JUL) messages below INFO level are not recorded in Karaf logs

[ffays]

Deploying Karaf 4.4.3 using Equinox OSGi System Bundle, log messages from java.util.logging.Logger below the INFO level (i.e. FINEST, FINER and FINE) are not recorded in karaf.log

[grgrzybek]

By default, INFO is the level of root logger, so without extra configuration you won't get much.

I've created this BundleActivator:

package grgr.test;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.osgi.framework.BundleActivator;
import org.osgi.framework.BundleContext;
import org.slf4j.LoggerFactory;

public class ActivatorLogging implements BundleActivator {

    private static final Logger LOGGER = LogManager.getLogger(ActivatorLogging.class);
    public static final org.slf4j.Logger LOG = LoggerFactory.getLogger(ActivatorLogging.class);

    @Override
    public void start(BundleContext context) throws Exception {
        StructuredDataMessage msg = new StructuredDataMessage("1", "message", "event");
        msg.put("testKey", "testValue");

        LOGGER.debug(msg);

        LOG.debug("From SLF4J");
        java.util.logging.Logger.getLogger(ActivatorLogging.class.getName()).fine("\"fine\" From java.util.logging");
        java.util.logging.Logger.getLogger(ActivatorLogging.class.getName()).finer("\"finer\" From java.util.logging");
        java.util.logging.Logger.getLogger(ActivatorLogging.class.getName()).finest("\"finest\" From java.util.logging");
    }

    @Override
    public void stop(BundleContext context) throws Exception {
    }

}

And added this to Karaf's etc/org.ops4j.pax.logging.cfg:

log4j2.logger.grgr.name = grgr.test
log4j2.logger.grgr.level = ALL

(See - I have Log4j2 backend, so I need Log4j2 configuration).

And I got this in the log file ($KARAF_HOME/data/log/karaf.log):

2023-03-29T09:07:29,106 | DEBUG | pipe-restart 52  | ActivatorLogging                 | 52 - bundle-simple - 0.1.0.RELEASE | event [1 testKey="testValue"] message
2023-03-29T09:07:29,107 | DEBUG | pipe-restart 52  | ActivatorLogging                 | 52 - bundle-simple - 0.1.0.RELEASE | From SLF4J
2023-03-29T09:07:29,108 | DEBUG | pipe-restart 52  | ActivatorLogging                 | 52 - bundle-simple - 0.1.0.RELEASE | "fine" From java.util.logging
2023-03-29T09:07:29,108 | TRACE | pipe-restart 52  | ActivatorLogging                 | 52 - bundle-simple - 0.1.0.RELEASE | "finer" From java.util.logging
2023-03-29T09:07:29,108 | TRACE | pipe-restart 52  | ActivatorLogging                 | 52 - bundle-simple - 0.1.0.RELEASE | "finest" From java.util.logging

[ffays]

I did compile your example as-is.
I modified etc/org.ops4j.pax.logging.cfg following your directions.
I restarted the Karaf service (hereby I'm testing on a Windows machine)
I even restarted the test.grgr bundle to be sure I did not miss something.

Here is the output in karaf.log:

2023-03-29T18:12:21,568 | DEBUG | Karaf ssh console user karaf | LoggingCommandSessionListener    | 45 - org.apache.karaf.shell.core - 4.4.3 | Executing command: 'start 53'
2023-03-29T18:12:21,570 | DEBUG | pipe-start 53    | configurator                     | 14 - org.apache.felix.configurator - 1.0.16 | Adding bundle grgr.test:1.0.0.202303291811 (53) : starting
2023-03-29T18:12:21,573 | DEBUG | pipe-start 53    | ActivatorLogging                 | 53 - grgr.test - 1.0.0.202303291811 | event [1 testKey="testValue"] message
2023-03-29T18:12:21,574 | DEBUG | pipe-start 53    | ActivatorLogging                 | 53 - grgr.test - 1.0.0.202303291811 | From SLF4J
2023-03-29T18:12:21,574 | DEBUG | pipe-start 53    | configurator                     | 14 - org.apache.felix.configurator - 1.0.16 | Adding bundle grgr.test:1.0.0.202303291811 (53) : active
2023-03-29T18:12:21,574 | DEBUG | pipe-start 53    | InfoBundleTrackerCustomizer      | 44 - org.apache.karaf.shell.commands - 4.4.3 | Ignore incorrect info null provided by bundle grgr.test
2023-03-29T18:12:21,575 | DEBUG | Karaf ssh console user karaf | LoggingCommandSessionListener    | 45 - org.apache.karaf.shell.core - 4.4.3 | Command: 'start 53' returned 'null'

So still not JUL output.

Note 1: I'm using Eclipse Equinox as OSGi system bundle.
Note 2: I found a bit unfair that the ticket has been closed before had a the chance either confirm or infirm that this is working ...

I will retry with a very plain install "vanilla" fresh install, i.e. without Windows Service and without change the OSGi system bundle from Felix to Equinox to see if I've more chance

PS. here is my MANIFEST.MF:

Manifest-Version: 1.0
Bundle-ManifestVersion: 2
Bundle-Name: Test
Bundle-SymbolicName: grgr.test
Bundle-Version: 1.0.0.qualifier
Bundle-Activator: grgr.test.ActivatorLogging
Bundle-RequiredExecutionEnvironment: JavaSE-17
Automatic-Module-Name: grgr.test
Import-Package: org.osgi.framework;version="1.3.0",
 org.apache.logging.log4j;version="[2,3)",
 org.apache.logging.log4j.message;version="[2,3)",
 org.slf4j;version="[1,2)"
Bundle-ActivationPolicy: lazy

[ffays]

On the vanilla install it even worse, I've simply nothing in karaf.log from your test bundle.

I just realized that I've changed in the Windows Service installation, the log4j2.rootLogger.level from INFO to DEBUG in etc/org.ops4j.pax.logging.cfg configuration file.

So in the fresh "vanilla" installation, log4j2.rootLogger.level=INFO ...

Edit: after double checking I discovered that the bundle was not started, starting it, I get the same output:

2023-03-29T19:06:42,832 | DEBUG | pipe-start 52    | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | event [1 testKey="testValue"] message
2023-03-29T19:06:42,833 | DEBUG | pipe-start 52    | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | From SLF4J

Still no messages from java.util.logging

[ffays]

Tested on Linux, still vanilla Karaf installation:

2023-03-29T18:55:20,995 | DEBUG | pipe-start 52    | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | event [1 testKey="testValue"] message
2023-03-29T18:55:20,996 | DEBUG | pipe-start 52    | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | From SLF4J

Still no messages from java.util.logging

[grgrzybek]

Please show me the changes you made to your original Karaf 4.4.3 installation (that you've chosen Equinox and what exactly did you add to etc/org.ops4j.pax.logging.cfg).

If possible, please attach the bundle (source or jar). This simply must work ;)

[ffays]

Some clarifications: For my project I made an "Windows Service" of the Karaf installation using Equinox as OSGi System bundle.

But to test your example I downloaded the latest version, i.e. version 4.4.3, of Karaf OSGi Runtime and deployed it on both a Windows machine and a Linux machine, plain vanilla, i.e. no change for Equinox, still using Felix as it is configured by default!

Deployed the zip (Windows), tar.gz (Linux) in both OSes in the current logged-in user's home directory, started it on both OSes from command line (i.e. no Windows Service, no Unix Daemon) with current logged-in user privileges (note the user hasn't the Windows Admin privilege, and on Linux it is not the root user and Karaf has not been started with sudo)

The only thing I changed to fresh install is the etc/org.ops4j.pax.logging.cfg configuration file, adding these two lines at the end of the file as you instructed me:

log4j2.logger.grgr.name = grgr.test
log4j2.logger.grgr.level = ALL

Then I deployed the bundle.
And ensured that it is properly started

Writting these lines, I just re-do all these steps on the Linux machine.

Shell:

curl -L https://archive.apache.org/dist/karaf/4.4.3/apache-karaf-4.4.3.tar.gz -o ~/Downloads/apache-karaf-4.4.3.tar.gz
tar xzf ~/Downloads/apache-karaf-4.4.3.tar.gz
cat << EOF | tee -a ~/apache-karaf-4.4.3/etc/org.ops4j.pax.logging.cfg
log4j2.logger.grgr.name = grgr.test
log4j2.logger.grgr.level = ALL
EOF
mkdir -p ~/apache-karaf-4.4.3/data/log && touch ~/apache-karaf-4.4.3/data/log/karaf.log
tail -f ~/apache-karaf-4.4.3/data/log/karaf.log &
cd ~/apache-karaf-4.4.3/bin && ./karaf

Karaf:

bundle:install file:///${user.home}/Downloads/grgr.test_1.0.0.202303291811.jar
bundle:start grgr.test
shell:logout

karaf.log

2023-03-30T11:27:15,391 | DEBUG | pipe-bundle:start grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | event [1 testKey="testValue"] message
2023-03-30T11:27:15,392 | DEBUG | pipe-bundle:start grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | From SLF4J

Edit: Karaf 4.4.3 instead of 4.4.2 (same outcome)

[ffays]

Hereby your code compiled and exported as "Plug-in Development => Deployable plug-ins and fragments" (Eclipse Plugin == OSGi bundle) by Eclipse IDE for RCP and RAP Developers

Note: I had to rename the extension from ".jar" to ".zip" in order to have Github accepting the file attachment.
So please rename it back to ".jar" (... as technically Jar files are Zip files)

grgr.test_1.0.0.202303291811.zip

[grgrzybek]

OK, I've checked your example (and removed Bundle-ActivationPolicy: lazy) and indeed - I don't see output below INFO level.

After a quick debugging, I have another reason to NOT use JUL logging ;)

The problem is that pax-logging-log4j2 (default backend used by Karaf 4.4) can alter levels of only existing JUL loggers. If you obtain a JUL logger after pax-logging-log4j2 was started/activated, you simply get a logger with default INFO level (because there's no other JUL configuration).

I'll think (but not this week) about some hacking into the JUL internals, so future loggers use some hand-crafted instances of java.util.logging.Logger.ConfigurationData. But please give me a bit of time.

For now, I recommend to switch to de-facto standard SLF4J ;) Yes - I treat it like this. I know that JavaEE advocates won't agree, but this is quite similar situation to Spring Framework being de-facto standard of Java Enterprise development.

[grgrzybek]

Also when I start this sample bundle, then restart pax-logging-log4j2 bundle and then restart the sample bundle again, the FINE level is logged.

[ffays]

Doing the same steps

Karaf:

bundle:start grgr.test
bundle:restart org.ops4j.pax.logging.pax-logging-log4j2
bundle:restart grgr.test

I confirm that I can see in karaf.log the FINEST, FINER and FINE logs from java.util.logging

2023-03-30T14:41:34,316 | DEBUG | pipe-bundle:restart grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | event [1 testKey="testValue"] message
2023-03-30T14:41:34,317 | DEBUG | pipe-bundle:restart grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | From SLF4J
2023-03-30T14:41:34,319 | DEBUG | pipe-bundle:restart grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | "fine" From java.util.logging
2023-03-30T14:41:34,320 | TRACE | pipe-bundle:restart grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | "finer" From java.util.logging
2023-03-30T14:41:34,321 | TRACE | pipe-bundle:restart grgr.test | ActivatorLogging                 | 52 - grgr.test - 1.0.0.202303291811 | "finest" From java.util.logging

Thank you! Now I've a workaround!

[ffays]

Still I would like to emphasis that going for java.util.logging is not a choice but a constraint.

Possibly I could pick a different logging library for the bundles that that I'm developing.
... And I'm not so fond to the idea to go for Log4J2, first it will add yet another bundle dependency, and last but not least, its is not like Log4J2 never had Common vulnerabilities and Exposures!

That said to come back to the constraint aspect, I'm not the owner of the other bundles that are still using java.util.logging, e.g. SQLServer JDBC Driver, or any other JDBC Driver relying on java.sql.Driver.getParentLogger()

I believe that my troubleshooting nightmare began with pax-logging-api bundle taking over the root java.util.logging.Logger (cf. org.ops4j.pax.logging.internal.Activator line #80) without any indication neither in the Karaf logs nor in its documentation (or maybe is there a Wiki/Documentation somewhere else!?).

I mean if pax-logging-api would read the org.ops4j.pax.logging.skipJUL System Property flag with true as default value, it would let the option to the packager to rely on the well documented java.util.logging.LogManager and to configure it to record the log messages from java.util.logging in a side log file (e.g. etc/data/log/jul.log). It would not be very fancy, but at least it will work.

So would it be possible to ...

1. change the default behavior of org.ops4j.pax.logging.internal.Activator to not take over JUL root Logger by default, i.e. assign true as default value for org.ops4j.pax.logging.skipJUL ?
2. add these lines in $KARAFE_HOME/etc/system.properties to indicate how to take over java.util.logging by the pax-logging-api?

# Change to "true" in order to redirect java.util.logging to "$KARAFE_HOME/data/log/karaf.log"
org.ops4j.pax.logging.skipJUL = false
# Change to "true" to reset the root java.util.logging.LogManager
org.ops4j.pax.logging.skipJULReset = false 

3. add a log message in org.ops4j.pax.logging.internal.Activator to indicate the redirection is effective?
4. document both flags org.ops4j.pax.logging.skipJUL and org.ops4j.pax.logging.skipJULReset in the documentation main Web page?

[grgrzybek]

Thanks again for your analysis.

Definitely there's a problem with JUL logger configured after the backend has been configured. However, because only you've found it, it may mean that JUL is not that popular ;)

Some ancient (without skipJUL) documentation is available here: https://ops4j1.jira.com/wiki/spaces/paxlogging/pages/499286109/Configuration

Sure - Log4J has CVEs, but it also means it's used, analyzed and taken care of. To be honest I think JUL is quite limited (imagine multiple WARs configured in Tomcat, each trying to configure logging differently) and mostly usable with flat-classpath deployments...

So I'll definitely have a look at proper configuration of JUL - in the scenario you've found when the logger is obtained after Log4J2 / Logback is configured.

[ffays]

... imagine multiple WARs configured in Tomcat, each trying to configure logging differently

Tomcat has since a long time addressed this issue with JULI, cf. Logging in Tomcat
And the configuration syntax for JULI is based on the one of JUL with some extensions that are inherent to the fact that JULI handles logs from multiple WARs
(Note here: I can understand that Log4J has different calls and log levels as it predate JUL!)

To my point of view, java.util.logging (JUL), wherever we like it or not, should be considered as a first class citizen as it is the logger that comes along with the JDK.

I appreciate that you envision to put in place another hack to cover this corner case,
still please also consider my 4 recommandations/requests above.
... I understand that coding is fancy, still documentation matters and helps*!

*) E.g. #519 provides a record of org.ops4j.pax.logging team rationale behind the implementation choice with pros and cons.

[globalbus]

I found this bug today, when I'm trying to make CXF little bit more verbose.
I also prefer using slf4j facade, but CXF creators sadly no.

Workaround works, but I lost some time to found what is going on in pax-logging JUL support. Maybe we need an information about known bug in docs?

[grgrzybek]

As mentioned in ops4j/org.ops4j.pax.jms#65, documentation is a bit lacking in ops4j projects. These are community driven project with quite little interest these days (OSGi's golden age is long gone I guess...).

(Un)fortunately, known bugs should be simply visible at this page ;) https://github.com/ops4j/org.ops4j.pax.logging/issues

And I really know that this particular problem can be fixed - I just didn't have time to do it...

[paul-mcculloch]

I found this issue today when trying to enable low level logging for the MS SQL JDBC driver which (as mentioned above) uses JUL. @ffays suggestion of an option to not try and take over JUL and just let me write a logging.properties would work for me.