JBoss EAP 7/6 deadlocks on a logging ConsoleHandler and java.io.PrintStream

Solution Verified - Updated 6 Aug 2024

Environment

Red Hat JBoss Enterprise Application Platform (EAP)
- 6.x
- 7.x

Issue

JBoss EAP 7/6 became unresponsive. Thread dumps showed the following deadlock:

"http-/0.0.0.0:80-2":
        at java.util.logging.StreamHandler.publish(StreamHandler.java:174)
        - waiting to lock <0x00000000f93c4498> (a java.util.logging.ConsoleHandler)
        at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:290)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        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 <0x00000000fa687ef8> (a java.lang.StringBuilder)
        at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
        at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
        - locked <0x00000000fa68c960> (a sun.nio.cs.UTF_8$Decoder)
        at java.io.PrintStream.write(PrintStream.java:432)
        - locked <0x00000000fa687e90> (a java.io.PrintStream)
        at org.jboss.stdio.StdioContext$DelegatingPrintStream.write(StdioContext.java:225)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
        - locked <0x00000000f93deff0> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
        at java.util.logging.StreamHandler.flush(StreamHandler.java:225)
        - locked <0x00000000f93de058> (a java.util.logging.ConsoleHandler)
        at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:89)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:290)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
        at org.jboss.logmanager.Logger.log(Logger.java:672)
        at org.jboss.logmanager.Logger.log(Logger.java:684)
        at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:40)
        at org.jboss.logging.Logger.debug(Logger.java:382)
        ...

"http-/0.0.0.0:80-1":
        at java.io.PrintStream.flush(PrintStream.java:285)
        - waiting to lock <0x00000000fa687e90> (a java.io.PrintStream)
        at org.jboss.stdio.StdioContext$DelegatingPrintStream.flush(StdioContext.java:209)
        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:278)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
        - locked <0x00000000f93c6680> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
        at java.util.logging.StreamHandler.flush(StreamHandler.java:225)
        - locked <0x00000000f93c4498> (a java.util.logging.ConsoleHandler)
        at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:89)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:290)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:298)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
        at org.jboss.logmanager.Logger.log(Logger.java:672)
        at org.jboss.logmanager.Logger.log(Logger.java:684)
        at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:40)
        at org.jboss.logging.Logger.debug(Logger.java:382)
        ...

There is a deadlock between multiple ConsoleAppenders, for example:

"ServerService Thread Pool -- 58":
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
	- waiting to lock <0x0000000702fa6888> (a org.apache.log4j.ConsoleAppender)
	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 <0x0000000702fa9458> (a java.lang.StringBuilder)
	at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
	at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
	- locked <0x0000000702fa9510> (a sun.nio.cs.UTF_8$Decoder)
	at java.io.PrintStream.write(PrintStream.java:482)
	- locked <0x0000000702fa93f0> (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 <0x0000000700121e10> (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 <0x00000007001213b8> (a org.apache.log4j.ConsoleAppender)
	at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:34)

"ServerService Thread Pool -- 75":
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
	- waiting to lock <0x00000007001213b8> (a org.apache.log4j.ConsoleAppender)
	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 <0x0000000700123fe0> (a java.lang.StringBuilder)
	at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
	at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
	- locked <0x0000000700124098> (a sun.nio.cs.UTF_8$Decoder)
	at java.io.PrintStream.write(PrintStream.java:482)
	- locked <0x0000000700123f78> (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 <0x0000000702fa72c8> (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 <0x0000000702fa6888> (a org.apache.log4j.ConsoleAppender)
	at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:34)

Resolution

Remove log4j ConsoleAppender from application-level code and log configs.
For versions below JBoss EAP 6.4.2, upgrade to JBoss EAP 6.4.2+ or later.

As a workaround a simple change on the configuration is to disable stdout/stderr in the JBoss EAP logging subsystem:

            <logger category="stdout">
                <level name="OFF"/>
            </logger>
            <logger category="stderr">
                <level name="OFF"/>
            </logger>

Root Cause

An application level logging config is set up with a ConsoleAppender along with a ConsoleAppender already defined in the JBoss level logging subsystem. This causes the STDOUT of each ConsoleAppender to feed into each other and cause potential deadlocks.
Content from issues.jboss.org is not included.LOGMGR-117
This content is not included.BZ-1196228

Diagnostic Steps

Troubleshoot using thread dumps and additional steps mentioned in Java application unresponsive
Check application level log configs for appenders writing to the console/standard output.

SBR

Product(s)

Red Hat JBoss Enterprise Application Platform

Components

Category

Troubleshoot

Tags

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.