Details
-
Bug
-
Resolution: Fixed
-
Major
-
1.4.8
-
None
-
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)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)
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)