JPPF Issue Tracker
star_faded.png
Please log in to bookmark issues
bug_report_small.png
CLOSED  Bug report JPPF-343  -  Use of log4j2 with console appender causes slave node to hang
Posted Oct 25, 2014 - updated Aug 15, 2018
icon_info.png This issue has been closed with status "Closed" and resolution "RESOLVED".
Issue details
  • Type of issue
    Bug report
  • Status
     
    		 Closed
  • Assigned to
    lolo4j
  • Progress
       
  • Type of bug
    Not triaged
  • Likelihood
    Not triaged
  • Effect
    Not triaged
  • Posted by
    lolo4j
  • Owned by
    Not owned by anyone
  • Category
    Node
  • Resolution
    RESOLVED
  • Priority
    Normal
  • Reproducability
    Always
  • Severity
    Normal
  • Targetted for
    icon_milestones.png JPPF 4.2.x
Issue description
When using a slave node configured with log4j2 with a console appender, if the tasks executed by that node generate too much output to the console via logging, then the node hangs on a write operation by the log4j2 console appender, with the following call stack: 
"Processing-0001" - Thread t@17 - java.lang.Thread.State: RUNNABLE
  at java.io.FileOutputStream.writeBytes(Native Method)
  at java.io.FileOutputStream.write(FileOutputStream.java:345)
  at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
  at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
  - locked <12fba172> (a java.io.BufferedOutputStream)
  at java.io.PrintStream.write(PrintStream.java:482)
  - locked <46244d1a> (a java.io.PrintStream)
  at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:122)
  - locked <794209ef> (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:365)
  at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:112)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1341)
  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1299)
  at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:177)
  at sample.test.deadlock.MyTask.run(MyTask.java:57)
  at org.jppf.server.node.NodeTaskWrapper.run(NodeTaskWrapper.java:145)
  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
  at java.util.concurrent.FutureTask.run(FutureTask.java:262)
  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
  at java.util.concurrent.FutureTask.run(FutureTask.java:262)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
  at java.lang.Thread.run(Thread.java:744)
 
  Locked ownable synchronizers:
  - locked <14ec621e> (a java.util.concurrent.ThreadPoolExecutor$Worker)
 Analysis of the issue:
  • the log4j2 console appender, upon creation, will point to the stream defined for the process' standard output, which is a pipe between the slave node and its parent process (the master node)
  • the slave node configuration has properties that redirect the standard output to a file "system_out.log". This happens after the console appender's initialization.
  • The problem is that 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
  • There is a workaround consisting in setting the follow="true" attribute in the appender configuration (it is "false" by default)
Steps to reproduce this issue
  • start a driver
  • configure a node with log4j2 logging, with a console appender
  • provision one slave node
  • execute enough tasks that generate log statements on the slave node
  • ==> the slave node will hang on a log write statement, as explained in the problem description

#2
Comment posted by
lolo4j
Oct 25, 03:58
Proposed fix:
  • in the node provisioning code, we set the "jppf.redirect.out = system_out.log" and "jppf.redirect.err = system_err.log" properties on the slave node. These properties are not overridable.
  • instead, we propose to use ProcessBuilder.redirectOutput(new File(slaveDir, "system_err.log")) and similar statement for the error stream, just before starting the slave
  • the difference is that the file redirection is set upon the JVM startup, which will allow log4j2 to pick it up immediately
#4
Comment posted by
lolo4j
Oct 25, 09:21
fixed in