[
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 (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.
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 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. 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.
> 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 (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)
