fix prudent mode OverlappingFileLockException, LOGBACK-1754

Signed-off-by: Ceki Gulcu <ceki@qos.ch>

logback-classic/src/test/input/issue/logback-1754.xml

@@ -0,0 +1,32 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!--
+  ~ Logback: the reliable, generic, fast and flexible logging framework.
+  ~ Copyright (C) 1999-2023, QOS.ch. All rights reserved.
+  ~
+  ~ This program and the accompanying materials are dual-licensed under
+  ~ either the terms of the Eclipse Public License v1.0 as published by
+  ~ the Eclipse Foundation
+  ~
+  ~   or (per the licensee's choosing)
+  ~
+  ~ under the terms of the GNU Lesser General Public License version 2.1
+  ~ as published by the Free Software Foundation.
+  -->
+
+<configuration debug="true">
+    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
+
+    <appender name="GENERAL" class="ch.qos.logback.core.rolling.RollingFileAppender">
+        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+            <fileNamePattern>${logback_1754_targetDirectory}/test-%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>

logback-classic/src/test/java/ch/qos/logback/classic/issue/logback_1754/SafeModeTest.java

@@ -0,0 +1,93 @@
+/*
+ * Logback: the reliable, generic, fast and flexible logging framework.
+ * Copyright (C) 1999-2023, QOS.ch. All rights reserved.
+ *
+ * This program and the accompanying materials are dual-licensed under
+ * either the terms of the Eclipse Public License v1.0 as published by
+ * the Eclipse Foundation
+ *
+ *   or (per the licensee's choosing)
+ *
+ * under the terms of the GNU Lesser General Public License version 2.1
+ * as published by the Free Software Foundation.
+ */
+
+package ch.qos.logback.classic.issue.logback_1754;
+
+import java.util.ArrayList;
+import java.util.List;
+import java.util.concurrent.CountDownLatch;
+
+import ch.qos.logback.classic.ClassicConstants;
+import ch.qos.logback.classic.ClassicTestConstants;
+import ch.qos.logback.core.testUtil.RandomUtil;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class SafeModeTest {
+
+    private static final int THREADS = 3;
+
+    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);
+        }
+        int i = 0;
+        for (Thread thread : threads) {
+            try {
+                thread.join();
+                System.out.println("joined thread "+thread.getName());
+            } catch (InterruptedException e) {
+                e.printStackTrace();
+                //Thread.currentThread().interrupt();
+                //throw new RuntimeException(e);
+            }
+        }
+    }
+
+    public static void main(String... args) {
+        int diff = RandomUtil.getPositiveInt();
+        //System.setProperty("logback.statusListenerClass", "sysout");
+        System.setProperty(ClassicConstants.CONFIG_FILE_PROPERTY, ClassicTestConstants.INPUT_PREFIX+"issue/logback-1754.xml");
+        System.setProperty("logback_1754_targetDirectory", ClassicTestConstants.OUTPUT_DIR_PREFIX+"safeWrite_"+diff);
+
+
+        new SafeModeTest().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();
+            for(int i = 0; i < 100; i++) {
+                if(i % 10 == 0) {
+                    delay(1);
+                }
+                LOG.info(message + " i=" + i);
+            }
+        }
+
+        static void delay(long millis) {
+            try {
+                Thread.sleep(millis);
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
+        }
+    }
+}

logback-core/src/main/java/ch/qos/logback/core/FileAppender.java

@@ -195,7 +195,7 @@ protected void addErrorForCollision(String optionName, String optionValue, Strin
      * @param file_name The path to the log file.
      */
     public void openFile(String file_name) throws IOException {
-        lock.lock();
+        streamWriteLock.lock();
         try {
             File file = new File(file_name);
             boolean result = FileUtil.createMissingParentDirectories(file);
@@ -207,7 +207,7 @@ public void openFile(String file_name) throws IOException {
             resilientFos.setContext(context);
             setOutputStream(resilientFos);
         } finally {
-            lock.unlock();
+            streamWriteLock.unlock();
         }
     }
 
@@ -239,7 +239,29 @@ public void setBufferSize(FileSize bufferSize) {
         this.bufferSize = bufferSize;
     }
 
-    private void safeWrite(E event) throws IOException {
+    @Override
+    protected void writeOut(E event) throws IOException {
+        if (prudent) {
+            safeWriteOut(event);
+        } else {
+            super.writeOut(event);
+        }
+    }
+
+    private void safeWriteOut(E event) {
+        byte[] byteArray = this.encoder.encode(event);
+        if (byteArray == null || byteArray.length == 0)
+            return;
+
+        streamWriteLock.lock();
+        try {
+           safeWriteBytes(byteArray);
+        } finally {
+            streamWriteLock.unlock();
+        }
+    }
+
+    private void safeWriteBytes(byte[] byteArray) {
         ResilientFileOutputStream resilientFOS = (ResilientFileOutputStream) getOutputStream();
         FileChannel fileChannel = resilientFOS.getChannel();
         if (fileChannel == null) {
@@ -257,14 +279,12 @@ private void safeWrite(E event) throws IOException {
             if (size != position) {
                 fileChannel.position(size);
             }
-            super.writeOut(event);
+            writeByteArrayToOutputStreamWithPossibleFlush(byteArray);
         } catch (IOException e) {
             // Mainly to catch FileLockInterruptionExceptions (see LOGBACK-875)
             resilientFOS.postIOFailure(e);
         } finally {
-            if (fileLock != null && fileLock.isValid()) {
-                fileLock.release();
-            }
+            releaseFileLock(fileLock);
 
             // Re-interrupt if we started in an interrupted state (see LOGBACK-875)
             if (interrupted) {
@@ -273,12 +293,13 @@ private void safeWrite(E event) throws IOException {
         }
     }
 
-    @Override
-    protected void writeOut(E event) throws IOException {
-        if (prudent) {
-            safeWrite(event);
-        } else {
-            super.writeOut(event);
+    private void releaseFileLock(FileLock fileLock) {
+        if (fileLock != null && fileLock.isValid()) {
+            try {
+                fileLock.release();
+            } catch (IOException e) {
+                addError("failed to release lock", e);
+            }
         }
     }
 }

logback-core/src/main/java/ch/qos/logback/core/OutputStreamAppender.java

@@ -44,7 +44,7 @@ public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
     /**
      * All synchronization in this class is done via the lock object.
      */
-    protected final ReentrantLock lock = new ReentrantLock(false);
+    protected final ReentrantLock streamWriteLock = new ReentrantLock(false);
 
     /**
      * This is the {@link OutputStream outputStream} where output will be written.
@@ -112,12 +112,12 @@ public void stop() {
         if(!isStarted())
             return;
 
-        lock.lock();
+        streamWriteLock.lock();
         try {
             closeOutputStream();
             super.stop();
         } finally {
-            lock.unlock();
+            streamWriteLock.unlock();
         }
     }
 
@@ -159,7 +159,7 @@ void encoderClose() {
      * @param outputStream An already opened OutputStream.
      */
     public void setOutputStream(OutputStream outputStream) {
-        lock.lock();
+        streamWriteLock.lock();
         try {
             // close any previously opened output stream
             closeOutputStream();
@@ -171,7 +171,7 @@ public void setOutputStream(OutputStream outputStream) {
 
             encoderInit();
         } finally {
-            lock.unlock();
+            streamWriteLock.unlock();
         }
     }
 
@@ -197,14 +197,23 @@ private void writeBytes(byte[] byteArray) throws IOException {
         if (byteArray == null || byteArray.length == 0)
             return;
 
-        lock.lock();
+        streamWriteLock.lock();
         try {
-            this.outputStream.write(byteArray);
-            if (immediateFlush) {
-                this.outputStream.flush();
-            }
+            writeByteArrayToOutputStreamWithPossibleFlush(byteArray);
         } finally {
-            lock.unlock();
+            streamWriteLock.unlock();
+        }
+    }
+
+    /**
+     * A simple method to write to an outputStream and flush the stream if immediateFlush is set to true.
+     *
+     * @since 1.3.9/1.4.9
+     */
+    protected final void writeByteArrayToOutputStreamWithPossibleFlush(byte[] byteArray) throws IOException {
+        this.outputStream.write(byteArray);
+        if (immediateFlush) {
+            this.outputStream.flush();
         }
     }
 

logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java

@@ -187,7 +187,7 @@ public String getFile() {
      * Implemented by delegating most of the rollover work to a rolling policy.
      */
     public void rollover() {
-        lock.lock();
+        streamWriteLock.lock();
         try {
             // Note: This method needs to be synchronized because it needs exclusive
             // access while it closes and then re-opens the target file.
@@ -198,7 +198,7 @@ public void rollover() {
             attemptRollover();
             attemptOpenFile();
         } finally {
-            lock.unlock();
+            streamWriteLock.unlock();
         }
     }
 

logback-core/src/test/java/ch/qos/logback/core/PrudentFileAppenderInterruptTest.java

@@ -54,7 +54,7 @@ public void setUp() throws InterruptedException {
 
     @Test
     public void smoke() throws InterruptedException, IOException {
-        Runner runner = new Runner(fa);
+        InterruptAndLogRunner runner = new InterruptAndLogRunner(fa);
         Thread t = new Thread(runner);
         t.start();
 
@@ -72,15 +72,15 @@ public void smoke() throws InterruptedException, IOException {
         fr.close();
         br.close();
 
-        Assertions.assertEquals(2, totalLines, "Incorrect number of logged lines");
+        Assertions.assertEquals(2, totalLines, "Incorrect number of logged lines "+outputDirStr);
     }
 
-    class Runner extends RunnableWithCounterAndDone {
+    class InterruptAndLogRunner extends RunnableWithCounterAndDone {
         FileAppender<Object> fa;
         CountDownLatch latch = new CountDownLatch(1); // Just to make sure this is executed before we log in the test
                                                       // method
 
-        Runner(FileAppender<Object> fa) {
+        InterruptAndLogRunner(FileAppender<Object> fa) {
             this.fa = fa;
         }