Repository: logging-log4j2 Updated Branches: refs/heads/master e38df78e8 -> 36cc28e95
LOG4J2-1640 - Sleep if event fires early Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/36cc28e9 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/36cc28e9 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/36cc28e9 Branch: refs/heads/master Commit: 36cc28e956ceae361cb7bae12a91c5c0bb4295f9 Parents: e38df78 Author: Ralph Goers <rgo...@nextiva.com> Authored: Mon Jan 9 09:19:35 2017 -0700 Committer: Ralph Goers <rgo...@nextiva.com> Committed: Mon Jan 9 09:19:59 2017 -0700 ---------------------------------------------------------------------- .../appender/rolling/CronTriggeringPolicy.java | 1 + .../appender/rolling/RollingFileManager.java | 1 + .../core/config/ConfigurationScheduler.java | 35 ++++++++ .../rolling/RollingAppenderCronEvery2Test.java | 95 ++++++++++++++++++++ .../log4j/core/util/CronExpressionTest.java | 9 ++ .../resources/log4j-rolling-cron-every2.xml | 54 +++++++++++ 6 files changed, 195 insertions(+) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/36cc28e9/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/CronTriggeringPolicy.java ---------------------------------------------------------------------- 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 0f54176..e8f4208 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 @@ -85,6 +85,7 @@ public final class CronTriggeringPolicy extends AbstractTriggeringPolicy { } lastRollDate = lastRegularRoll; future = scheduler.scheduleWithCron(cronExpression, now, new CronTrigger()); + LOGGER.debug(scheduler.toString()); } /** http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/36cc28e9/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java ---------------------------------------------------------------------- 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 71647a0..10cb79e 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 @@ -104,6 +104,7 @@ public class RollingFileManager extends FileManager { public void initialize() { if (!initialized) { + LOGGER.debug("Initializing triggering policy {}", triggeringPolicy); initialized = true; triggeringPolicy.initialize(this); if (triggeringPolicy instanceof LifeCycle) { http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/36cc28e9/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java index 4eaa007..6c639f2 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java @@ -18,21 +18,25 @@ package org.apache.logging.log4j.core.config; import java.util.Date; import java.util.List; +import java.util.Queue; import java.util.concurrent.Callable; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledFuture; import java.util.concurrent.ScheduledThreadPoolExecutor; import java.util.concurrent.TimeUnit; +import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.AbstractLifeCycle; import org.apache.logging.log4j.core.util.CronExpression; import org.apache.logging.log4j.core.util.Log4jThreadFactory; +import org.apache.logging.log4j.status.StatusLogger; /** * */ public class ConfigurationScheduler extends AbstractLifeCycle { + private static final Logger LOGGER = StatusLogger.getLogger(); private static final String SIMPLE_NAME = "Log4j2 " + ConfigurationScheduler.class.getSimpleName(); private static final int MAX_SCHEDULED_ITEMS = 5; private ScheduledExecutorService executorService; @@ -139,6 +143,7 @@ public class ConfigurationScheduler extends AbstractLifeCycle { final ScheduledFuture<?> future = schedule(runnable, nextFireInterval(fireDate), TimeUnit.MILLISECONDS); final CronScheduledFuture<?> cronScheduledFuture = new CronScheduledFuture<>(future, fireDate); runnable.setScheduledFuture(cronScheduledFuture); + LOGGER.debug("Scheduled cron expression {} to fire at {}", cronExpression.getCronExpression(), fireDate); return cronScheduledFuture; } @@ -212,15 +217,45 @@ public class ConfigurationScheduler extends AbstractLifeCycle { @Override public void run() { try { + long millis = scheduledFuture.getFireTime().getTime() - System.currentTimeMillis(); + if (millis > 0) { + LOGGER.debug("Cron thread woke up {} millis early. Sleeping", millis); + try { + Thread.sleep(millis); + } catch (InterruptedException ie) { + // Ignore the interruption. + } + } runnable.run(); } catch(final Throwable ex) { LOGGER.error("{} caught error running command", SIMPLE_NAME, ex); } finally { final Date fireDate = cronExpression.getNextValidTimeAfter(new Date()); final ScheduledFuture<?> future = schedule(this, nextFireInterval(fireDate), TimeUnit.MILLISECONDS); + LOGGER.debug("Cron expression {} scheduled to fire again at {}", cronExpression.getCronExpression(), + fireDate); scheduledFuture.reset(future, fireDate); } } + + public String toString() { + return "CronRunnable{" + cronExpression.getCronExpression() + " - " + scheduledFuture.getFireTime(); + } + } + + public String toString() { + StringBuilder sb = new StringBuilder("ConfigurationScheduler {"); + Queue<Runnable> queue = ((ScheduledThreadPoolExecutor) executorService).getQueue(); + boolean first = true; + for (Runnable runnable : queue) { + if (!first) { + sb.append(", "); + } + sb.append(runnable.toString()); + first = false; + } + sb.append("}"); + return sb.toString(); } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/36cc28e9/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronEvery2Test.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronEvery2Test.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronEvery2Test.java new file mode 100644 index 0000000..a2e859b --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderCronEvery2Test.java @@ -0,0 +1,95 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache license, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the license for the specific language governing permissions and + * limitations under the license. + */ +package org.apache.logging.log4j.core.appender.rolling; + +import java.io.File; +import java.io.FileOutputStream; +import java.io.OutputStream; +import java.nio.file.FileSystems; +import java.nio.file.Files; +import java.nio.file.Path; +import java.security.SecureRandom; +import java.util.Random; + +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.appender.RollingFileAppender; +import org.apache.logging.log4j.core.util.CronExpression; +import org.apache.logging.log4j.junit.LoggerContextRule; +import org.hamcrest.Matcher; +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.*; + +/** + * + */ +public class RollingAppenderCronEvery2Test { + + private static final String CONFIG = "log4j-rolling-cron-every2.xml"; + private static final String DIR = "target/rolling-cron-every2"; + private static final String FILE = "target/rolling-cron-every2/rollingtest.log"; + private static final int LOOP_COUNT = 100; + + private final LoggerContextRule loggerContextRule = LoggerContextRule.createShutdownTimeoutLoggerContextRule(CONFIG); + + @Rule + public RuleChain chain = loggerContextRule.withCleanFoldersRule(DIR); + + @Test + public void testAppender() throws Exception { + // TODO Is there a better way to test than putting the thread to sleep all over the place? + final Logger logger = loggerContextRule.getLogger(); + final File file = new File(FILE); + assertTrue("Log file does not exist", file.exists()); + long end = System.currentTimeMillis() + 5000; + Random rand = new SecureRandom(); + rand.setSeed(end); + int count = 1; + do { + logger.debug("Log Message {}", count++); + Thread.sleep(10 * rand.nextInt(100)); + } while (System.currentTimeMillis() < end); + final File dir = new File(DIR); + assertTrue("Directory not created", dir.exists() && dir.listFiles().length > 0); + + final int MAX_TRIES = 20; + final Matcher<File[]> hasGzippedFile = hasItemInArray(that(hasName(that(endsWith(".gz"))))); + boolean succeeded = false; + for (int i = 0; i < MAX_TRIES; i++) { + final File[] files = dir.listFiles(); + if (hasGzippedFile.matches(files)) { + succeeded = true; + break; + } + logger.debug("Sleeping #" + i); + Thread.sleep(100); // Allow time for rollover to complete + } + if (!succeeded) { + final File[] files = dir.listFiles(); + for (final File dirFile : files) { + logger.error("Found file: " + dirFile.getPath()); + } + fail("No compressed files found"); + } + } + +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/36cc28e9/log4j-core/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java index d096e39..0212cac 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/util/CronExpressionTest.java @@ -66,6 +66,15 @@ public class CronExpressionTest { } @Test + public void testNextDay() throws Exception { + final CronExpression parser = new CronExpression("0 0 0 * * ?"); + final Date date = new GregorianCalendar(2015, 10, 2).getTime(); + final Date fireDate = parser.getNextValidTimeAfter(date); + final Date expected = new GregorianCalendar(2015, 10, 3, 0, 0, 0).getTime(); + assertEquals("Dates not equal.", expected, fireDate); + } + + @Test public void testPrevFireTime1() throws Exception { CronExpression parser = new CronExpression("0 */15,12 7-11,13-17 L * ?"); Date date = new GregorianCalendar(2015, 10, 2).getTime(); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/36cc28e9/log4j-core/src/test/resources/log4j-rolling-cron-every2.xml ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/resources/log4j-rolling-cron-every2.xml b/log4j-core/src/test/resources/log4j-rolling-cron-every2.xml new file mode 100644 index 0000000..67f1d0c --- /dev/null +++ b/log4j-core/src/test/resources/log4j-rolling-cron-every2.xml @@ -0,0 +1,54 @@ +<?xml version="1.0" encoding="UTF-8"?> +<!-- + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + +--> +<Configuration status="WARN" name="RollingCronTest" monitorInterval="1"> + <Properties> + <Property name="filename">target/rolling-cron-every2/rollingtest.log</Property> + </Properties> + <Filters> + <ThresholdFilter level="debug"/> + </Filters> + + <Appenders> + <Console name="STDOUT"> + <PatternLayout pattern="%m%n"/> + </Console> + <RollingFile name="RollingFile" fileName="${filename}" filePattern="target/rolling-cron-every2/test1-%d{MM-dd-yy-HH-mm-ss}.log.gz"> + <PatternLayout> + <Pattern>%d %p %C{1.} [%t] %m%n</Pattern> + </PatternLayout> + <CronTriggeringPolicy schedule="0/2 * * * * ?"/> + </RollingFile> + <List name="List"> + <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> + + <Root level="error"> + <AppenderRef ref="STDOUT"/> + </Root> + </Loggers> + +</Configuration> \ No newline at end of file
