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:53:00 UTC

[jira] [Created] (LOG4J2-2733) the initial logs were flushed away while rolling files at the second time

ma jun created LOG4J2-2733:
------------------------------

             Summary: 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
         Attachments: Main.java, log4j2_utc_test.xml

observed a bug that the initial logs were flushed away while rolling files at the second time. 

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 &

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)