You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "ma jun (Jira)" <ji...@apache.org> on 2019/12/10 00:58:00 UTC
[jira] [Updated] (LOG4J2-2733) the initial logs were flushed away
while rolling file at the second time
[ https://issues.apache.org/jira/browse/LOG4J2-2733?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
ma jun updated LOG4J2-2733:
---------------------------
Summary: the initial logs were flushed away while rolling file at the second time (was: the initial logs were flushed away while rolling files at the second time)
> the initial logs were flushed away while rolling file at the second time
> ------------------------------------------------------------------------
>
> Key: LOG4J2-2733
> URL: https://issues.apache.org/jira/browse/LOG4J2-2733
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.12.1
> Reporter: ma jun
> Priority: Major
> Attachments: Main.java, log4j2_utc_test.xml
>
>
> observed a bug that the initial logs were flushed away while rolling files at the second time. if jvm is set a timezone which is different the log config's timezone, the issue happens and the log file will be rolling at different time point between the first day and the next days.
> please see below details
> 1. in java code the default timezone was set to UTC (project requirement). see below testing code piece .
> {code:java}
> static final Logger log = LoggerFactory.getLogger(Main.class);
>
> public static void main(String[] args) {
> java.util.TimeZone.setDefault(TimeZone.getTimeZone("UTC"));
> log.info("set timezone to UTC");
> while (true) {
> log.info("echo current timing-------------{}", System.currentTimeMillis());
> try {
> Thread.sleep(3 * 60 * 1000);
> } catch (InterruptedException e) {
> Thread.currentThread().interrupt();
> }
> }
> }
> {code}
> 2. and in log4j2 configuration , the time zone was still configured to America/New_York. see below configs.
> {noformat}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="INFO" strict="true">
> <Appenders>
>
> <RollingFile name="fileout" fileName="${sys:logDir}/log4j_rolling_test_utc.log"
> filePattern="${sys:logDir}/log4j_rolling_test_utc.log.%d{yyyyMMdd}{America/New_York}">
> <PatternLayout pattern="%d{yy-MM-dd HH:mm:ss.SSS}{America/New_York} [%-5level] %t %c{1.}:%L - %msg%n" />
> <Policies>
> <TimeBasedTriggeringPolicy interval="1"/>
> </Policies>
> </RollingFile>
> </Appenders>
> <Loggers>
> <Root level="${sys:logLevel}">
> <AppenderRef ref="fileout" />
> </Root>
> </Loggers>
> </Configuration>
> {noformat}
> 3. java cmd --
> /opt/jdk/1.8.0_151l64/bin/java -Dlog4j.configurationFile=/var/tmp/log4j2test/log4j2_utc_test.xml -DlogLevel=info -DlogDir=/var/tmp/log4j2test -jar /var/tmp/log4j2test/log4j2rolling_UTC.jar &
> and the linux session was in timezone EST
> 4. observed issue
> #1. the first day the logs were looking good. and the file rolling was also good for the first time
> 19-12-05 04:54:27.373 [INFO ] main l.Main:12 - echo current timing-------------1575539667366
> 19-12-05 04:57:27.378 [INFO ] main l.Main:12 - echo current timing-------------1575539847378
> 19-12-05 05:00:27.378 [INFO ] main l.Main:12 - echo current timing-------------1575540027378
> it generated a log file log4j_rolling_test_utc.log.20191205 with above logs. and meanwhile
> log4j_rolling_test_utc.log was still there to receive the new logs. and it was rolling at US time midnight, that's what i expected.
> #2. when the next day time moved to *UTC* midnight (US time 19:00), file rolling happened which was not expected. the initial logs(at timing 19-12-05 04:54) in log4j_rolling_test_utc.log.20191205 were flushed away. actually all the logs before 19-12-06 were flushed away.
> bash-4.1$ head log4j_rolling_test_utc.log.20191205
> 19-12-06 00:00:34.271 [INFO ] main l.Main:16 - echo current timing-------------1575608434270
> 19-12-06 00:03:34.277 [INFO ] main l.Main:16 - echo current timing-------------1575608614277
> 19-12-06 00:06:34.278 [INFO ] main l.Main:16 - echo current timing-------------1575608794277
> 19-12-06 00:09:34.278 [INFO ] main l.Main:16 - echo current timing-------------1575608974278
> Please let me know if you need more details.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)