logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Laurent Cohen (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-880) ConsoleAppender hangs when writing to System.out in a spawned JVM
Date Sat, 25 Oct 2014 02:36:33 GMT

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

Laurent Cohen commented on LOG4J2-880:
--------------------------------------

I was able able to reproduce the same problem in similar circumstances - and registered this
[JPPF bug|http://www.jppf.org/tracker/tbg/jppf/issues/JPPF-343] with full details.

My analysis of the problem:

* the log4j2 console appender, upon creation, will point to the stream defined for the child
process' standard output, which is a pipe between the process and its parent process
* the child process is configured to redirect the standard output to a file "system_out.log".
This happens after the console appender's initialization.
* The problem is that, unless configured otherwise, the console appender will continue to
write to the same stream, from which the parent process is not reading. Thus the stream buffer
will fill quickly, until the appender blocks because there's is no space left in the buffer
* a workaround consists in setting the follow="true" attribute in the appender configuration
(it is "false" by default)

Thus, I believe that the behavior of the console appender is in fact to be expected. You can
reproduce the same hanging behavior without Log4j2, using System.out.println() statements
in the child process: if the parent process is not reading from the stream on the other side
of the pipe, the child process will also block on a System.out.println() at some point in
time.

Furthermore, as far as I know the Java I/O stream APIs do not provide any way to determine
the state of a buffered stream, in particular you can't know how much space is available in
the buffer, so it's very difficult if not impossible to determine whether the next write()
operation will block or not.

To conclude, my take on this is that it may not be a Log4j2 bug and the only thing, if any,
that should be changed, is the default value for the "follow" attribute.

> 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)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message