Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1421

Logback 1.2.3 threads getting deadlocked at CachingDateFormatter

    Details

    • Type: Bug
    • Status: In Progress
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.2.3
    • Fix Version/s: 1.3.0-alpha5
    • Component/s: logback-core
    • Labels:
      None

      Description

      As suggested in the email list filing the JIRA.

      I am observing logback 1.2.3 getting stuck with stacktrace like below

       

      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)
      

      logback.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=&lt;&gt;:@/.,"\'\-\[\]\{\}\(\)\n\s!|]','_'}%n</pattern>
              </encoder>
          </appender>
      
          <root level="INFO">
              <appender-ref ref="CONSOLE"/>
          </root>
      </configuration>
      

      I am using Java 8 on Ubuntu 14.04
       

        Attachments

          Activity

            People

            • Assignee:
              ceki Ceki Gülcü
              Reporter:
              tuk DEBRAJ MANNA
            • Votes:
              2 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated: