This is an automated email from the ASF dual-hosted git repository. rgoers pushed a commit to branch release-2.x in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/release-2.x by this push: new 42fe68e LOG4J2-2542 - CronTriggeringPolicy was not rolling properly, especially when used with the SizeBasedTriggeringPolicy 42fe68e is described below commit 42fe68e4394c6fe335f15f9b7320aed83cc0142d Author: Ralph Goers <rgo...@apache.org> AuthorDate: Fri Feb 1 23:44:23 2019 -0700 LOG4J2-2542 - CronTriggeringPolicy was not rolling properly, especially when used with the SizeBasedTriggeringPolicy --- .../appender/rolling/CronTriggeringPolicy.java | 5 +- .../appender/rolling/DefaultRolloverStrategy.java | 6 +- .../core/appender/rolling/PatternProcessor.java | 4 +- .../core/appender/rolling/RollingFileManager.java | 7 ++ ...st.java => RollingAppenderCronAndSizeTest.java} | 79 +++++++++++++++------- .../rolling/RollingAppenderTimeAndSizeTest.java | 45 +++++++++--- ...olling3.xml => log4j-rolling-cron-and-size.xml} | 25 ++++--- log4j-core/src/test/resources/log4j-rolling3.xml | 8 +-- src/site/xdoc/manual/appenders.xml | 10 ++- 9 files changed, 131 insertions(+), 58 deletions(-) diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java index 060e7fa..14997e1 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java @@ -145,10 +145,7 @@ public final class CronTriggeringPolicy extends AbstractTriggeringPolicy { } private void rollover() { - manager.getPatternProcessor().setPrevFileTime(lastRollDate.getTime()); - final Date thisRoll = cronExpression.getPrevFireTime(new Date()); - manager.getPatternProcessor().setCurrentFileTime(thisRoll.getTime()); - manager.rollover(); + manager.rollover(cronExpression.getPrevFireTime(new Date()), lastRollDate); if (future != null) { lastRollDate = future.getFireTime(); } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DefaultRolloverStrategy.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DefaultRolloverStrategy.java index 335018e..6dff555 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DefaultRolloverStrategy.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DefaultRolloverStrategy.java @@ -517,9 +517,11 @@ public class DefaultRolloverStrategy extends AbstractRolloverStrategy { @Override public RolloverDescription rollover(final RollingFileManager manager) throws SecurityException { int fileIndex; + final StringBuilder buf = new StringBuilder(255); if (minIndex == Integer.MIN_VALUE) { final SortedMap<Integer, Path> eligibleFiles = getEligibleFiles(manager); fileIndex = eligibleFiles.size() > 0 ? eligibleFiles.lastKey() + 1 : 1; + manager.getPatternProcessor().formatFileName(strSubstitutor, buf, fileIndex); } else { if (maxIndex < 0) { return null; @@ -529,13 +531,13 @@ public class DefaultRolloverStrategy extends AbstractRolloverStrategy { if (fileIndex < 0) { return null; } + manager.getPatternProcessor().formatFileName(strSubstitutor, buf, fileIndex); if (LOGGER.isTraceEnabled()) { final double durationMillis = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNanos); LOGGER.trace("DefaultRolloverStrategy.purge() took {} milliseconds", durationMillis); } } - final StringBuilder buf = new StringBuilder(255); - manager.getPatternProcessor().formatFileName(strSubstitutor, buf, fileIndex); + final String currentFileName = manager.getFileName(); String renameTo = buf.toString(); diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java index f1231fd..6d1fb7e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java @@ -213,7 +213,9 @@ public class PatternProcessor { } public void updateTime() { - prevFileTime = nextFileTime; + if (nextFileTime != 0) { + prevFileTime = nextFileTime; + } } private long debugGetNextTime(final long nextTime) { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java index 954d958..b8f9ef4 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java @@ -27,6 +27,7 @@ import java.nio.file.Path; import java.nio.file.attribute.BasicFileAttributes; import java.nio.file.attribute.FileTime; import java.util.Collection; +import java.util.Date; import java.util.concurrent.ArrayBlockingQueue; import java.util.concurrent.ExecutorService; import java.util.concurrent.Semaphore; @@ -319,6 +320,12 @@ public class RollingFileManager extends FileManager { return status; } + public synchronized void rollover(Date prevFileTime, Date prevRollTime) { + getPatternProcessor().setPrevFileTime(prevFileTime.getTime()); + getPatternProcessor().setCurrentFileTime(prevRollTime.getTime()); + rollover(); + } + public synchronized void rollover() { if (!hasOutputStream()) { return; diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronAndSizeTest.java similarity index 53% copy from log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java copy to log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronAndSizeTest.java index ad0ea64..652389a 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronAndSizeTest.java @@ -16,15 +16,9 @@ */ package org.apache.logging.log4j.core.appender.rolling; -import static org.apache.logging.log4j.hamcrest.Descriptors.that; -import static org.apache.logging.log4j.hamcrest.FileMatchers.hasName; -import static org.hamcrest.Matchers.endsWith; -import static org.hamcrest.Matchers.hasItemInArray; -import static org.junit.Assert.assertNotNull; -import static org.junit.Assert.assertThat; -import static org.junit.Assert.assertTrue; - import java.io.File; +import java.util.Arrays; +import java.util.Random; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.junit.LoggerContextRule; @@ -33,14 +27,24 @@ import org.junit.Rule; import org.junit.Test; import org.junit.rules.RuleChain; +import static org.apache.logging.log4j.hamcrest.Descriptors.that; +import static org.apache.logging.log4j.hamcrest.FileMatchers.hasName; +import static org.hamcrest.Matchers.endsWith; +import static org.hamcrest.Matchers.hasItemInArray; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertThat; +import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; + /** - * + * LOG4J2-1804. */ -public class RollingAppenderTimeAndSizeTest { +public class RollingAppenderCronAndSizeTest { - private static final String CONFIG = "log4j-rolling3.xml"; + private static final String CONFIG = "log4j-rolling-cron-and-size.xml"; - private static final String DIR = "target/rolling3/test"; + private static final String DIR = "target/rolling-cron-size"; public static LoggerContextRule loggerContextRule = LoggerContextRule.createShutdownTimeoutLoggerContextRule(CONFIG); @@ -51,19 +55,44 @@ public class RollingAppenderTimeAndSizeTest { @Before public void setUp() throws Exception { - this.logger = loggerContextRule.getLogger(RollingAppenderTimeAndSizeTest.class.getName()); + this.logger = loggerContextRule.getLogger(RollingAppenderCronAndSizeTest.class.getName()); } - @Test - public void testAppender() throws Exception { - for (int i=0; i < 100; ++i) { - logger.debug("This is test message number " + i); - } - Thread.sleep(50); - final File dir = new File(DIR); - assertTrue("Directory not created", dir.exists() && dir.listFiles().length > 0); - final File[] files = dir.listFiles(); - assertNotNull(files); - assertThat(files, hasItemInArray(that(hasName(that(endsWith(".gz")))))); - } + @Test + public void testAppender() throws Exception { + Random rand = new Random(); + for (int j=0; j < 100; ++j) { + int count = rand.nextInt(100); + for (int i = 0; i < count; ++i) { + logger.debug("This is test message number " + i); + } + Thread.sleep(rand.nextInt(50)); + } + Thread.sleep(50); + final File dir = new File(DIR); + assertTrue("Directory not created", dir.exists() && dir.listFiles().length > 0); + final File[] files = dir.listFiles(); + Arrays.sort(files); + assertNotNull(files); + assertThat(files, hasItemInArray(that(hasName(that(endsWith(".log")))))); + int found = 0; + int fileCounter = 0; + String previous = ""; + for (final File file: files) { + final String actual = file.getName(); + StringBuilder padding = new StringBuilder(); + String length = Long.toString(file.length()); + for (int i = length.length(); i < 10; ++i) { + padding.append(" "); + } + final String[] fileParts = actual.split("_|\\."); + fileCounter = previous.equals(fileParts[1]) ? ++fileCounter : 1; + previous = fileParts[1]; + assertEquals("Incorrect file name. Expected counter value of " + fileCounter + " in " + actual, + Integer.toString(fileCounter), fileParts[2]); + + + } + + } } diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java index ad0ea64..a94300b 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeAndSizeTest.java @@ -20,11 +20,14 @@ import static org.apache.logging.log4j.hamcrest.Descriptors.that; import static org.apache.logging.log4j.hamcrest.FileMatchers.hasName; import static org.hamcrest.Matchers.endsWith; import static org.hamcrest.Matchers.hasItemInArray; +import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertThat; import static org.junit.Assert.assertTrue; import java.io.File; +import java.util.Arrays; +import java.util.Random; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.junit.LoggerContextRule; @@ -56,14 +59,38 @@ public class RollingAppenderTimeAndSizeTest { @Test public void testAppender() throws Exception { - for (int i=0; i < 100; ++i) { - logger.debug("This is test message number " + i); - } - Thread.sleep(50); - final File dir = new File(DIR); - assertTrue("Directory not created", dir.exists() && dir.listFiles().length > 0); - final File[] files = dir.listFiles(); - assertNotNull(files); - assertThat(files, hasItemInArray(that(hasName(that(endsWith(".gz")))))); + Random rand = new Random(); + for (int j=0; j < 100; ++j) { + int count = rand.nextInt(100); + for (int i = 0; i < count; ++i) { + logger.debug("This is test message number " + i); + } + Thread.sleep(rand.nextInt(50)); + } + Thread.sleep(50); + final File dir = new File(DIR); + assertTrue("Directory not created", dir.exists() && dir.listFiles().length > 0); + final File[] files = dir.listFiles(); + Arrays.sort(files); + assertNotNull(files); + assertThat(files, hasItemInArray(that(hasName(that(endsWith(".log")))))); + int found = 0; + int fileCounter = 0; + String previous = ""; + for (final File file: files) { + final String actual = file.getName(); + StringBuilder padding = new StringBuilder(); + String length = Long.toString(file.length()); + for (int i = length.length(); i < 10; ++i) { + padding.append(" "); + } + final String[] fileParts = actual.split("_|\\."); + fileCounter = previous.equals(fileParts[1]) ? ++fileCounter : 1; + previous = fileParts[1]; + assertEquals("Incorrect file name. Expected counter value of " + fileCounter + " in " + actual, + Integer.toString(fileCounter), fileParts[2]); + + + } } } diff --git a/log4j-core/src/test/resources/log4j-rolling3.xml b/log4j-core/src/test/resources/log4j-rolling-cron-and-size.xml similarity index 69% copy from log4j-core/src/test/resources/log4j-rolling3.xml copy to log4j-core/src/test/resources/log4j-rolling-cron-and-size.xml index a4b0e71..8e32a7f 100644 --- a/log4j-core/src/test/resources/log4j-rolling3.xml +++ b/log4j-core/src/test/resources/log4j-rolling-cron-and-size.xml @@ -16,34 +16,37 @@ limitations under the License. --> -<Configuration status="OFF" name="XMLConfigTest"> +<Configuration status="ERROR" name="RollingCronTest" monitorInterval="1"> <Properties> - <Property name="filename">target/rolling3/rollingtest.log</Property> + <Property name="filename">target/rolling1/rollingtest.log</Property> + <Property name="DIR">target/rolling-cron-size</Property> </Properties> - <ThresholdFilter level="debug"/> + <Filters> + <ThresholdFilter level="debug"/> + </Filters> <Appenders> <Console name="STDOUT"> <PatternLayout pattern="%m%n"/> </Console> - <RollingFile name="RollingFile" fileName="${filename}" filePattern="target/rolling3/test/test1-%d{MM-dd-yy-HH-mm}-%i.log.gz"> - <PatternLayout> - <Pattern>%d %p %C{1.} [%t] %m%n</Pattern> - </PatternLayout> + <RollingFile name="RollingFile" fileName="${filename}" filePattern="${DIR}/rollingfile_%d{yyyy-MM-dd-HH-mm-ss}_%i.log"> + <PatternLayout pattern="%d{yyyy-MM-dd-HH-mm-ss} [%level] [%c] %msg%n"/> <Policies> - <TimeBasedTriggeringPolicy /> - <SizeBasedTriggeringPolicy size="500" /> + <CronTriggeringPolicy schedule="* * * * * ?"/> + <SizeBasedTriggeringPolicy size="1000" /> </Policies> </RollingFile> <List name="List"> - <ThresholdFilter level="error"/> + <Filters> + <ThresholdFilter level="error"/> + </Filters> </List> </Appenders> <Loggers> <Logger name="org.apache.logging.log4j.core.appender.rolling" level="debug" additivity="false"> <AppenderRef ref="RollingFile"/> - </Logger>> + </Logger> <Root level="error"> <AppenderRef ref="STDOUT"/> diff --git a/log4j-core/src/test/resources/log4j-rolling3.xml b/log4j-core/src/test/resources/log4j-rolling3.xml index a4b0e71..a2c1310 100644 --- a/log4j-core/src/test/resources/log4j-rolling3.xml +++ b/log4j-core/src/test/resources/log4j-rolling3.xml @@ -16,7 +16,7 @@ limitations under the License. --> -<Configuration status="OFF" name="XMLConfigTest"> +<Configuration status="ERROR" name="XMLConfigTest"> <Properties> <Property name="filename">target/rolling3/rollingtest.log</Property> </Properties> @@ -26,10 +26,8 @@ <Console name="STDOUT"> <PatternLayout pattern="%m%n"/> </Console> - <RollingFile name="RollingFile" fileName="${filename}" filePattern="target/rolling3/test/test1-%d{MM-dd-yy-HH-mm}-%i.log.gz"> - <PatternLayout> - <Pattern>%d %p %C{1.} [%t] %m%n</Pattern> - </PatternLayout> + <RollingFile name="RollingFile" fileName="${filename}" filePattern="target/rolling3/test/rollingfile_%d{yyyy-MM-dd-HH-mm-ss}_%i.log"> + <PatternLayout pattern="%d{yyyy-MM-dd-HH-mm-ss} [%level] [%c] %msg%n"/> <Policies> <TimeBasedTriggeringPolicy /> <SizeBasedTriggeringPolicy size="500" /> diff --git a/src/site/xdoc/manual/appenders.xml b/src/site/xdoc/manual/appenders.xml index d3887af..263a2d3 100644 --- a/src/site/xdoc/manual/appenders.xml +++ b/src/site/xdoc/manual/appenders.xml @@ -3181,7 +3181,12 @@ public class JpaLogEntity extends AbstractLogEventWrapperEntity { <TimeBasedTriggeringPolicy /> </Policies>]]></pre> <h5>Cron Triggering Policy</h5> - <p>The <code>CronTriggeringPolicy</code> triggers rollover based on a cron expression.</p> + <p>The <code>CronTriggeringPolicy</code> triggers rollover based on a cron expression. This policy + is controlled by a timer and is asynchronous to processing log events, so it is possible that log events + from the previous or next time period may appear at the beginning or end of the log file. The + filePattern attribute of the Appender should contain a timestamp otherwise the target file will be + overwritten on each rollover. + </p> <table> <caption align="top">CronTriggeringPolicy Parameters</caption> <tr> @@ -3238,6 +3243,9 @@ public class JpaLogEntity extends AbstractLogEventWrapperEntity { <p> The <code>SizeBasedTriggeringPolicy</code> causes a rollover once the file has reached the specified size. The size can be specified in bytes, with the suffix KB, MB or GB, for example <code>20MB</code>. + The file pattern must contain a <code>%i</code> otherwise the target file will be overwritten on + every rollover as the SizeBased Triggering Policy does not cause the timestamp value + in the file name to change. </p> <h5>TimeBased Triggering Policy</h5> <p>