From a5ad1de69bdb00b725fd447cff6607c4862bf43a Mon Sep 17 00:00:00 2001 From: Jared Stehler Date: Tue, 22 Oct 2024 11:13:04 -0400 Subject: [PATCH] Revert "Revert "Don't call file.length() for every append if we can avoid it"" --- .../ch/qos/logback/core/FileAppender.java | 15 ++++++++ .../recovery/ByteCountingOutputStream.java | 35 +++++++++++++++++++ .../recovery/ResilientFileOutputStream.java | 22 ++++++++++-- ...imeBasedFileNamingAndTriggeringPolicy.java | 4 +++ .../core/rolling/RollingFileAppender.java | 2 +- .../core/rolling/SizeAndTimeBasedFNATP.java | 11 ++++-- .../rolling/SizeBasedTriggeringPolicy.java | 9 +++-- .../core/rolling/TimeBasedRollingPolicy.java | 5 +++ .../core/rolling/TriggeringPolicy.java | 2 ++ .../recovery/ResilientOutputStreamTest.java | 14 ++++++++ 10 files changed, 111 insertions(+), 8 deletions(-) create mode 100644 logback-core/src/main/java/ch/qos/logback/core/recovery/ByteCountingOutputStream.java diff --git a/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java b/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java index 2c92a3538b..7721747829 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java +++ b/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) { diff --git a/logback-core/src/main/java/ch/qos/logback/core/recovery/ByteCountingOutputStream.java b/logback-core/src/main/java/ch/qos/logback/core/recovery/ByteCountingOutputStream.java new file mode 100644 index 0000000000..3ecf0763c4 --- /dev/null +++ b/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(); + } +} diff --git a/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java b/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java index 199f125fd0..de6bb69342 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java +++ b/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,6 +43,10 @@ public File getFile() { return file; } + public long getCount() { + return originalFileLength + (countingOutputStream == null ? 0 : countingOutputStream.getByteCount()); + } + @Override String getDescription() { return "file [" + file + "]"; @@ -46,9 +54,11 @@ String getDescription() { @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 @@ -56,4 +66,12 @@ 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; + } + } } diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java index 9e5289bc40..d67be1c324 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java +++ b/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(); diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java index e041a5f3f0..fd07b68f45 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java +++ b/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 { diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java index 68694f5f6d..9c086d8422 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java +++ b/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); diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java index 6ef9bbcf7b..4d0937814c 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java +++ b/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() { diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java index e75b4bf83b..4984eb995b 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java +++ b/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. * diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java index 29abbc8212..b99fe6b3ef 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java @@ -35,4 +35,6 @@ public interface TriggeringPolicy 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); } diff --git a/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java b/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java index 76a6a2a415..ebc2c58bf6 100644 --- a/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java +++ b/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()); } }