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: Logback dev list
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
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
