[logback-dev] [JIRA] Commented: (LBCLASSIC-256) java.util.logging propagated level changes are lost because of race condition with garbage collection

[Mark Mielke (JIRA)]

    [ http://jira.qos.ch/browse/LBCLASSIC-256?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12408#action_12408 ] 

Mark Mielke commented on LBCLASSIC-256:
---------------------------------------

Just spent a number of hours trying to figure this out... I failed... but luckily I had an inkling of what to look for and stumbled upon this issue.

I'm a new user to Logback trying it out for the first time, and I immediately found jul-to-slf4j to not work properly for named loggers. After reading the above, I was able to work around the issue for the time being like this:

{noformat}
    /* TODO: Remove once bug is fixed: http://jira.qos.ch/browse/LBCLASSIC-256 */
    static final java.util.logging.Logger[] PERSISTENT_LOGGERS = new java.util.logging.Logger[] {
            java.util.logging.Logger.getLogger("LOGGER1"),
            java.util.logging.Logger.getLogger("LOGGER2"),
            java.util.logging.Logger.getLogger("LOGGER3")
    };

    static {
        /* Initialize SLF4J bridge. This re-routes logging through java.util.logging to SLF4J. */
        java.util.logging.LogManager.getLogManager().reset();
        SLF4JBridgeHandler.install();
    }
{noformat}

Bingo. Adding that first static final made the problem disappear...

In my case, it's happening on a regular Java application running on slf4j-api 1.6.4 / jul-to-slf4j 1.6.4 /  logback-classic 1.0.2 / RHEL 5.5 / x86-32 / Java SE 7u4.

Please fix... because other than this one really ugly blemish... I really like that I can throw away my file rolling implementation and use Logback instead... Thanks!

> java.util.logging propagated level changes are lost because of race condition with garbage collection
> -----------------------------------------------------------------------------------------------------
>
>                 Key: LBCLASSIC-256
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-256
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.9.28
>         Environment: win7 64-bit, bootstrapped in a Tomcat server
>            Reporter: Samuel Stanojevic
>            Assignee: Ceki Gulcu
>         Attachments: LevelChangePropagator.java
>
>
> I have bootstrapped logback in my Tomcat server, and have setup JUL to redirect logging requests to SLF4J by adding the following in my logging.properties:
> .handlers = org.slf4j.bridge.SLF4JBridgeHandler
> Anyways, my setup works pretty nicely.  The problem is when I try to activate the JUL LevelChangePropagator, the info doesn't quite propagate as expected.
> Here is my config:
> <configuration debug="true">
>   <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
>     <resetJUL>true</resetJUL>
>   </contextListener>
>   
>   <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
>     <!-- encoders are assigned the type
>          ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
>     <encoder>
>       <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
>     </encoder>
>     <target>System.out</target>
>   </appender>
>   <root level="ERROR">
>     <appender-ref ref="STDOUT" />
>   </root>
>   
>   <logger name="test.propagation" level="TRACE"/> <!-- race condition here? -->
> </configuration>
> The problem is that if my app tries to do:
>   java.util.logging.Logger.getLogger("test.propagation").fine("hello world");
> ..., it doesn't print.
> I have confirmed that the bug is because, even though the LevelChangePropagator class does propagate the level change info to JUL, it fails to keep a strong reference to the logger that it just changed.  By not keeping a strong reference, and because the JUL LogManager only keeps WeakReferences to loggers, then the GC has time to clear out the change before the app's first attempt to use the logger.  (see java.util.logging.LogManager#addLogger where the javadoc says "The application should retain its own reference to the Logger object to avoid it being garbage collected.  The LogManager may only retain a weak reference")
> To test my hunch, I patched the LevelChangePropagator class by adding a global hashset of java.util.logging.Logger, and I systematically add the loggers to the hashset in the method "propagate(logger,level)". After this patch, my logging started working as expected.
> My fix may not be the best, and may have implications that I did not think about, but I think something along those lines needs to be done to fix the bug.

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira