[logback-dev] [JIRA] Updates for LOGBACK-1754: OverlappingFileLockException when using prudent mode

logback developers list logback-dev at qos.ch
Tue Jul 4 11:31:00 CEST 2023


logback / LOGBACK-1754 [Open]
OverlappingFileLockException when using prudent mode

==============================

Here's what changed in this issue in the last few minutes.

This issue has been created
This issue is now assigned to you.


View or comment on issue using this link
https://jira.qos.ch/browse/LOGBACK-1754

==============================
 Issue created
------------------------------

Christian Habermehl created this issue on 04/Jul/23 11:19

Summary:              OverlappingFileLockException when using prudent mode
Issue Type:           Bug
Affects Versions:     1.4.8
Assignee:             Logback dev list
Components:           logback-core
Created:              04/Jul/23 11:19
Environment:
  Windows 10
  openjdk version "17.0.5" 2022-10-18
  OpenJDK Runtime Environment JBR-17.0.5+1-653.14-jcef (build 17.0.5+1-b653.14)
  OpenJDK 64-Bit Server VM JBR-17.0.5+1-653.14-jcef (build 17.0.5+1-b653.14, mixed mode)
  
  Debian
  openjdk version "17.0.2" 2022-01-18
  OpenJDK Runtime Environment (build 17.0.2+8-86)
  OpenJDK 64-Bit Server VM (build 17.0.2+8-86, mixed mode, sharing)
Priority:             Major
Reporter:             Christian Habermehl
Description:
  Hi,
  
  after moving from logback 1.2.12 to 1.4.8 I ran into OverlappingFileLockExceptions when using prudent mode.
  {code:java}
  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)
  {code}
  This is my logback.xml
  {code: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>
  {code}
  and this is my test class:
  {code:java}
  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);
          }
      }
  }
  {code}
  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:
  {code:java}
        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)
  {code}


==============================
 This message was sent by Atlassian Jira (v9.6.0#960000-sha1:a3ee8af)



More information about the logback-dev mailing list