[jira] [Created] (LOG4J2-880) ConsoleAppender hangs when writing to System.out in a spawned JVM

Discussion:

Daniel Widdis (JIRA)

2014-10-23 01:55:35 UTC

Daniel Widdis created LOG4J2-880:
------------------------------------

Summary: ConsoleAppender hangs when writing to System.out in a spawned JVM
Key: LOG4J2-880
URL: https://issues.apache.org/jira/browse/LOG4J2-880
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.0.2
Reporter: Daniel Widdis

I am using Log4J2 in an application using Java Parallel Processing Framework (www.jppf.org). One of the features of JPPF is node provisioning, in which a node process can spawn additional JVMs. However, since the spawned JVMs do not have a "console" the only way to access System.out is by redirecting it to a file, which is done automatically.

By default, the ConsoleAppender sets {{follow="false"}}. However, rather than exiting gracefully doing nothing, it locks an OutputStreamManger and never releases it. This causes the application to hang.

The problem is easily worked around by setting {{follow="true"}} on the appender. However, I propose that the default behavior for {{follow="false"}} should simply return without doing anything, rather than locking resources.

Relevant stack trace of the thread holding the lock is shown below. The {{writeBytes()}} method never returned. Other threads attempted to write but were blocked because of this lock.

"pool-5-thread-6" prio=6 tid=0x000000000c0c2000 nid=0x2ce4 runnable [0x000000000d9ae000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.write(Unknown Source)
- locked <0x00000000d0063960> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(Unknown Source)
- locked <0x00000000d0063940> (a java.io.PrintStream)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:122)
- locked <0x00000000d00638e0> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:106)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:428)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:410)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:365)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
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.warn(AbstractLogger.java:1738)

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Daniel Widdis (JIRA)

2014-10-23 02:40:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-880?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Daniel Widdis updated LOG4J2-880:
---------------------------------
Description:
I am using Log4J2 in an application using Java Parallel Processing Framework (www.jppf.org). One of the features of JPPF is node provisioning, in which a node process can spawn additional JVMs. However, since the spawned JVMs do not have a "console" the only way to access System.out is by redirecting it to a file, which is done automatically.

By default, the ConsoleAppender sets {{follow="false"}}. However, rather than exiting gracefully doing nothing, it locks an OutputStreamManger and never releases it. This causes the application to hang.

The problem is easily worked around by setting {{follow="true"}} on the appender. However, I propose that the default behavior for {{follow="false"}} when System.out is unavailable (as in a spawned JVM) should simply return without doing anything, rather than locking resources.

Relevant stack trace of the thread holding the lock is shown below. The {{writeBytes()}} method never returned. Other threads attempted to write but were blocked because of this lock.

"pool-5-thread-6" prio=6 tid=0x000000000c0c2000 nid=0x2ce4 runnable [0x000000000d9ae000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.write(Unknown Source)
- locked <0x00000000d0063960> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(Unknown Source)
- locked <0x00000000d0063940> (a java.io.PrintStream)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:122)
- locked <0x00000000d00638e0> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:106)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:428)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:410)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:365)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
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.warn(AbstractLogger.java:1738)

was:
I am using Log4J2 in an application using Java Parallel Processing Framework (www.jppf.org). One of the features of JPPF is node provisioning, in which a node process can spawn additional JVMs. However, since the spawned JVMs do not have a "console" the only way to access System.out is by redirecting it to a file, which is done automatically.

By default, the ConsoleAppender sets {{follow="false"}}. However, rather than exiting gracefully doing nothing, it locks an OutputStreamManger and never releases it. This causes the application to hang.

The problem is easily worked around by setting {{follow="true"}} on the appender. However, I propose that the default behavior for {{follow="false"}} should simply return without doing anything, rather than locking resources.

Relevant stack trace of the thread holding the lock is shown below. The {{writeBytes()}} method never returned. Other threads attempted to write but were blocked because of this lock.

"pool-5-thread-6" prio=6 tid=0x000000000c0c2000 nid=0x2ce4 runnable [0x000000000d9ae000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.write(Unknown Source)
- locked <0x00000000d0063960> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(Unknown Source)
- locked <0x00000000d0063940> (a java.io.PrintStream)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:122)
- locked <0x00000000d00638e0> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:106)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:428)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:410)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:365)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
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.warn(AbstractLogger.java:1738)

Post by Daniel Widdis (JIRA)
ConsoleAppender hangs when writing to System.out in a spawned JVM
-----------------------------------------------------------------
Key: LOG4J2-880
URL: https://issues.apache.org/jira/browse/LOG4J2-880
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.0.2
Reporter: Daniel Widdis
I am using Log4J2 in an application using Java Parallel Processing Framework (www.jppf.org). One of the features of JPPF is node provisioning, in which a node process can spawn additional JVMs. However, since the spawned JVMs do not have a "console" the only way to access System.out is by redirecting it to a file, which is done automatically.
By default, the ConsoleAppender sets {{follow="false"}}. However, rather than exiting gracefully doing nothing, it locks an OutputStreamManger and never releases it. This causes the application to hang.
The problem is easily worked around by setting {{follow="true"}} on the appender. However, I propose that the default behavior for {{follow="false"}} when System.out is unavailable (as in a spawned JVM) should simply return without doing anything, rather than locking resources.
Relevant stack trace of the thread holding the lock is shown below. The {{writeBytes()}} method never returned. Other threads attempted to write but were blocked because of this lock.
"pool-5-thread-6" prio=6 tid=0x000000000c0c2000 nid=0x2ce4 runnable [0x000000000d9ae000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.write(Unknown Source)
- locked <0x00000000d0063960> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(Unknown Source)
- locked <0x00000000d0063940> (a java.io.PrintStream)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:122)
- locked <0x00000000d00638e0> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:106)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:428)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:410)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:365)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
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.warn(AbstractLogger.java:1738)

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Gary Gregory (JIRA)

2014-10-23 15:18:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-880?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14181455#comment-14181455 ]

Gary Gregory commented on LOG4J2-880:
-------------------------------------

Thank you for your report. Would you be willing to provide a patch?

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Daniel Widdis (JIRA)

2014-10-23 15:27:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-880?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14181466#comment-14181466 ]

Daniel Widdis commented on LOG4J2-880:
--------------------------------------

I'll do my best.... patch should be easy. Figuring out the condition to test on notsomuch...

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)