Merge pull request #8 from HubSpot/js_file_length

Don't call file.length() for every append if we can avoid it

Author: jaredstehler

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

@@ -18,6 +18,7 @@
 
 import java.io.File;
 import java.io.IOException;
+import java.io.OutputStream;
 import java.nio.channels.FileChannel;
 import java.nio.channels.FileLock;
 import java.util.Map;
@@ -239,6 +240,20 @@ public void setBufferSize(FileSize bufferSize) {
         this.bufferSize = bufferSize;
     }
 
+    /**
+     * Returns the current position in the current file, as counted by
+     * {@link ch.qos.logback.core.recovery.ByteCountingOutputStream}, or zero if no file has been opened.
+     */
+    protected long getCurrentFilePosition() {
+        OutputStream outputStream = getOutputStream();
+        if (outputStream == null) {
+            return 0;
+        } else {
+            // we already cast to a ResilientFileOutputStream in #safeWrite()
+            return ((ResilientFileOutputStream) outputStream).getCount();
+        }
+    }
+
     @Override
     protected void writeOut(E event) throws IOException {
         if (prudent) {

logback-core/src/main/java/ch/qos/logback/core/recovery/ByteCountingOutputStream.java

@@ -0,0 +1,35 @@
+package ch.qos.logback.core.recovery;
+
+import java.io.FilterOutputStream;
+import java.io.IOException;
+import java.io.OutputStream;
+
+public class ByteCountingOutputStream extends FilterOutputStream {
+
+    private long count;
+
+    public ByteCountingOutputStream(OutputStream out) {
+        super(out);
+    }
+
+    public long getByteCount() {
+        return count;
+    }
+
+    @Override
+    public void write(byte[] b, int off, int len) throws IOException {
+        out.write(b, off, len);
+        count += len;
+    }
+
+    @Override
+    public void write(int b) throws IOException {
+        out.write(b);
+        count++;
+    }
+
+    @Override
+    public void close() throws IOException {
+        out.close();
+    }
+}

logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java

@@ -20,11 +20,15 @@ public class ResilientFileOutputStream extends ResilientOutputStreamBase {
 
     private File file;
     private FileOutputStream fos;
+    private ByteCountingOutputStream countingOutputStream;
+    private long originalFileLength;
 
     public ResilientFileOutputStream(File file, boolean append, long bufferSize) throws FileNotFoundException {
         this.file = file;
+        this.originalFileLength = append ? getFileLength(file) : 0;
         fos = new FileOutputStream(file, append);
-        this.os = new BufferedOutputStream(fos, (int) bufferSize);
+        countingOutputStream = new ByteCountingOutputStream(new BufferedOutputStream(fos, (int) bufferSize));
+        this.os = countingOutputStream;
         this.presumedClean = true;
     }
 
@@ -39,21 +43,35 @@ public File getFile() {
         return file;
     }
 
+    public long getCount() {
+        return originalFileLength + (countingOutputStream == null ? 0 : countingOutputStream.getByteCount());
+    }
+
     @Override
     String getDescription() {
         return "file [" + file + "]";
     }
 
     @Override
     OutputStream openNewOutputStream() throws IOException {
+        originalFileLength = getFileLength(file);
         // see LOGBACK-765
         fos = new FileOutputStream(file, true);
-        return new BufferedOutputStream(fos);
+        countingOutputStream = new ByteCountingOutputStream(new BufferedOutputStream(fos));
+        return countingOutputStream;
     }
 
     @Override
     public String toString() {
         return "c.q.l.c.recovery.ResilientFileOutputStream@" + System.identityHashCode(this);
     }
 
+    private static long getFileLength(File file) {
+        try {
+            return file.length();
+        } catch (Exception ignored) {
+            // file doesn't exist or we don't have permissions
+            return 0L;
+        }
+    }
 }

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

@@ -43,6 +43,10 @@ public void start() {
         started = true;
     }
 
+    public boolean isTriggeringEvent(final File activeFile, final E event, long currentFilePosition) {
+        return isTriggeringEvent(activeFile, event);
+    }
+
     public boolean isTriggeringEvent(File activeFile, final E event) {
         long currentTime = getCurrentTime();
         long localNextCheck = atomicNextCheck.get();

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

@@ -242,7 +242,7 @@ protected void subAppend(E event) {
 
         triggeringPolicyLock.lock();
         try {
-            if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
+            if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event, getCurrentFilePosition())) {
                 rollover();
             }
         } finally {

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

@@ -141,7 +141,11 @@ void computeCurrentPeriodsHighestCounterValue(final String stemRegex) {
 
     @Override
     public boolean isTriggeringEvent(File activeFile, final E event) {
+        return isTriggeringEvent(activeFile, event, -1);
+    }
 
+    @Override
+    public boolean isTriggeringEvent(final File activeFile, final E event, long currentFilePosition) {
         long currentTime = getCurrentTime();
         long localNextCheck = atomicNextCheck.get();
 
@@ -158,10 +162,10 @@ public boolean isTriggeringEvent(File activeFile, final E event) {
             return true;
         }
 
-        return checkSizeBasedTrigger(activeFile, currentTime);
+        return checkSizeBasedTrigger(activeFile, currentTime, currentFilePosition);
     }
 
-    private boolean checkSizeBasedTrigger(File activeFile, long currentTime) {
+    private boolean checkSizeBasedTrigger(File activeFile, long currentTime, long currentFilePosition) {
         // next check for roll-over based on size
         if (invocationGate.isTooSoon(currentTime)) {
             return false;
@@ -175,7 +179,8 @@ private boolean checkSizeBasedTrigger(File activeFile, long currentTime) {
             addWarn("maxFileSize = null");
             return false;
         }
-        if (activeFile.length() >= maxFileSize.getSize()) {
+        long activeFileLength = currentFilePosition >= 0 ? currentFilePosition : activeFile.length();
+        if (activeFileLength >= maxFileSize.getSize()) {
 
             elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInCurrentPeriod,
                     currentPeriodsCounter);

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

@@ -54,12 +54,17 @@ public void start() {
     }
 
 
-    public boolean isTriggeringEvent(final File activeFile, final E event) {
+    @Override
+    public boolean isTriggeringEvent(File activeFile, E event, long currentFilePosition) {
         long now = System.currentTimeMillis();
         if (invocationGate.isTooSoon(now))
             return false;
+        long activeFileLength = currentFilePosition >= 0 ? currentFilePosition : activeFile.length();
+        return (activeFileLength >= maxFileSize.getSize());
+    }
 
-        return (activeFile.length() >= maxFileSize.getSize());
+    public boolean isTriggeringEvent(final File activeFile, final E event) {
+        return isTriggeringEvent(activeFile, event, -1);
     }
 
     public FileSize getMaxFileSize() {

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

@@ -227,6 +227,11 @@ public String getActiveFileName() {
         }
     }
 
+    @Override
+    public boolean isTriggeringEvent(File activeFile, E event, long currentFilePosition) {
+        return timeBasedFileNamingAndTriggeringPolicy.isTriggeringEvent(activeFile, event, currentFilePosition);
+    }
+
     /**
      * Delegates to the underlying timeBasedFileNamingAndTriggeringPolicy.
      *

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

@@ -35,4 +35,6 @@ public interface TriggeringPolicy<E> extends LifeCycle {
      * @return true if a roll-over should occur.
      */
     boolean isTriggeringEvent(final File activeFile, final E event);
+
+    boolean isTriggeringEvent(final File activeFile, final E event, long currentFilePosition);
 }

logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java

@@ -13,6 +13,7 @@
  */
 package ch.qos.logback.core.recovery;
 
+import static org.junit.jupiter.api.Assertions.assertEquals;
 import static org.mockito.Mockito.spy;
 import static org.mockito.Mockito.verify;
 
@@ -51,15 +52,28 @@ public void verifyRecuperationAfterFailure() throws Exception {
 
         spy.write("a".getBytes());
         spy.flush();
+        assertEquals(1, spy.getCount());
 
         spy.getChannel().close();
         spy.write("b".getBytes());
         spy.flush();
+        // we have 2 in our countingoutput stream
+        // but the 'b' write failed due to the channel closing
+        assertEquals(2, spy.getCount());
         Thread.sleep(RecoveryCoordinator.BACKOFF_COEFFICIENT_MIN + 10);
         spy.write("c".getBytes());
         spy.flush();
+
+        // since we recovered the output stream, we recomputed
+        // our count from the length of the file. both b and c were lost.
+        assertEquals(1, spy.getCount());
         verify(spy).openNewOutputStream();
 
+        Thread.sleep(RecoveryCoordinator.BACKOFF_COEFFICIENT_MIN + 10);
+        spy.write("d".getBytes());
+        spy.flush();
+        // the 'd' write succeeds, so we have 2 bytes written
+        assertEquals(2, spy.getCount());
     }
 
 }