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

OverlappingFileLockException when using prudent mode

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Major Major
    • 1.4.9, 1.3.9
    • 1.4.8
    • logback-core
    • None

    Description

      Hi,

      after moving from logback 1.2.12 to 1.4.8 I ran into OverlappingFileLockExceptions when using prudent mode.

      ERROR in ch.qos.logback.core.rolling.RollingFileAppender[GENERAL] - Appender [GENERAL] failed to append. java.nio.channels.OverlappingFileLockException
          at java.nio.channels.OverlappingFileLockException
          at     at java.base/sun.nio.ch.FileLockTable.checkList(FileLockTable.java:229)
          at     at java.base/sun.nio.ch.FileLockTable.add(FileLockTable.java:123)
          at     at java.base/sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:1276)
          at     at java.base/java.nio.channels.FileChannel.lock(FileChannel.java:1089)
          at     at ch.qos.logback.core.FileAppender.safeWrite(FileAppender.java:254)
          at     at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:279)
          at     at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:228)
          at     at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:253)
          at     at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
          at     at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
          at     at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
          at     at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
          at     at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
          at     at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
          at     at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
          at     at ch.qos.logback.classic.Logger.info(Logger.java:584)
          at     at LogbackTest$LoggerThread.run(LogbackTest.java:47)
      

      This is my logback.xml

      <?xml version="1.0" encoding="UTF-8"?>
      <configuration debug="true">
          <appender name="GENERAL" class="ch.qos.logback.core.rolling.RollingFileAppender">
              <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                  <fileNamePattern>applog/my-log-%d{yyyy-MM-dd}.log</fileNamePattern>
                  <maxHistory>120</maxHistory>
              </rollingPolicy>
              <encoder>
                  <pattern>%date{HH:mm:ss.SSS} [%level] %logger{0} [%thread] [%class{3}:%line] : %msg%n</pattern>
              </encoder>
              <prudent>true</prudent>
          </appender>
          <root level="debug">
              <appender-ref ref="GENERAL" />
          </root>
      </configuration>
      

      and this is my test class:

      import java.util.ArrayList;
      import java.util.List;
      import java.util.concurrent.CountDownLatch;
      
      import org.slf4j.Logger;
      import org.slf4j.LoggerFactory;
      
      public class LogbackTest {
          private static final int THREADS = 20;
      
          private void runTest() {
              CountDownLatch latch = new CountDownLatch(THREADS);
              List<Thread> threads = new ArrayList<>(THREADS);
              for (int i = 0; i < THREADS; i++) {
                  LoggerThread thread = new LoggerThread(latch, "message from thread " + i);
                  thread.start();
                  threads.add(thread);
              }
              for (Thread thread : threads) {
                  try {
                      thread.join();
                  } catch (InterruptedException e) {
                      Thread.currentThread().interrupt();
                      throw new RuntimeException(e);
                  }
              }
          }
      
          public static void main(String... args) {
              new LogbackTest().runTest();
          }
      
          private static final class LoggerThread extends Thread {
              private static final Logger LOG = LoggerFactory.getLogger(LoggerThread.class);
              private final CountDownLatch latch;
              private final String message;
      
              LoggerThread(CountDownLatch latch, String message) {
                  setDaemon(false);
                  this.latch = latch;
                  this.message = message;
              }
      
              @Override
              public void run() {
                  latch.countDown();
                  LOG.info(message);
              }
          }
      }
      

      I never had this problems with logback 1.2 (the test class runs without problems when using 1.2). I didn't change the logback.xml and the jvm is the same. Here is a stack trace when the RollingFileAppender is called with 1.2.12:

            at ch.qos.logback.core.recovery.ResilientOutputStreamBase.write(ResilientOutputStreamBase.java:52)
            at java.io.OutputStream.write(OutputStream.java:127)
            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.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
            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 LogbackTest$LoggerThread.run(LogbackTest.java:47)
      

      Attachments

        Activity

          People

            ceki Ceki Gülcü
            christian.habermehl Christian Habermehl
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: