JUL to SLF4J Bridge

Question

I'm currently observing that a 3rd party library (namely restfb) is using java.util.logging and I'm seeing those logs end up in STDOUT even though I don't have an SLF4J console appender configured in my logback.xml. I also have the jul-to-slf4j bridge in my classpath. Does the jul-to-slf4j bridge only log to the appenders configured by logback when the bridge is installed or does it also log to stdout?

Innerve

Answer 1

You need to call SLF4JBridgeHandler.install(). You also need to enable all log levels at the root logger (reason in excerpt below) in java.util.logging and remove the default console appender.

This handler will redirect jul logging to SLF4J. However, only logs enabled in j.u.l. will be redirected. For example, if a log statement invoking a j.u.l. logger disabled that statement, by definition, will not reach any SLF4JBridgeHandler instance and cannot be redirected.

The whole process can be accomplished like so

import java.util.logging.Logger;
import org.slf4j.bridge.SLF4JBridgeHandler;

SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();
Logger.getLogger("").setLevel(Level.FINEST); // Root logger, for example.

You can set the level to something higher than finest for performance reasons, but you won't be able to turn those logs on without enabling them in java.util.logging first (for the reason mentioned above in the excerpt).

Silviasilviculture

Interesting, I was under the impression that having the bridge in the classpath was enough. Is this only necessary for JUL? – Innerve

Yes. The reason is that the jul-to-slf4j bridge cannot replace classes in the java.util.logging package to do the redirection statically as it does for the other bridge implementations. Instead it has to register a handler on the root logger and listen for logging statements like any other handler. It will then redirect those logging statements. – Silviasilviculture

The performance concerns are pretty bad. Makes me lean towards not using the bridge. – Innerve

I found that if any part of the application creates JUL Logger objects, for example in static initializers, before this procedure is executed, their log levels are not changed. – Rick

The LevelChangePropagator addresses performance issues if you use Logback: logback.qos.ch/manual/configuration.html#LevelChangePropagator – Android

In my case Logger.getLogger(<concrete log package or class>).setLevel(Level.FINEST) helps instead of Logger.getLogger("global").setLevel(Level.FINEST); – Hinterland

As of Java 1.7, Logger.getLogger("global") can be replaced with Logger.getGlobal() - marginally more convenient! – Calandracalandria

Or replace Logger.getLogger("global") to Logger.getLogger("") – Candelabra

@Android the level change propagator negates the need for the last line, right? Logger.getLogger("").setLevel(Level.FINEST) – Hugues

Answer 2

As mentioned in the javadocs for SLF4JBridgeHandler, you get either install SLF4JBridgeHandler programmatically by invoking:

 // Optionally remove existing handlers attached to j.u.l root logger
 SLF4JBridgeHandler.removeHandlersForRootLogger();  // (since SLF4J 1.6.5)

 // add SLF4JBridgeHandler to j.u.l's root logger, should be done once during
 // the initialization phase of your application
 SLF4JBridgeHandler.install();

or via logging.properties

 // register SLF4JBridgeHandler as handler for the j.u.l. root logger
 handlers = org.slf4j.bridge.SLF4JBridgeHandler

As for performance, the section on jul-to-slf4j bridge discusses this issue. In essence, since you are already using logback, enabling the LevelChangePropagator should yield good performance regardless of the load.

Okechuku

Have you ever seen instances where java.lang.ClassNotFoundException: org.slf4j.bridge.SLF4JBridgeHandler happens even though the SLF4JBridgeHandler does exist on the classpath? I seem to get this when I use -Djava.util.logging.config.file= to specify the logging.properties file. – Innerve

@TaylorLeese .. I am facing the same issue currently, could you please let me know if you found a way to fix that? Look into this SO for more info.. #16473301 – Faint

@Faint The only workaround I found was initializing the bridge in code rather than via the property file. – Innerve

@TaylorLeese.. thanks! But how do I configure tomcat so that it doesnt log its default format during startup? Could you check the SO link #16473301 I think your comments might be helpful for me to solve this issue. Thanks! – Faint

would'nt it be nice if there was something like a maven dependency that contains a ready configured logging.properties and the Bridge ? SO you could add it for example to maven-plugin depedencies section where you have no access otherwise – Obligate

Answer 3

I use SLF4J and new Postgres driver 42.0.0

According changelog it use java.util.logging

To have driver logs it is enough:

1. Add jul-to-slf4j bridge:

   <dependency>
       <groupId>org.slf4j</groupId>
       <artifactId>jul-to-slf4j</artifactId>
       <version>${slf4j.version}</version>
       <scope>runtime</scope>
   </dependency>
   

2. Add in logback.xml (logback-test.xml)

   <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
       <resetJUL>true</resetJUL>
   </contextListener>
   
   <appender ...
   
   <logger name="org.postgresql" level="trace"/>
   

3. Add in code

   static {
       SLF4JBridgeHandler.install();
   }
   

Candelabra

This is a complete solution. – Alansen

In my case I had to prepend SLF4JBridgeHandler.removeHandlersForRootLogger() inside static block. In other case logger logged messages twice. – Allheal

Answer 4

My solution :

SLF4JBridgeHandler.install();
java.util.logging.LogManager.getLogManager().getLogger("").setLevel( Level.INFO);

placing jul-to-slf4j on your app libs or glassfish libs, these redirect JUL to SLF4J (and thus in my case to LOG4J)

then for Jersey, you could do something like :

<logger name="com.sun.jersey" additivity="false">
    <level value="WARN" />
    <appender-ref ref="JVM" />
    <appender-ref ref="CONSOLE" />
</logger>   

<logger name="com.sun.common.util.logging" additivity="false">
    <level value="ERROR" />
    <appender-ref ref="JVM" />
    <appender-ref ref="CONSOLE" />
</logger>

the last config is to avoid to be polluted by other loggers

Thao

Answer 5

Solution that seems nice (considering the circumstances with the JUL bridging) and works for me, since I only have to write everything in the logback.groovy file.

1. (If you are not using logback.groovy configuration or logback at all, of course you have to put the logic part into some class (e.g. like class MyApp { static { /* log init code here */ } ... }).)

2. src/logback.groovy:

    import org.slf4j.bridge.SLF4JBridgeHandler
    import ch.qos.logback.classic.jul.LevelChangePropagator
   
    // for debug: just to see it in case something is logging/initialized before
    System.out.println( 'my myapp logback.groovy is loading' )
   
    // see also: http://logback.qos.ch/manual/configuration.html#LevelChangePropagator
    // performance speedup for redirected JUL loggers
    def lcp = new LevelChangePropagator()
    lcp.context = context
    lcp.resetJUL = true
    context.addListener(lcp)
   
    // needed only for the JUL bridge: https://mcmap.net/q/236058/-jul-to-slf4j-bridge
    java.util.logging.LogManager.getLogManager().reset()
    SLF4JBridgeHandler.removeHandlersForRootLogger()
    SLF4JBridgeHandler.install()
    java.util.logging.Logger.getLogger( "global" ).setLevel( java.util.logging.Level.FINEST )
   
    def logPattern = "%date |%.-1level| [%thread] %20.20logger{10}|  %msg%n"
   
    appender("STDOUT", ConsoleAppender) {
        encoder(PatternLayoutEncoder) {
            pattern = logPattern
        }
    }
   
    /*// outcommenting in dev will not create dummy empty file
    appender("ROLLING", RollingFileAppender) {  // prod
        encoder(PatternLayoutEncoder) {
            Pattern = "%date %.-1level [%thread] %20.20logger{10}  %msg%n"
        }
        rollingPolicy(TimeBasedRollingPolicy) {
            FileNamePattern = "${WEBAPP_DIR}/log/orgv-fst-gwt-%d{yyyy-MM-dd}.zip"
        }
    }
    */
   
    appender("FILE", FileAppender) {  // dev
   
        // log to myapp/tmp (independent of running in dev/prod or junit mode:
   
        //System.out.println( 'DEBUG: WEBAPP_DIR env prop:  "."='+new File('.').absolutePath+',  \${WEBAPP_DIR}=${WEBAPP_DIR},  env=' + System.getProperty( "WEBAPP_DIR" ))
        String webappDirName = "war"
        if ( new File( "./../"+webappDirName ).exists() )  // we are not running within a junit test
            file = "../tmp/myapp.log"
        else  // junit test
            file = "tmp/myapp-junit-tests.log"
   
        encoder(PatternLayoutEncoder) { pattern = logPattern }
    }
   
    // without JUL bridge:
    //root(WARN, ["STDOUT", "ROLLING"])  // prod
    //root(DEBUG, ["STDOUT", "FILE"])  // dev
   
    // with JUL bridge: (workaround: see links above)
    def rootLvl = WARN
    root(TRACE, [/*"STDOUT",*/ "FILE"])
    // I manually added all "root package dirs" I know my libs are based on to apply
    // the root level to the second "package dir level" at least
    // depending on your libs used you could remove entries, but I would recommend
    // to add common entries instead (feel free to edit this post if you like to
    // enhance it anywhere)
    logger( "antlr", rootLvl )
    logger( "de", rootLvl )
    logger( "ch", rootLvl )
    logger( "com", rootLvl )
    logger( "java", rootLvl )
    logger( "javassist", rootLvl )
    logger( "javax", rootLvl )
    logger( "junit", rootLvl )
    logger( "groovy", rootLvl )
    logger( "net", rootLvl )
    logger( "org", rootLvl )
    logger( "sun", rootLvl )
   
   
    // my logger setup
   
    logger( "myapp", DEBUG )
   
   
    //logger( "org.hibernate.SQL", DEBUG )  // debug: log SQL statements in DEBUG mode
    //logger( "org.hibernate.type", TRACE )  // debug: log JDBC parameters in TRACE mode
    logger( "org.hibernate.type.BasicTypeRegistry", WARN )  // uninteresting
   
    scan("30 seconds")  // reload/apply-on-change config every x sec
   

(recommended to be used by me since you can react with Java code vars/functions as you can see in here with, e.g. SLF4JBridgeHandler or the log dir regarding webappDirName)

(left the file complete since it gives a better impression how everything can be setup or as a starting template)

(may be relevant to somebody - my env: slf4j 1.7.5, logback 1.1.2, groovy 2.1.9)

Seminal

You are amazing !! ... thank you, this configuration is really cool !! ;) :) – Iago

Answer 6

In addition to configuration commands provided at answer by Dev. In the code I'm working with there is a lot of trace-level (FINEST) messages wrapped with isLoggable check generated by 3rd-party libraries. So enabling all the levels unconditionally doesn't look like a good idea.

I'm using SLF4J Simple Logger and it doesn't have means to dynamically change logging levels. Thus I've added following snippet of code to automatically tune java util logging levels based on slf4j simple logger configuration passed via system properties:

import java.util.logging.Level;
import java.util.logging.Logger;

class Main {
    static {
        java.util.Map<String,Level> levelMap = new java.util.HashMap<>();
        levelMap.put("TRACE", Level.FINEST);
        levelMap.put("DEBUG", Level.FINE);
        levelMap.put("INFO", Level.INFO);
        levelMap.put("WARN", Level.WARNING);
        levelMap.put("ERROR", Level.SEVERE);
        levelMap.put("OFF", Level.OFF);

        for (String property : System.getProperties().stringPropertyNames()) {
            if (property.startsWith(org.slf4j.simple.SimpleLogger.LOG_KEY_PREFIX)) {

                String logger = property.replaceFirst(org.slf4j.simple.SimpleLogger.LOG_KEY_PREFIX, "");
                String value = System.getProperty(property).toUpperCase();

                Level level = levelMap.getOrDefault(value, Level.INFO);
                Logger.getLogger(logger).setLevel(level);
            }
        }

        org.slf4j.bridge.SLF4JBridgeHandler.removeHandlersForRootLogger();
        org.slf4j.bridge.SLF4JBridgeHandler.install();
    }
}

P.S. this snippet doesn't handle Simple Logger settings defined in simplelogger.properties file on your classpath. Assuming those are static and corresponding JUL tuning could be performed as needed.

The LevelChangePropagator available in Logback basically does the same but dynamically tracks Level changes.

Romelda