You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rg...@apache.org on 2019/02/02 06:44:34 UTC
[logging-log4j2] branch release-2.x updated: LOG4J2-2542 -
CronTriggeringPolicy was not rolling properly,
especially when used with the SizeBasedTriggeringPolicy
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 <rg...@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>