[logback-user] FW: Antwort: Deadlock in case of console appender and system.out/err captured
Dancewicz Grzegorz
Grzegorz.Dancewicz at trapezegroup.pl
Thu May 22 12:21:42 CEST 2014
Hi,
Last days I had to update from logback 0.9.15 to the 1.1.2.
Since this update the multithreaded test I have, dies in a deadlock. This test simply tries to simultaneously write to System.err and System.out in different threads. I use the logback under SLF4J(1.7.7) logging facade and additionally I also redirect the System.out and System.err into the the logback via SLF4J. For this purpose I have written my own OutputStream which I set as System.out and System.err (different instance for each). This stream writes forward using the ILogger (logback). Additionally the logback is configured in a way, that (among others) it has a ConsoleAppender from logback.core package. Finally, this results in the ConsoleTarget class using System.out/System.err to write to the console and here the deadlock happens.
Does anyone had similar case or problems? Something must have changed in the locking system of Logback as the multithreaded test case passes with version 0.9.15 of Logback.
I also tried to replace my own capturing stream written for System.out and System.err with the stuff from sysout-ver-slf4j from lidalia (project information link: http://projects.lidalia.org.uk/sysout-over-slf4j/project-summary.html) but the dealock behavior was exactly the same.
I will appreciate any hints and help.
Below there is a thread dump from jvisualvm and also the logback configuration used + test snippet:
Found one Java-level deadlock:
=============================
"Thread-226":
waiting to lock monitor 0x19ebc774 (object 0x04621280, a java.io.PrintStream),
which is held by "Thread-28"
"Thread-28":
waiting to lock monitor 0x188392e4 (object 0x0461afe8, a java.io.PrintStream),
which is held by "Thread-27"
"Thread-27":
waiting for ownable synchronizer 0x0ab25c88, (a java.util.concurrent.locks.ReentrantLock$FairSync),
which is held by "Thread-28"
Java stack information for the threads listed above:
===================================================
"Thread-226":
at java.io.PrintStream.write(PrintStream.java:523)
- waiting to lock <0x04621280> (a java.io.PrintStream)
at java.io.PrintStream.print(PrintStream.java:669)
at mhcc.cci.logging.SystemOutErrTest$4.run(SystemOutErrTest.java:349)
at java.lang.Thread.run(Thread.java:744)
"Thread-28":
at java.io.PrintStream.write(PrintStream.java:478)
- waiting to lock <0x0461afe8> (a java.io.PrintStream)
at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:36)
at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:135)
at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
at ch.qos.logback.classic.Logger.error(Logger.java:563)
at mhcc.cci.logging.internal.Slf4JLoggerWrapper.error(Slf4JLoggerWrapper.java:573)
at mhcc.cci.logging.internal.LoggerOutputStream.writeToLog(LoggerOutputStream.java:223)
at mhcc.cci.logging.internal.LoggerOutputStream.handleLogFragment(LoggerOutputStream.java:170)
at mhcc.cci.logging.internal.LoggerOutputStream.flush(LoggerOutputStream.java:150)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x04621280> (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 <0x04621400> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.newLine(PrintStream.java:546)
- locked <0x04621280> (a java.io.PrintStream)
at java.io.PrintStream.println(PrintStream.java:807)
- locked <0x04621280> (a java.io.PrintStream)
at mhcc.cci.logging.SystemOutErrTest$4.run(SystemOutErrTest.java:353)
at java.lang.Thread.run(Thread.java:744)
"Thread-27":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0ab25c88> (a java.util.concurrent.locks.ReentrantLock$FairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:229)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
at ch.qos.logback.classic.Logger.info(Logger.java:620)
at mhcc.cci.logging.internal.Slf4JLoggerWrapper.info(Slf4JLoggerWrapper.java:333)
at mhcc.cci.logging.internal.LoggerOutputStream.writeToLog(LoggerOutputStream.java:213)
at mhcc.cci.logging.internal.LoggerOutputStream.handleLogFragment(LoggerOutputStream.java:170)
at mhcc.cci.logging.internal.LoggerOutputStream.flush(LoggerOutputStream.java:150)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x0461afe8> (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 <0x0461b168> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.newLine(PrintStream.java:546)
- locked <0x0461afe8> (a java.io.PrintStream)
at java.io.PrintStream.println(PrintStream.java:807)
- locked <0x0461afe8> (a java.io.PrintStream)
at mhcc.cci.logging.SystemOutErrTest$3.run(SystemOutErrTest.java:336)
at java.lang.Thread.run(Thread.java:744)
Found 1 deadlock.
================================
Logback configuration:
<?xml version="1.0" encoding="UTF-8" ?>
<!-- logback configuration to be used throughout testing -->
<configuration scan="true" scanPeriod="120 seconds">
<jmxConfigurator />
<conversionRule
conversionWord="bundle"
converterClass="mhcc.cci.logging.internal.BundleMarkerConverter" />
<conversionRule
conversionWord="category"
converterClass="mhcc.cci.logging.internal.CategoryMarkerConverter" />
<!-- this appender is used by the unit tests -->
<appender name="TEST"
class="mhcc.cci.logging.internal.test.LogbackAppenderQueue"/>
<appender name="STDOUT"
class="ch.qos.logback.core.MHCCConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>%date{HH:mm:ss.SSS} %-5level [%-15.15thread] %-25.25logger{25} [%mdc] %msg%n</pattern>
</layout>
</appender>
<appender name="LOGFILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>${user.home}/dcvl/logs/component.log</File>
<Append>true</Append>
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{ISO8601}\t*\t%level\t%category\t[%-29.29thread]\t%26.26bundle/%-36.36logger{36}\t[%mdc]\t*\t%msg%n
</Pattern>
</layout>
<rollingPolicy
class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<FileNamePattern>${user.home}/dcvl/logs/component.%i.log.zip</FileNamePattern>
<MinIndex>0</MinIndex>
<MaxIndex>10</MaxIndex>
</rollingPolicy>
<triggeringPolicy
class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>50MB</MaxFileSize>
</triggeringPolicy>
</appender>
<appender name="AUDITLOGFILE" class="ch.qos.logback.core.FileAppender">
<Filter class="mhcc.cci.logging.internal.CategoryFilter">
<category>AUDIT</category>
</Filter>
<File>${user.home}/dcvl/logs/audit.log</File>
<Append>true</Append>
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{ISO8601}\t*\t%level\t%category\t[%-29.29thread]\t%26.26bundle/%-36.36logger{36}\t[%mdc]\t*\t%msg%n</Pattern>
</layout>
</appender>
<!-- this logger is used by the unit tests -->
<logger name="TEST" level="TRACE">
<appender-ref ref="TEST" />
</logger>
<logger name="mhcc.cci.configurator.dsl.modelprovider.internal.RuntimeMHCfgURIConverter" level="INFO" />
<logger name="mhcc.cci.logging.internal.Slf4jBundleEventLogger" level="INFO" />
<logger name="org.springframework" level="WARN" />
<logger name="org.springframework.osgi" level="WARN" />
<root level="debug">
<appender-ref ref="STDOUT" />
<appender-ref ref="LOGFILE" />
<appender-ref ref="AUDITLOGFILE" />
</root>
</configuration>
=================================
Test snippet:
final int NUM_TEST_THREADS = 2 * 100; // must be en even number
final ConcurrentLinkedQueue<Exception> exceptions = new ConcurrentLinkedQueue<Exception>();
final Runnable useOut = new Runnable() {
@Override
public void run() {
try {
System.out.print( "dummy text, " );
Thread.yield();
System.out.println( "rest of text" );
} catch ( Exception e ) {
exceptions.add( e );
}
}
};
final Runnable useErr = new Runnable() {
@Override
public void run() {
try {
System.err.print( "dummy text, " );
Thread.yield();
System.err.println( "rest of text" );
} catch ( Exception e ) {
exceptions.add( e );
}
}
};
Thread[] testThreads = new Thread[ NUM_TEST_THREADS ];
for ( int i = 0; i < NUM_TEST_THREADS; i += 2 ) {
testThreads[ i ] = new Thread( useOut );
testThreads[ i + 1 ] = new Thread( useErr );
}
// all threads run in parallel
for ( int i = 0; i < NUM_TEST_THREADS; i++ ) {
testThreads[ i ].start();
}
for ( int i = 0; i < NUM_TEST_THREADS; i++ ) {
testThreads[ i ].join();
}
With best regards,
Grzegorz Dancewicz
More information about the Logback-user
mailing list