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/09 09:58:00 UTC
[jira] [Updated] (LOG4J2-2733) the initial logs were flushed away
while rolling files 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:
---------------------------
Description:
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, 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.
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
was:
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 with 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, 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.
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
> the initial logs were flushed away while rolling files 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, 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.
> 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
--
This message was sent by Atlassian Jira
(v8.3.4#803005)