[logback-user] Logback 1.2.3 threads getting deadlocked

Thu Sep 13 06:03:55 CEST 2018

Is there any workaround for this so that I can avoid this contention flow?

On Thu 13 Sep, 2018, 12:31 AM Debraj Manna, <subharaj.manna at gmail.com>
wrote:

> Filed https://jira.qos.ch/browse/LOGBACK-1421
>
> On Wed, Sep 12, 2018 at 10:44 PM ceki <ceki at qos.ch> wrote:
>
>> Hi Debraj,
>>
>> Can you please create a JiRA issue for the deadlock you describe?
>> --
>> Ceki Gülcü
>>
>>
>>
>> Sent from my Samsung Galaxy smartphone.
>> -------- Original message --------
>> From: Debraj Manna <subharaj.manna at gmail.com>
>> Date: 9/12/2018 18:21 (GMT+01:00)
>> To: logback-user at qos.ch
>> Subject: [logback-user] Logback 1.2.3 threads getting deadlocked
>>
>> I am observing logback 1.2.3 getting stuck with stacktrace like below .
>> In case the email gets truncated I am also placing the above logs in the
>> below gist
>> <https://gist.github.com/debraj-manna/d3b8de557ae3514368ab66b947d0ed14>
>>  .
>>
>> https://gist.github.com/debraj-manna/d3b8de557ae3514368ab66b947d0ed14
>>
>> I am using java 8
>>
>> 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)
>>
>> 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:
>>
>> "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)
>>
>> Loback.xml
>> <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>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20180913/2454b07d/attachment.html>