Deadlock in log4j2 (with JBoss)

Question

A simple Spring-based war application, with a typical log4j2.xml. When JBoss is shut down normally, it hangs with a thread deadlock inside log4j2 so the shutdown procedure never finishes and the process has to be killed. JBoss is EAP 6.3 (AS 7.4.0), JDK is 1.8.0_20.

Anything that can be done?

Log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <RollingFile name="file" append="true"
                     fileName="myapp.log"
                     filePattern="myapp-$${date:yyyy-MM}/app-%d{MM-dd-yyyy}.log" >
            <PatternLayout pattern="%d{DEFAULT} %-5p [%t] %c - %m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy />
            </Policies>
            <DefaultRolloverStrategy max="5000"/>
        </RollingFile>
    </Appenders>

    <Loggers>
        <Root level="debug">
            <AppenderRef ref="file"/>
        </Root>
    </Loggers>
</Configuration>

Thread dump below.

Found one Java-level deadlock:
=============================
"ServerService Thread Pool -- 110":
  waiting to lock monitor 0x000000001f884068 (object 0x00000000c412bff0, a org.apache.log4j.ConsoleAppender),
  which is held by "MSC service thread 1-10"
"MSC service thread 1-10":
  waiting to lock monitor 0x000000001d75ee88 (object 0x00000000c06805a0, a java.io.PrintStream),
  which is held by "log4j-shutdown"
"log4j-shutdown":
  waiting to lock monitor 0x000000001f884068 (object 0x00000000c412bff0, a org.apache.log4j.ConsoleAppender),
  which is held by "MSC service thread 1-10"

Java stack information for the threads listed above:
===================================================
"ServerService Thread Pool -- 110":
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
        - waiting to lock <0x00000000c412bff0> (a org.apache.log4j.ConsoleAppender)
        at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:79)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
        at org.jboss.logmanager.Logger.log(Logger.java:672)
        at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:50)
        at org.jboss.logging.Logger.logf(Logger.java:2096)
        at org.jboss.as.web.WebLogger_$logger.unregisterWebapp(WebLogger_$logger.java:183)
        at org.jboss.as.web.deployment.WebDeploymentService.doStop(WebDeploymentService.java:167)
        at org.jboss.as.web.deployment.WebDeploymentService.access$100(WebDeploymentService.java:58)
        at org.jboss.as.web.deployment.WebDeploymentService$2.run(WebDeploymentService.java:111)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
        at org.jboss.threads.JBossThread.run(JBossThread.java:122)
"MSC service thread 1-10":
        at java.io.PrintStream.write(PrintStream.java:478)
        - waiting to lock <0x00000000c06805a0> (a java.io.PrintStream)
        at org.jboss.stdio.StdioContext$DelegatingPrintStream.write(StdioContext.java:264)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
        - locked <0x00000000c412ce30> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
        at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        - locked <0x00000000c412bff0> (a org.apache.log4j.ConsoleAppender)
        at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:79)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
        at org.jboss.logmanager.Logger.log(Logger.java:672)
        at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:50)
        at org.jboss.logging.Logger.logf(Logger.java:2096)
        at org.jboss.web.CoyoteLogger_$logger.pauseHttpConnector(CoyoteLogger_$logger.java:794)
        at org.apache.coyote.http11.Http11Protocol.pause(Http11Protocol.java:235)
        at org.apache.catalina.connector.Connector.pause(Connector.java:998)
        at org.jboss.as.web.WebConnectorService.stop(WebConnectorService.java:419)
        - locked <0x00000000c1014728> (a org.jboss.as.web.WebConnectorService)
        at org.jboss.msc.service.ServiceControllerImpl$StopTask.stopService(ServiceControllerImpl.java:2088)
        at org.jboss.msc.service.ServiceControllerImpl$StopTask.run(ServiceControllerImpl.java:2049)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
"log4j-shutdown":
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
        - waiting to lock <0x00000000c412bff0> (a org.apache.log4j.ConsoleAppender)
        at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:79)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
        at org.jboss.logmanager.Logger.log(Logger.java:506)
        at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71)
        - locked <0x00000000c0680600> (a java.lang.StringBuilder)
        at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
        at org.jboss.stdio.WriterOutputStream.write(WriterOutputStream.java:124)
        - locked <0x00000000c0680770> (a sun.nio.cs.SingleByte$Decoder)
        at java.io.PrintStream.write(PrintStream.java:480)
        - locked <0x00000000c06805a0> (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 <0x00000000c0680b48> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
        at java.io.PrintStream.write(PrintStream.java:527)
        - locked <0x00000000c06805a0> (a java.io.PrintStream)
        at java.io.PrintStream.print(PrintStream.java:669)
        at java.io.PrintStream.println(PrintStream.java:806)
        - locked <0x00000000c06805a0> (a java.io.PrintStream)
        at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:474)
        at org.apache.logging.log4j.status.StatusConsoleListener.log(StatusConsoleListener.java:81)
        at org.apache.logging.log4j.status.StatusLogger.logMessage(StatusLogger.java:216)
        at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1336)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1325)
        at org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:551)
        at org.apache.logging.log4j.core.jmx.Server.unregisterAllMatching(Server.java:315)
        at org.apache.logging.log4j.core.jmx.Server.unregisterStatusLogger(Server.java:261)
        at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:234)
        at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:217)
        at org.apache.logging.log4j.core.LoggerContext.stop(LoggerContext.java:225)
        at org.apache.logging.log4j.core.LoggerContext$ShutdownThread.run(LoggerContext.java:482)
        at java.lang.Thread.run(Thread.java:745)

Found 1 deadlock.

Answer 1

This looks like a JBoss bug. The package org.apache.log4j is not used in log4j 2 any more. The namespace in log4j 2 is org.apache.logging.log4j. So this is a log4j-1.x based log library, and it looks like it is a JBoss internal adaptation. I recommend you file a bug report with JBoss.