[
https://issues.apache.org/jira/browse/LOG4J2-1457?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15365057#comment-15365057
]
Leon Finker edited comment on LOG4J2-1457 at 7/6/16 8:58 PM:
-------------------------------------------------------------
I was able to reproduce it consistently in debugger. I've set a conditional
breakpoint in:
at
org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
The condition being that the className.contains the class name that has the
static initializer.
Another breakpoint was in the static initializer of the class in question. I
also added a for loop to make sure to fill up the disruptor buffer from
initializer (-DAsyncLogger.RingBufferSize=512):
static {
Exception e = new Exception();
for(int i =0; i<1024; ++i) {
logger.error(e);
}
}
For the logger was carefull not to specify the class name in question, but
simply:
private static Logger logger = Logger.getLogger("test");
Once the breakpoint in class static initializer was hit, I let it log the
exception once and kept it suspended. This caused the breakpoint in
initializeClass to be hit. I kept it suspended. I then switched back to the
thread with static initializer and let it go through the loop. This filled up
the buffer and blocked the class initializer. I then resumed the thread with
initializeClass. They have both deadlocked.
Then I have made local log4j2 changes to load class without initializer. The
deadlock doesn't happen any longer. So this does solve the issue. Even if the
other thread is still in breakpoint in class initializer, the call to
Class.forName(className, false, loader); still succeeds and doesn't block
anymore.
I now realize what caused the bug to show up. Apparently there were two
exceptions logged from the static initializer and the second exception log
happened just at the time when the ring buffer was full. This caused the
deadlock.
was (Author: leonfin):
I was able to reproduce it consistently in debugger. I've set a conditional
breakpoint in:
at
org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
The condition being that the className.contains the class name that has the
static initializer.
Another breakpoint was in the static initializer of the class in question. I
also added a for loop to make sure to fill up the disruptor buffer from
initializer (-DAsyncLogger.RingBufferSize=512):
static {
Exception e = new Exception();
for(int i =0; i<1024; ++i) {
logger.error(e);
}
}
Once the breakpoint in class static initializer was hit, I let it log the
exception once and kept it suspended. This caused the breakpoint in
initializeClass to be hit. I kept it suspended. I then switched back to the
thread with static initializer and let it go through the loop. This filled up
the buffer and blocked the class initializer. I then resumed the thread with
initializeClass. They have both deadlocked.
Then I have made local log4j2 changes to load class without initializer. The
deadlock doesn't happen any longer. So this does solve the issue. Even if the
other thread is still in breakpoint in class initializer, the call to
Class.forName(className, false, loader); still succeeds and doesn't block
anymore.
I now realize what caused the bug to show up. Apparently there were two
exceptions logged from the static initializer and the second exception log
happened just at the time when the ring buffer was full. This caused the
deadlock.
> Class loader deadlock when using async logging
> ----------------------------------------------
>
> Key: LOG4J2-1457
> URL: https://issues.apache.org/jira/browse/LOG4J2-1457
> Project: Log4j 2
> Issue Type: Bug
> Affects Versions: 2.6.1
> Environment: On CentOS 6.7 and Java 1.8.0_60.
> Reporter: Leon Finker
> Priority: Critical
> Attachments: threaddump.txt
>
>
> We've encountered a class loading deadlock. Please review attached thread
> dump. Is it possible to have an option of pre-initializing the exception's
> thread stack on the caller's thread? It's hard to predict what libraries are
> doing in their classes' static initializers and may eventually end up logging
> and causing deadlock.
> In the attached thread dump here are the threads of interest:
> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0
> tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
> java.lang.Thread.State: RUNNABLE
> at java.lang.Class.forName0(Native Method)
> ...
> and
> "1A03340:Company:japan" #568 prio=5 os_prio=0 tid=0x00007ff871677000
> nid=0x725 runnable [0x00007ff74bd27000]
> ...<clinit>...
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
