LOG4J2-1405 - OnStartupTriggeringPolicy was forcing a rollover of empty files at startup and would append a second footer that was added by the prior shutdown
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/9eae0857 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/9eae0857 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/9eae0857 Branch: refs/heads/LOG4J2-1395 Commit: 9eae08579162f7328045a8343660f123235a0b28 Parents: 37d1428 Author: Ralph Goers <[email protected]> Authored: Sat Jun 4 23:31:14 2016 -0700 Committer: Ralph Goers <[email protected]> Committed: Sun Jun 5 15:06:17 2016 -0700 ---------------------------------------------------------------------- .../core/appender/OutputStreamManager.java | 11 +- .../rolling/OnStartupTriggeringPolicy.java | 48 ++------- .../rolling/RollingAppenderOnStartupTest.java | 100 +++++++++++++++++++ log4j-core/src/test/resources/log4j-test4.xml | 36 +++++++ src/changes/changes.xml | 4 + 5 files changed, 156 insertions(+), 43 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9eae0857/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/OutputStreamManager.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/OutputStreamManager.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/OutputStreamManager.java index 5e3ae5d..825e2c5 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/OutputStreamManager.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/OutputStreamManager.java @@ -33,6 +33,7 @@ public class OutputStreamManager extends AbstractManager implements ByteBufferDe protected final Layout<?> layout; protected ByteBuffer byteBuffer; private volatile OutputStream os; + private boolean skipFooter = false; protected OutputStreamManager(final OutputStream os, final String streamName, final Layout<?> layout, final boolean writeHeader) { @@ -81,6 +82,14 @@ public class OutputStreamManager extends AbstractManager implements ByteBufferDe } /** + * Indicate whether the footer should be skipped or not. + * @param skipFooter true if the footer should be skipped. + */ + public void skipFooter(boolean skipFooter) { + this.skipFooter = skipFooter; + } + + /** * Default hook to write footer during close. */ @Override @@ -93,7 +102,7 @@ public class OutputStreamManager extends AbstractManager implements ByteBufferDe * Writes the footer. */ protected void writeFooter() { - if (layout == null) { + if (layout == null || skipFooter) { return; } final byte[] footer = layout.getFooter(); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9eae0857/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java index 6f2dd6b..bf49516 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java @@ -25,15 +25,10 @@ import org.apache.logging.log4j.core.util.Loader; import org.apache.logging.log4j.status.StatusLogger; /** - * Triggers a rollover on every restart. The target file's timestamp is compared with the JVM start time - * and if it is older isTriggeringEvent will return true. After isTriggeringEvent has been called it will - * always return false. + * Triggers a rollover on every restart, but only if the file size is greater than zero. */ @Plugin(name = "OnStartupTriggeringPolicy", category = "Core", printObject = true) public class OnStartupTriggeringPolicy implements TriggeringPolicy { - private static long JVM_START_TIME = initStartTime(); - - private boolean evaluated = false; private RollingFileManager manager; /** @@ -43,37 +38,10 @@ public class OnStartupTriggeringPolicy implements TriggeringPolicy { @Override public void initialize(final RollingFileManager manager) { this.manager = manager; - if (JVM_START_TIME == 0) { - evaluated = true; - } - } - - /** - * Returns the result of {@code ManagementFactory.getRuntimeMXBean().getStartTime()}, - * or the current system time if JMX is not available. - */ - private static long initStartTime() { - // LOG4J2-379: - // We'd like to call ManagementFactory.getRuntimeMXBean().getStartTime(), - // but Google App Engine throws a java.lang.NoClassDefFoundError - // "java.lang.management.ManagementFactory is a restricted class". - // The reflection is necessary because without it, Google App Engine - // will refuse to initialize this class. - try { - final Class<?> factoryClass = Loader.loadSystemClass("java.lang.management.ManagementFactory"); - final Method getRuntimeMXBean = factoryClass.getMethod("getRuntimeMXBean"); - final Object runtimeMXBean = getRuntimeMXBean.invoke(null); - - final Class<?> runtimeMXBeanClass = Loader.loadSystemClass("java.lang.management.RuntimeMXBean"); - final Method getStartTime = runtimeMXBeanClass.getMethod("getStartTime"); - final Long result = (Long) getStartTime.invoke(runtimeMXBean); - - return result.longValue(); - } catch (final Throwable t) { - StatusLogger.getLogger().error("Unable to call ManagementFactory.getRuntimeMXBean().getStartTime(), " // - + "using system time for OnStartupTriggeringPolicy", t); - // We have little option but to declare "now" as the beginning of time. - return System.currentTimeMillis(); + if (manager.getFileSize() > 0) { + manager.skipFooter(true); + manager.rollover(); + manager.skipFooter(false); } } @@ -84,11 +52,7 @@ public class OnStartupTriggeringPolicy implements TriggeringPolicy { */ @Override public boolean isTriggeringEvent(final LogEvent event) { - if (evaluated) { - return false; - } - evaluated = true; - return manager.getFileTime() < JVM_START_TIME; + return false; } @Override http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9eae0857/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderOnStartupTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderOnStartupTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderOnStartupTest.java new file mode 100644 index 0000000..3d1e704 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/rolling/RollingAppenderOnStartupTest.java @@ -0,0 +1,100 @@ +/* + * 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.nio.file.DirectoryStream; +import java.nio.file.Files; +import java.nio.file.Path; +import java.nio.file.Paths; +import java.util.Arrays; +import java.util.Collection; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.junit.LoggerContextRule; +import org.junit.AfterClass; +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.Parameterized; + +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 static org.junit.Assert.fail; + +/** + * + */ +@RunWith(Parameterized.class) +public class RollingAppenderOnStartupTest { + + private static final String DIR = "target/rolling1"; + + private final String fileExtension; + + private Logger logger; + + @Parameterized.Parameters(name = "{0} \u2192 {1}") + public static Collection<Object[]> data() { + return Arrays.asList(new Object[][] { // + // @formatter:off + {"log4j-test4.xml", ".gz"}, + {"log4j-test4.xml", ".gz"},}); + // @formatter:on + } + + @Rule + public LoggerContextRule init; + + public RollingAppenderOnStartupTest(final String configFile, final String fileExtension) { + this.fileExtension = fileExtension; + this.init = new LoggerContextRule(configFile); + } + + @Before + public void setUp() throws Exception { + this.logger = this.init.getLogger(RollingAppenderOnStartupTest.class.getName()); + } + + @AfterClass + public static void afterClass() throws Exception { + long size = 0; + try (DirectoryStream<Path> directoryStream = Files.newDirectoryStream(Paths.get("target/onStartup"))) { + for (Path path : directoryStream) { + if (size == 0) { + size = Files.size(path); + } else { + assertTrue(size == Files.size(path)); + } + Files.delete(path); + } + Files.delete(Paths.get("target/onStartup")); + } + } + + @Test + public void testAppender() throws Exception { + for (int i = 0; i < 100; ++i) { + logger.debug("This is test message number " + i); + } + + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9eae0857/log4j-core/src/test/resources/log4j-test4.xml ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/resources/log4j-test4.xml b/log4j-core/src/test/resources/log4j-test4.xml new file mode 100644 index 0000000..a1ee305 --- /dev/null +++ b/log4j-core/src/test/resources/log4j-test4.xml @@ -0,0 +1,36 @@ +<?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="OFF" name="XMLConfigTest" monitorInterval="1"> + <Appenders> + <RollingFile name="RollingFile" fileName="target/onStartup/onStartup.log" + filePattern="target/onStartup/onStartup-%d{MM-dd-yyyy}-%i.log"> + <HTMLLayout title="test"/> + <Policies> + <OnStartupTriggeringPolicy /> + </Policies> + </RollingFile> + </Appenders> + + <Loggers> + <Root level="trace"> + <AppenderRef ref="RollingFile"/> + </Root> + </Loggers> + +</Configuration> \ No newline at end of file http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/9eae0857/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index 08a2915..a78de5b 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -24,6 +24,10 @@ </properties> <body> <release version="2.6.1" date="2016-MM-DD" description="GA Release 2.6.1"> + <action issue="LOG4J2-1405" dev="rgoers" type="fix"> + OnStartupTriggeringPolicy was forcing a rollover of empty files at startup and would append a + second footer that was added by the prior shutdown. + </action> <action issue="LOG4J2-1406" dev="rpopma" type="fix" due-to="Trask Stalnaker"> Fixed bug in ReusableParameterizedMessage where Throwable was never updated so first error was logged over and over again and subsequent errors were not logged.
