JBoss EAP deadlocks log4j RollingFileAppenders and java.io.PrintStream

Environment

• JBoss Enterprise Application Platform (EAP)
  • 6.x
  • 7.x
• Log4J deployed to the application war file.
• Separate application and server log streams.
• org.jboss.as.logging.per-deployment = false

Issue

• Application logging stops writing to logs and periodically rotating
• A deadlock between multiple RollingFileAppenders:

Resolution

• Remove application level log4j RollingFileAppenders or ensure it does not have log4j debug enabled in the log4j properties file or through the log4j.configDebug or log4j.debug system properties.

Root Cause

• RollingFileAppender is printing debug messages about its activity through stdout and the app is writing through stdout to the log appender. Look for:

Diagnostic Steps

• Run a set of thread dumps when it happens and look for BLOCKED threads on java.io.PrintStream.

    "Thread-2158" daemon prio=10 tid=0x00007ffb80077000 nid=0x7f61 waiting for monitor entry [0x00007ffbaae86000]
    java.lang.Thread.State: BLOCKED (on object monitor)
        at java.io.PrintStream.println(PrintStream.java:806)
        - waiting to lock <0x000000074ac95720> (a java.io.PrintStream)
        at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:474)
        at org.apache.log4j.helpers.LogLog.debug(LogLog.java:100)
        at org.apache.log4j.RollingFileAppender.rollOver(RollingFileAppender.java:153)
        at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:280)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        - locked <0x000000074c79a260> (a org.apache.log4j.RollingFileAppender)
        at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:34)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:302)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:310)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:310)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:310)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:719)
        at org.apache.log4j.Category.callAppenders(Category.java:69)
        at org.apache.log4j.Category.forcedLog(Category.java:121)
        at org.apache.log4j.Category.info(Category.java:241)
  
    "http-127.0.0.1:38443-5" daemon prio=10 tid=0x00007ffb8c019000 nid=0x6e40 waiting for monitor entry [0x00007ffba8a05000]
    java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
        - waiting to lock <0x000000074c79a260> (a org.apache.log4j.RollingFileAppender)
        at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:34)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:302)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:310)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:719)
        at org.jboss.logmanager.Logger.log(Logger.java:504)
        at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71)
        - locked <0x000000074ac95788> (a java.lang.StringBuilder)
        at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
        at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
        - locked <0x000000074ac95840> (a sun.nio.cs.UTF_8$Decoder)
        at java.io.PrintStream.write(PrintStream.java:482)
        - locked <0x000000074ac95720> (a java.io.PrintStream)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
        at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
        - locked <0x000000074ac95c18> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
        at java.io.PrintStream.newLine(PrintStream.java:546)
        - locked <0x000000074ac95720> (a java.io.PrintStream)
        at java.io.PrintStream.println(PrintStream.java:807)
        - locked <0x000000074ac95720> (a java.io.PrintStream)
        at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:474)
    ...
  

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.