LOG4J2-1235 - org.apache.logging.log4j.core.appender.routing.IdlePurgePolicy not working correctly 1. Removed issue with NPE when tries to delete already deleted appender 2. Added parameter checkInterval for cases when all appenders already purged, so scheduler will keep working with this interval 3. Fixed an issue when appender purged even if received new event to it during purge procedure
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/040e29e2 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/040e29e2 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/040e29e2 Branch: refs/heads/LOG4J2-1010&LOG4J2-1447-injectable-contextdata&better-datastructure Commit: 040e29e209133efef788eb4132de30262d954ee4 Parents: af7d1a0 Author: Aleksey Zvolinsky <[email protected]> Authored: Fri May 27 15:29:37 2016 +0300 Committer: Gary Gregory <[email protected]> Committed: Mon Aug 29 10:20:53 2016 -0700 ---------------------------------------------------------------------- .../core/appender/routing/IdlePurgePolicy.java | 56 +++++++++++++------- .../core/appender/routing/RoutingAppender.java | 14 +++-- .../routing/RoutingAppenderWithPurgingTest.java | 19 +++++-- 3 files changed, 64 insertions(+), 25 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/040e29e2/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/IdlePurgePolicy.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/IdlePurgePolicy.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/IdlePurgePolicy.java index f4f6e35..dacf993 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/IdlePurgePolicy.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/IdlePurgePolicy.java @@ -22,7 +22,6 @@ import java.util.concurrent.ConcurrentMap; import java.util.concurrent.ScheduledFuture; import java.util.concurrent.TimeUnit; -import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.AbstractLifeCycle; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.config.Configuration; @@ -32,7 +31,6 @@ import org.apache.logging.log4j.core.config.plugins.Plugin; import org.apache.logging.log4j.core.config.plugins.PluginAttribute; import org.apache.logging.log4j.core.config.plugins.PluginConfiguration; import org.apache.logging.log4j.core.config.plugins.PluginFactory; -import org.apache.logging.log4j.status.StatusLogger; /** * Policy is purging appenders that were not in use specified time in minutes @@ -41,15 +39,16 @@ import org.apache.logging.log4j.status.StatusLogger; @Scheduled public class IdlePurgePolicy extends AbstractLifeCycle implements PurgePolicy, Runnable { - private static final Logger LOGGER = StatusLogger.getLogger(); private final long timeToLive; + private final long checkInterval; private final ConcurrentMap<String, Long> appendersUsage = new ConcurrentHashMap<>(); private RoutingAppender routingAppender; private final ConfigurationScheduler scheduler; private volatile ScheduledFuture<?> future = null; - public IdlePurgePolicy(final long timeToLive, final ConfigurationScheduler scheduler) { + public IdlePurgePolicy(long timeToLive, long checkInterval, final ConfigurationScheduler scheduler) { this.timeToLive = timeToLive; + this.checkInterval = checkInterval; this.scheduler = scheduler; } @@ -73,8 +72,9 @@ public class IdlePurgePolicy extends AbstractLifeCycle implements PurgePolicy, R for (final Entry<String, Long> entry : appendersUsage.entrySet()) { if (entry.getValue() < createTime) { LOGGER.debug("Removing appender " + entry.getKey()); - appendersUsage.remove(entry.getKey()); - routingAppender.deleteAppender(entry.getKey()); + if(appendersUsage.remove(entry.getKey(), entry.getValue())) { + routingAppender.deleteAppender(entry.getKey()); + } } } } @@ -100,33 +100,39 @@ public class IdlePurgePolicy extends AbstractLifeCycle implements PurgePolicy, R } private void scheduleNext() { - long createTime = Long.MAX_VALUE; + long updateTime = Long.MAX_VALUE; for (final Entry<String, Long> entry : appendersUsage.entrySet()) { - if (entry.getValue() < createTime) { - createTime = entry.getValue(); + if (entry.getValue() < updateTime) { + updateTime = entry.getValue(); } } - if (createTime < Long.MAX_VALUE) { - final long interval = timeToLive - (System.currentTimeMillis() - createTime); + + if (updateTime < Long.MAX_VALUE) { + long interval = timeToLive - (System.currentTimeMillis() - updateTime); future = scheduler.schedule(this, interval, TimeUnit.MILLISECONDS); + } else { + // reset to initial state - in case of all appenders already purged + future = scheduler.schedule(this, checkInterval, TimeUnit.MILLISECONDS); } } /** * Create the PurgePolicy * - * @param timeToLive the number of increments of timeUnit before the Appender should be purged. - * @param timeUnit the unit of time the timeToLive is expressed in. + * @param timeToLive the number of increments of timeUnit before the Appender should be purged. + * @param checkInterval when all appenders purged, the number of increments of timeUnit to check if any appenders appeared + * @param timeUnit the unit of time the timeToLive and the checkInterval is expressed in. * @return The Routes container. */ @PluginFactory public static PurgePolicy createPurgePolicy( @PluginAttribute("timeToLive") final String timeToLive, + @PluginAttribute("checkInterval") final String checkInterval, @PluginAttribute("timeUnit") final String timeUnit, @PluginConfiguration final Configuration configuration) { if (timeToLive == null) { - LOGGER.error("A timeToLive value is required"); + LOGGER.error("A timeToLive value is required"); return null; } TimeUnit units; @@ -136,15 +142,29 @@ public class IdlePurgePolicy extends AbstractLifeCycle implements PurgePolicy, R try { units = TimeUnit.valueOf(timeUnit.toUpperCase()); } catch (final Exception ex) { - LOGGER.error("Invalid time unit {}", timeUnit); + LOGGER.error("Invalid timeUnit value {}. timeUnit set to MINUTES", timeUnit, ex); units = TimeUnit.MINUTES; } } - final long ttl = units.toMillis(Long.parseLong(timeToLive)); - + long ttl = units.toMillis(Long.parseLong(timeToLive)); + if(ttl < 0) { + LOGGER.error("timeToLive must be positive. timeToLive set to 0"); + ttl = 0; + } + + long ci; + if(checkInterval == null) { + ci = ttl; + } else { + ci = units.toMillis(Long.parseLong(checkInterval)); + if(ci < 0) { + LOGGER.error("checkInterval must be positive. checkInterval set equal to timeToLive = {}", ttl); + ci = ttl; + } + } - return new IdlePurgePolicy(ttl, configuration.getScheduler()); + return new IdlePurgePolicy(ttl, ci, configuration.getScheduler()); } @Override http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/040e29e2/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/RoutingAppender.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/RoutingAppender.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/RoutingAppender.java index 0df19eb..059413d 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/RoutingAppender.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/routing/RoutingAppender.java @@ -182,9 +182,17 @@ public final class RoutingAppender extends AbstractAppender { * @param key The appender's key */ public void deleteAppender(final String key) { - LOGGER.debug("Stopping route with key" + key); - final AppenderControl control = appenders.remove(key); - control.getAppender().stop(); + LOGGER.debug("Stopping route with key" + key); + AppenderControl control = appenders.remove(key); + control.getAppender().stop(); + LOGGER.debug("Deleting route with " + key + " key "); + AppenderControl control = appenders.remove(key); + if(null != control) { + LOGGER.debug("Stopping route with " + key + " key"); + control.getAppender().stop(); + } else { + LOGGER.debug("Route with " + key + " key already deleted"); + } } /** http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/040e29e2/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/routing/RoutingAppenderWithPurgingTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/routing/RoutingAppenderWithPurgingTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/routing/RoutingAppenderWithPurgingTest.java index 8fdb402..9fc4005 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/routing/RoutingAppenderWithPurgingTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/routing/RoutingAppenderWithPurgingTest.java @@ -105,11 +105,22 @@ public class RoutingAppenderWithPurgingTest { assertEquals("Incorrect number of appenders with IdlePurgePolicy.", 1, routingAppenderIdle.getAppenders().size()); assertEquals("Incorrect number of appenders with manual purge.", 0, routingAppenderManual.getAppenders().size()); + + msg = new StructuredDataMessage("5", "This is a test 5", "Service"); + EventLogger.logEvent(msg); + + assertEquals("Incorrect number of appenders with manual purge.", 1, routingAppenderManual.getAppenders().size()); + + routingAppenderManual.deleteAppender("5"); + routingAppenderManual.deleteAppender("5"); + + assertEquals("Incorrect number of appenders with manual purge.", 0, routingAppenderManual.getAppenders().size()); } - private void assertFileExistance(final String... files) { - for (final String file : files) { - assertTrue("File should exist - " + file + " file ", new File(file).exists()); - } + + private void assertFileExistance(String... files) { + for (String file : files) { + assertTrue("File should exist - " + file + " file ", new File(file).exists()); + } } }
