- logback-dev - mailman3.qos.ch

[JIRA] (LOGBACK-1422) Deadlock with logging
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

MJ created LOGBACK-1422: --------------------------- Summary: Deadlock with logging Key: LOGBACK-1422 URL: https://jira.qos.ch/browse/LOGBACK-1422 Project: logback Issue Type: Bug Affects Versions: 1.2.3 Environment: jdk8 Reporter: MJ Assignee: Logback dev list Multithreaded java service Threadpool with each thread doing logging high request rate A number of threads like the one below waiting for 0x00000003c0658e90 "pool-6-thread-110" #155 prio=5 os_prio=0 tid=0x00007f90c80b1000 nid=0xd7 waiting on condition [0x00007f8fd59d8000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000003c0658e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:197) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.info(Logger.java:579) at com.k2io.validator.repository.ValidationRepository.constructPmapWithTrail(ValidationRepository.java:555) at com.k2io.validator.ValidationService$ValidationCallable.getAgrePmap(ValidationService.java:329) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:167) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:70) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) And 0x00000003c0658e90 is held by – why is this not releasing the lock "pool-6-thread-87" #129 prio=5 os_prio=0 tid=0x00007f90d405d000 nid=0xb6 runnable [0x00007f8fd73f2000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) - locked <0x00000003c06e8890> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:480) - locked <0x00000003c06e8870> (a java.io.PrintStream) at java.io.FilterOutputStream.write(FilterOutputStream.java:97) at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37) at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.info(Logger.java:579) at com.k2io.validator.repository.ValidationRepository.constructPmapWithTrail(ValidationRepository.java:555) at com.k2io.validator.ValidationService$ValidationCallable.getAgrePmap(ValidationService.java:329) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:167) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:70) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - <0x00000003c0658e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) - <0x00000003c11c30e8> (a java.util.concurrent.ThreadPoolExecutor$Worker) -- This message was sent by Atlassian JIRA (v7.3.1#73012)

1 0

[JIRA] (LOGBACK-891) Deadlock in RollingFileAppender
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

1 0

[JIRA] (LOGBACK-1421) Logback 1.2.3 threads getting deadlocked at CachingDateFormatter
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

1 0

[JIRA] (LOGBACK-891) Deadlock in RollingFileAppender
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

1 0

[JIRA] (LOGBACK-891) Deadlock in RollingFileAppender
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

1 0

[JIRA] (LOGBACK-891) Deadlock in RollingFileAppender
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

1 0

[JIRA] (LOGBACK-1421) Logback 1.2.3 threads getting deadlocked at CachingDateFormatter
by QOS.CH (JIRA) 12 Sep '18

12 Sep '18

DEBRAJ MANNA created LOGBACK-1421: ------------------------------------- Summary: Logback 1.2.3 threads getting deadlocked at CachingDateFormatter Key: LOGBACK-1421 URL: https://jira.qos.ch/browse/LOGBACK-1421 Project: logback Issue Type: Bug Components: logback-core Affects Versions: 1.2.3 Environment: I am observing logback 1.2.3 getting stuck with stacktrace like below {code:java} Schedule_CISCON9K_10.22.8.7_config_OpMgr-0" #874742 prio=5 os_prio=0 tid=0x00007fff54789000 nid=0x31f0 waiting for monitor entry [0x00007fff0e323000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.util.CachingDateFormatter.format(CachingDateFormatter.java:45) - waiting to lock <0x00000006488ca358> (a ch.qos.logback.core.util.CachingDateFormatter) at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:61) at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:23) at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:36) at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:115) at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:141) at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:39) at ch.qos.logback.core.encoder.LayoutWrappingEncoder.encode(LayoutWrappingEncoder.java:115) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:230) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.info(Logger.java:579) at com.van.dataproviders.core.impl.cas.n5k.tasks.N5KSynchronousTask.doRun(N5KSynchronousTask.java:63) at com.van.dataproviders.core.common.impl.dataprovider.tasks.AbstractTask.run(AbstractTask.java:104) at com.van.dataproviders.tasker.Tasker$ScheduledTaskWrapper.run(Tasker.java:359) at com.google.common.util.concurrent.MoreExecutors$ScheduledListeningDecorator$NeverSuccessfulListenableFutureTask.run(MoreExecutors.java:678) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) {code} Most thread trying to write to log are blocked on a {{synchronize(this)}} lock in {{CachingDateFormatter}} of logback. But another thread, which actually has the above lock (thus blocking the other threads) is itself blocked as follows: {code:java} "Schedule_CISCON9K_10.22.8.149_metric_OpMgr-0" #871618 prio=5 os_prio=0 tid=0x00007fff54740800 nid=0x7e56 waiting for monitor entry [0x00007fff15f1a000] java.lang.Thread.State: BLOCKED (on object monitor) at java.util.ResourceBundle.getBundleImpl(ResourceBundle.java:1333) at java.util.ResourceBundle.getBundle(ResourceBundle.java:899) at sun.util.resources.LocaleData$1.run(LocaleData.java:167) at sun.util.resources.LocaleData$1.run(LocaleData.java:163) at java.security.AccessController.doPrivileged(Native Method) at sun.util.resources.LocaleData.getBundle(LocaleData.java:163) at sun.util.resources.LocaleData.getDateFormatData(LocaleData.java:127) at java.text.DateFormatSymbols.initializeData(DateFormatSymbols.java:710) at java.text.DateFormatSymbols.<init>(DateFormatSymbols.java:145) at sun.util.locale.provider.DateFormatSymbolsProviderImpl.getInstance(DateFormatSymbolsProviderImpl.java:85) at java.text.DateFormatSymbols.getProviderInstance(DateFormatSymbols.java:364) at java.text.DateFormatSymbols.getInstance(DateFormatSymbols.java:340) at java.util.Calendar.getDisplayName(Calendar.java:2110) at java.text.SimpleDateFormat.subFormat(SimpleDateFormat.java:1125) at java.text.SimpleDateFormat.format(SimpleDateFormat.java:966) at java.text.SimpleDateFormat.format(SimpleDateFormat.java:936) at java.text.DateFormat.format(DateFormat.java:345) at ch.qos.logback.core.util.CachingDateFormatter.format(CachingDateFormatter.java:48) - locked <0x00000006488ca358> (a ch.qos.logback.core.util.CachingDateFormatter) at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:61) {code} {{logback.xml}} {code:java} <configuration scan="true" debug="true"> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <Target>System.out</Target> <encoder> <pattern>%p [%d{yyyy-MM-dd HH:mm:ss,SSS}] %c{3}:[%C{1}:%M:%L] - [%t] - %replace(%.-20480m){'[^A-Za-z0-9=<>:@/.,"\'\-\[\]\{\}\n\s!|]','_'}%n</pattern> </encoder> </appender> <root level="INFO"> <appender-ref ref="CONSOLE"/> </root> </configuration> {code} Java 8 Reporter: DEBRAJ MANNA Assignee: Logback dev list -- This message was sent by Atlassian JIRA (v7.3.1#73012)

1 0

[JIRA] (LOGBACK-891) Deadlock in RollingFileAppender
by QOS.CH (JIRA) 11 Sep '18

11 Sep '18

1 0

[JIRA] (LOGBACK-891) Deadlock in RollingFileAppender
by QOS.CH (JIRA) 11 Sep '18

11 Sep '18

1 0

[JIRA] (LOGBACK-1396) JVM fatal error with libzip.so
by QOS.CH (JIRA) 11 Sep '18

11 Sep '18

1 0