You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by ma...@apache.org on 2022/03/23 05:57:27 UTC
[logging-log4j2] branch master updated: Make Clock injectable in TimeBasedTriggeringPolicy
This is an automated email from the ASF dual-hosted git repository.
mattsicker pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/master by this push:
new 85db357 Make Clock injectable in TimeBasedTriggeringPolicy
85db357 is described below
commit 85db3570037b68fec0868dc79fcd4b3828e7dd4f
Author: Matt Sicker <ma...@apache.org>
AuthorDate: Wed Mar 23 00:57:00 2022 -0500
Make Clock injectable in TimeBasedTriggeringPolicy
This allows for refactoring any test that uses this plugin to speed up or slow down the passage of time. This refactors some known flaky tests to stop flaking.
Signed-off-by: Matt Sicker <ma...@apache.org>
---
.../appender/DailyRollingFileAppenderBuilder.java | 29 +++++++------
.../appender/RollingFileAppenderBuilder.java | 31 +++++++-------
.../appender/rolling/RollingAppenderTimeTest.java | 47 +++++++++++++---------
.../RollingDirectSizeTimeNewDirectoryTest.java | 11 ++++-
.../rolling/RollingDirectTimeNewDirectoryTest.java | 11 ++++-
.../rolling/TimeBasedTriggeringPolicy.java | 24 +++++++++--
6 files changed, 97 insertions(+), 56 deletions(-)
diff --git a/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/DailyRollingFileAppenderBuilder.java b/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/DailyRollingFileAppenderBuilder.java
index 04ba338..d098f29 100644
--- a/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/DailyRollingFileAppenderBuilder.java
+++ b/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/DailyRollingFileAppenderBuilder.java
@@ -16,15 +16,6 @@
*/
package org.apache.log4j.builders.appender;
-import static org.apache.log4j.builders.BuilderManager.CATEGORY;
-import static org.apache.log4j.config.Log4j1Configuration.THRESHOLD_PARAM;
-import static org.apache.log4j.xml.XmlConfiguration.FILTER_TAG;
-import static org.apache.log4j.xml.XmlConfiguration.LAYOUT_TAG;
-import static org.apache.log4j.xml.XmlConfiguration.PARAM_TAG;
-import static org.apache.log4j.xml.XmlConfiguration.forEachElement;
-
-import java.util.Properties;
-
import org.apache.log4j.Appender;
import org.apache.log4j.Layout;
import org.apache.log4j.bridge.AppenderWrapper;
@@ -44,10 +35,17 @@ import org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy;
import org.apache.logging.log4j.core.appender.rolling.RolloverStrategy;
import org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy;
import org.apache.logging.log4j.core.appender.rolling.TriggeringPolicy;
+import org.apache.logging.log4j.core.time.Clock;
import org.apache.logging.log4j.plugins.Plugin;
import org.apache.logging.log4j.status.StatusLogger;
import org.w3c.dom.Element;
+import java.util.Properties;
+
+import static org.apache.log4j.builders.BuilderManager.CATEGORY;
+import static org.apache.log4j.config.Log4j1Configuration.THRESHOLD_PARAM;
+import static org.apache.log4j.xml.XmlConfiguration.*;
+
/**
* Build a Daily Rolling File Appender
*/
@@ -129,7 +127,7 @@ public class DailyRollingFileAppenderBuilder extends AbstractBuilder implements
}
});
return createAppender(name, layout.get(), filter.get(), fileName.get(), append.get(), immediateFlush.get(),
- level.get(), bufferedIo.get(), bufferSize.get(), config);
+ level.get(), bufferedIo.get(), bufferSize.get(), config, config.getComponent(Clock.KEY));
}
@Override
@@ -144,12 +142,13 @@ public class DailyRollingFileAppenderBuilder extends AbstractBuilder implements
boolean bufferedIo = getBooleanProperty(BUFFERED_IO_PARAM);
int bufferSize = Integer.parseInt(getProperty(BUFFER_SIZE_PARAM, "8192"));
return createAppender(name, layout, filter, fileName, append, immediateFlush,
- level, bufferedIo, bufferSize, configuration);
+ level, bufferedIo, bufferSize, configuration, configuration.getComponent(Clock.KEY));
}
- private <T extends Log4j1Configuration> Appender createAppender(final String name, final Layout layout,
- final Filter filter, final String fileName, final boolean append, boolean immediateFlush,
- final String level, final boolean bufferedIo, final int bufferSize, final T configuration) {
+ private <T extends Log4j1Configuration> Appender createAppender(
+ final String name, final Layout layout, final Filter filter, final String fileName, final boolean append,
+ boolean immediateFlush, final String level, final boolean bufferedIo, final int bufferSize, final T configuration,
+ final Clock clock) {
org.apache.logging.log4j.core.Layout<?> fileLayout = null;
if (bufferedIo) {
@@ -166,7 +165,7 @@ public class DailyRollingFileAppenderBuilder extends AbstractBuilder implements
return null;
}
String filePattern = fileName + "%d{.yyyy-MM-dd}";
- TriggeringPolicy timePolicy = TimeBasedTriggeringPolicy.newBuilder().setModulate(true).build();
+ TriggeringPolicy timePolicy = TimeBasedTriggeringPolicy.newBuilder().setClock(clock).setModulate(true).build();
TriggeringPolicy policy = CompositeTriggeringPolicy.createPolicy(timePolicy);
RolloverStrategy strategy = DefaultRolloverStrategy.newBuilder()
.setConfig(configuration)
diff --git a/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/RollingFileAppenderBuilder.java b/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/RollingFileAppenderBuilder.java
index bc62db5..9bc8349 100644
--- a/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/RollingFileAppenderBuilder.java
+++ b/log4j-1.2-api/src/main/java/org/apache/log4j/builders/appender/RollingFileAppenderBuilder.java
@@ -16,15 +16,6 @@
*/
package org.apache.log4j.builders.appender;
-import static org.apache.log4j.builders.BuilderManager.CATEGORY;
-import static org.apache.log4j.config.Log4j1Configuration.THRESHOLD_PARAM;
-import static org.apache.log4j.xml.XmlConfiguration.FILTER_TAG;
-import static org.apache.log4j.xml.XmlConfiguration.LAYOUT_TAG;
-import static org.apache.log4j.xml.XmlConfiguration.PARAM_TAG;
-import static org.apache.log4j.xml.XmlConfiguration.forEachElement;
-
-import java.util.Properties;
-
import org.apache.log4j.Appender;
import org.apache.log4j.Layout;
import org.apache.log4j.bridge.AppenderWrapper;
@@ -45,10 +36,17 @@ import org.apache.logging.log4j.core.appender.rolling.RolloverStrategy;
import org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy;
import org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy;
import org.apache.logging.log4j.core.appender.rolling.TriggeringPolicy;
+import org.apache.logging.log4j.core.time.Clock;
import org.apache.logging.log4j.plugins.Plugin;
import org.apache.logging.log4j.status.StatusLogger;
import org.w3c.dom.Element;
+import java.util.Properties;
+
+import static org.apache.log4j.builders.BuilderManager.CATEGORY;
+import static org.apache.log4j.config.Log4j1Configuration.THRESHOLD_PARAM;
+import static org.apache.log4j.xml.XmlConfiguration.*;
+
/**
* Build a File Appender
*/
@@ -150,7 +148,7 @@ public class RollingFileAppenderBuilder extends AbstractBuilder implements Appen
}
});
return createAppender(name, config, layout.get(), filter.get(), bufferedIo.get(), immediateFlush.get(),
- fileName.get(), level.get(), maxSize.get(), maxBackups.get());
+ fileName.get(), level.get(), maxSize.get(), maxBackups.get(), config.getComponent(Clock.KEY));
}
@Override
@@ -165,12 +163,13 @@ public class RollingFileAppenderBuilder extends AbstractBuilder implements Appen
String maxSize = getProperty(MAX_SIZE_PARAM);
String maxBackups = getProperty(MAX_BACKUP_INDEX);
return createAppender(name, configuration, layout, filter, bufferedIo, immediateFlush, fileName, level, maxSize,
- maxBackups);
+ maxBackups, configuration.getComponent(Clock.KEY));
}
- private Appender createAppender(final String name, final Log4j1Configuration config, final Layout layout,
- final Filter filter, final boolean bufferedIo, boolean immediateFlush, final String fileName,
- final String level, final String maxSize, final String maxBackups) {
+ private Appender createAppender(
+ final String name, final Log4j1Configuration config, final Layout layout, final Filter filter,
+ final boolean bufferedIo, boolean immediateFlush, final String fileName, final String level, final String maxSize,
+ final String maxBackups, final Clock clock) {
org.apache.logging.log4j.core.Layout<?> fileLayout = null;
if (bufferedIo) {
immediateFlush = true;
@@ -186,9 +185,9 @@ public class RollingFileAppenderBuilder extends AbstractBuilder implements Appen
return null;
}
String filePattern = fileName + ".%i";
- TriggeringPolicy timePolicy = TimeBasedTriggeringPolicy.newBuilder().setModulate(true).build();
+ TriggeringPolicy timePolicy = TimeBasedTriggeringPolicy.newBuilder().setClock(clock).setModulate(true).build();
SizeBasedTriggeringPolicy sizePolicy = SizeBasedTriggeringPolicy.createPolicy(maxSize);
- CompositeTriggeringPolicy policy = CompositeTriggeringPolicy.createPolicy(sizePolicy);
+ CompositeTriggeringPolicy policy = CompositeTriggeringPolicy.createPolicy(timePolicy, sizePolicy);
RolloverStrategy strategy = DefaultRolloverStrategy.newBuilder()
.setConfig(config)
.setMax(maxBackups)
diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeTest.java
index 16305f0..95f4371 100644
--- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeTest.java
+++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderTimeTest.java
@@ -16,21 +16,26 @@
*/
package org.apache.logging.log4j.core.appender.rolling;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.test.junit.LoggerContextSource;
+import org.apache.logging.log4j.core.time.Clock;
+import org.apache.logging.log4j.plugins.Factory;
+import org.apache.logging.log4j.test.junit.CleanUpDirectories;
+import org.hamcrest.Matcher;
+import org.junit.jupiter.api.Test;
+
+import java.io.File;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.locks.LockSupport;
+
import static org.apache.logging.log4j.core.test.hamcrest.Descriptors.that;
import static org.apache.logging.log4j.core.test.hamcrest.FileMatchers.hasName;
import static org.hamcrest.Matchers.endsWith;
import static org.hamcrest.Matchers.hasItemInArray;
-import static org.junit.Assert.assertTrue;
-import static org.junit.Assert.fail;
-
-import java.io.File;
-
-import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.test.junit.LoggerContextRule;
-import org.hamcrest.Matcher;
-import org.junit.Rule;
-import org.junit.Test;
-import org.junit.rules.RuleChain;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+import static org.junit.jupiter.api.Assertions.fail;
/**
*
@@ -40,22 +45,26 @@ public class RollingAppenderTimeTest {
private static final String CONFIG = "log4j-rolling2.xml";
private static final String DIR = "target/rolling2";
- private final LoggerContextRule loggerContextRule = LoggerContextRule.createShutdownTimeoutLoggerContextRule(CONFIG);
+ private final AtomicLong currentTimeMillis = new AtomicLong(System.currentTimeMillis());
- @Rule
- public RuleChain chain = loggerContextRule.withCleanFoldersRule(DIR);
+ @Factory
+ Clock clock() {
+ return currentTimeMillis::get;
+ }
@Test
- public void testAppender() throws Exception {
- final Logger logger = loggerContextRule.getLogger();
+ @CleanUpDirectories(DIR)
+ @LoggerContextSource(value = CONFIG, timeout = 10)
+ public void testAppender(final LoggerContext context) throws Exception {
+ final Logger logger = context.getLogger(getClass());
logger.debug("This is test message number 1");
- Thread.sleep(1500);
+ currentTimeMillis.addAndGet(1500);
// Trigger the rollover
for (int i = 0; i < 16; ++i) {
logger.debug("This is test message number " + i + 1);
}
final File dir = new File(DIR);
- assertTrue("Directory not created", dir.exists() && dir.listFiles().length > 0);
+ assertTrue(dir.exists() && dir.listFiles().length > 0, "Directory not created");
final int MAX_TRIES = 20;
final Matcher<File[]> hasGzippedFile = hasItemInArray(that(hasName(that(endsWith(".gz")))));
@@ -65,7 +74,7 @@ public class RollingAppenderTimeTest {
return; // test succeeded
}
logger.debug("Adding additional event " + i);
- Thread.sleep(100); // Allow time for rollover to complete
+ LockSupport.parkNanos(TimeUnit.MILLISECONDS.toNanos(100)); // Allow time for rollover to complete
}
fail("No compressed files found");
}
diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectSizeTimeNewDirectoryTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectSizeTimeNewDirectoryTest.java
index 0e5270e..b5154b2 100644
--- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectSizeTimeNewDirectoryTest.java
+++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectSizeTimeNewDirectoryTest.java
@@ -20,6 +20,8 @@ import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.appender.RollingFileAppender;
import org.apache.logging.log4j.core.test.junit.LoggerContextSource;
+import org.apache.logging.log4j.core.time.Clock;
+import org.apache.logging.log4j.plugins.Factory;
import org.apache.logging.log4j.plugins.Named;
import org.apache.logging.log4j.test.junit.CleanUpDirectories;
import org.junit.jupiter.api.Test;
@@ -30,6 +32,7 @@ import java.util.Comparator;
import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
import static org.junit.jupiter.api.Assertions.assertTrue;
@@ -46,6 +49,12 @@ public class RollingDirectSizeTimeNewDirectoryTest implements RolloverListener {
private static final String DIR = "target/rolling-size-time-new-directory";
private final Map<String, AtomicInteger> rolloverFiles = new HashMap<>();
+ private final AtomicLong currentTimeMillis = new AtomicLong(System.currentTimeMillis());
+
+ @Factory
+ Clock clock() {
+ return currentTimeMillis::get;
+ }
@Test
@CleanUpDirectories(DIR)
@@ -57,7 +66,7 @@ public class RollingDirectSizeTimeNewDirectoryTest implements RolloverListener {
for (int i = 0; i < 1000; i++) {
logger.info("nHq6p9kgfvWfjzDRYbZp");
}
- Thread.sleep(1500);
+ currentTimeMillis.addAndGet(1500);
for (int i = 0; i < 1000; i++) {
logger.info("nHq6p9kgfvWfjzDRYbZp");
}
diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectTimeNewDirectoryTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectTimeNewDirectoryTest.java
index c3adf98..e6c0508 100644
--- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectTimeNewDirectoryTest.java
+++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingDirectTimeNewDirectoryTest.java
@@ -21,12 +21,15 @@ import org.apache.commons.io.filefilter.TrueFileFilter;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.test.junit.LoggerContextSource;
+import org.apache.logging.log4j.core.time.Clock;
+import org.apache.logging.log4j.plugins.Factory;
import org.apache.logging.log4j.test.junit.CleanUpDirectories;
import org.junit.jupiter.api.Test;
import java.io.File;
import java.util.Arrays;
import java.util.Iterator;
+import java.util.concurrent.atomic.AtomicLong;
import static org.junit.jupiter.api.Assertions.assertNotNull;
import static org.junit.jupiter.api.Assertions.assertTrue;
@@ -37,6 +40,12 @@ public class RollingDirectTimeNewDirectoryTest {
// Note that the path is hardcoded in the configuration!
private static final String DIR = "target/rolling-folder-direct";
+ private final AtomicLong currentTimeMillis = new AtomicLong(System.currentTimeMillis());
+
+ @Factory
+ Clock clock() {
+ return currentTimeMillis::get;
+ }
@Test
@CleanUpDirectories(DIR)
@@ -48,7 +57,7 @@ public class RollingDirectTimeNewDirectoryTest {
for (int i = 0; i < 1000; i++) {
logger.info("nHq6p9kgfvWfjzDRYbZp");
}
- Thread.sleep(1500);
+ currentTimeMillis.addAndGet(1500);
for (int i = 0; i < 1000; i++) {
logger.info("nHq6p9kgfvWfjzDRYbZp");
}
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/TimeBasedTriggeringPolicy.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/TimeBasedTriggeringPolicy.java
index 223e847..e8add12 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/TimeBasedTriggeringPolicy.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/TimeBasedTriggeringPolicy.java
@@ -18,6 +18,8 @@ package org.apache.logging.log4j.core.appender.rolling;
import org.apache.logging.log4j.core.Core;
import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.time.Clock;
+import org.apache.logging.log4j.plugins.Inject;
import org.apache.logging.log4j.plugins.Plugin;
import org.apache.logging.log4j.plugins.PluginBuilderAttribute;
import org.apache.logging.log4j.plugins.PluginFactory;
@@ -43,10 +45,12 @@ public final class TimeBasedTriggeringPolicy extends AbstractTriggeringPolicy {
@PluginBuilderAttribute
private int maxRandomDelay = 0;
+ private Clock clock;
+
@Override
public TimeBasedTriggeringPolicy build() {
final long maxRandomDelayMillis = TimeUnit.SECONDS.toMillis(maxRandomDelay);
- return new TimeBasedTriggeringPolicy(interval, modulate, maxRandomDelayMillis);
+ return new TimeBasedTriggeringPolicy(interval, modulate, maxRandomDelayMillis, clock);
}
public int getInterval() {
@@ -61,6 +65,10 @@ public final class TimeBasedTriggeringPolicy extends AbstractTriggeringPolicy {
return maxRandomDelay;
}
+ public Clock getClock() {
+ return clock;
+ }
+
public Builder setInterval(final int interval){
this.interval = interval;
return this;
@@ -76,19 +84,27 @@ public final class TimeBasedTriggeringPolicy extends AbstractTriggeringPolicy {
return this;
}
+ @Inject
+ public Builder setClock(final Clock clock) {
+ this.clock = clock;
+ return this;
+ }
}
private long nextRolloverMillis;
private final int interval;
private final boolean modulate;
private final long maxRandomDelayMillis;
+ private final Clock clock;
private RollingFileManager manager;
- private TimeBasedTriggeringPolicy(final int interval, final boolean modulate, final long maxRandomDelayMillis) {
+ private TimeBasedTriggeringPolicy(
+ final int interval, final boolean modulate, final long maxRandomDelayMillis, final Clock clock) {
this.interval = interval;
this.modulate = modulate;
this.maxRandomDelayMillis = maxRandomDelayMillis;
+ this.clock = clock;
}
public int getInterval() {
@@ -108,7 +124,7 @@ public final class TimeBasedTriggeringPolicy extends AbstractTriggeringPolicy {
this.manager = aManager;
long current = aManager.getFileTime();
if (current == 0) {
- current = System.currentTimeMillis();
+ current = clock.currentTimeMillis();
}
// LOG4J2-531: call getNextTime twice to force initialization of both prevFileTime and nextFileTime
@@ -130,7 +146,7 @@ public final class TimeBasedTriggeringPolicy extends AbstractTriggeringPolicy {
if (nowMillis >= nextRolloverMillis) {
nextRolloverMillis = ThreadLocalRandom.current().nextLong(0, 1 + maxRandomDelayMillis)
+ manager.getPatternProcessor().getNextTime(nowMillis, interval, modulate);
- manager.getPatternProcessor().setCurrentFileTime(System.currentTimeMillis());
+ manager.getPatternProcessor().setCurrentFileTime(clock.currentTimeMillis());
return true;
}
return false;