[
https://issues.apache.org/jira/browse/LOG4J2-2168?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16320673#comment-16320673
]
Remko Popma commented on LOG4J2-2168:
-------------------------------------
I took another look at the attached log and it seems that the time on that
machine was modified to one hour in the past, is that possible?
{code}
...
2017-12-13 17:41:58,424 main TRACE Using default SystemClock for timestamps.
2017-12-13 16:42:08,668 main TRACE PatternProcessor.getNextTime returning
2017/12/13-16:43:00.000, nextFileTime=2017/12/13-16:42:00.000, prevFileTime=
...
{code}
The rollover appender has come cached values and keeps adding to the rollover
time, so it creates rollover files with a 17:41... timestamp. It essentially
creates log archives with timestamps in the future:
{code}
2017-12-13 16:42:08,675 main TRACE Renamed file
/data/hazelcast/logs/hazelcast.log to
/data/hazelcast/logs/hazelcast-2017-12-13-17-41-1.log with Files
.move
2017-12-13 16:42:08,675 main DEBUG RollingFileManager executing async
GzCompressAction[/data/hazelcast/logs/hazelcast-2017-12-13-17-41-1.log to /data/
hazelcast/logs/hazelcast-2017-12-13-17-41-1.log.gz, deleteSource=true]
...
2017-12-13 16:43:08,700 [V3D Pool-12]-AlertService-FlushExecutor-oes-1 TRACE
Renamed file /data/hazelcast/logs/hazelcast.log to /data/hazelcast/logs/h
azelcast-2017-12-13-17-42-1.log with Files.move
2017-12-13 16:43:08,700 [V3D Pool-12]-AlertService-FlushExecutor-oes-1 DEBUG
RollingFileManager executing async GzCompressAction[/data/hazelcast/logs/
hazelcast-2017-12-13-17-42-1.log to
/data/hazelcast/logs/hazelcast-2017-12-13-17-42-1.log.gz, deleteSource=true]
...
{code}
Multiple rollover files are created like this.
After this, the configuration is changed from rolling over every minute to
every hour, and again the clock is set back by some amount.
Is it possible that these operations of changing the clock time on the machine
and reconfiguring Log4j caused the rollovers to overwrite log archives that
were created earlier but had a timestamp that was in the future?
> RollingFile appender make no archive
> ------------------------------------
>
> Key: LOG4J2-2168
> URL: https://issues.apache.org/jira/browse/LOG4J2-2168
> Project: Log4j 2
> Issue Type: Question
> Affects Versions: 2.7
> Reporter: Claire Villard
> Attachments: log_log4j.txt
>
>
> Hi,
> I run a Java app, with Log4J2, on Linux (mainly CentOS) servers.
> Here is my configuration file:
> {code}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration shutdownHook="disable" monitorInterval="30" status="trace">
> <Appenders>
> <RollingFile name="RollingFile" fileName="/data/logs/hazelcast.log"
> filePattern="/data/logs/hazelcast-%d{yyyy-MM-dd-HH}{CET}-%i.log.gz">
> <PatternLayout>
> <Pattern>%d{yyyy-MM-dd HH:mm:ss,fff}{CET} %-5p [%t] %C{2}
> (%F:%L) - %m%n</Pattern>
> </PatternLayout>
> <Policies>
> <SizeBasedTriggeringPolicy size="300MB" />
> <TimeBasedTriggeringPolicy />
> </Policies>
> <DefaultRolloverStrategy max="90"/>
> </RollingFile>
> </Appenders>
> <Loggers>
> <Root level="DEBUG">
> <AppenderRef ref="RollingFile"/>
> </Root>
> </Loggers>
> </Configuration>
> {code}
> We expect the log file to be rolled each hour, or when its size reaches 300MB.
> This behavior is observed on all our servers, except one, and we can't find
> why.
> On this server, the file is rolled, the file with the old logs is renamed and
> gzipped... and a few seconds after that, gets deleted.
> The files are not deleted if our application is not started, invalidating the
> hypothesis of another process on the server deleting them.
> Removing the line {{<DefaultRolloverStrategy max="90"/>}} did not changed
> anything.
> Changing the file pattern to make them roll each minute, or each day, did not
> changed anything neither. The files are always deleted.
> Another test we did on December, 13th: we created a few files with the
> expected pattern (rolling each minute):
> {code}
> [root@INCBMCBINTMD03 logs]# ll
> total 52912
> -rw-r--r-- 1 hazelcast hazelcast 48238592 Dec 20 2016
> hazelcast-2016-12-19-1.log
> -rw-r--r-- 1 hazelcast hazelcast 345052 Sep 1 01:59
> hazelcast-2017-08-31-1.log
> -rw-r--r-- 1 hazelcast hazelcast 1147 Dec 13 09:55
> hazelcast-2017-12-13-09-54-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 783 Dec 13 09:58
> hazelcast-2017-12-13-09-57-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 782 Dec 13 10:01
> hazelcast-2017-12-13-10-00-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 463 Dec 13 10:09
> hazelcast-2017-12-13-10-08-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 239 Dec 13 10:11
> hazelcast-2017-12-13-10-10-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 1075 Dec 13 10:12
> hazelcast-2017-12-13-10-11-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 465 Dec 13 10:14
> hazelcast-2017-12-13-10-13-1.log.gz
> -rw-r--r-- 1 hazelcast hazelcast 533 Dec 13 10:15
> hazelcast-2017-12-13-10-14-1.log.gz
> -rw-rw-r-- 1 hazelcast hazelcast 81184 Dec 13 10:51 hazelcast.log
> -rw-rw-r-- 1 hazelcast hazelcast 5469748 Sep 15 2016 hazelcast.log.old
> {code}
> We start the app, and 2 minutes later, the content of the directory is:
> {code}
> [root@INCBMCBINTMD03 logs]# ll
> total 52892
> -rw-r--r-- 1 hazelcast hazelcast 48238592 Dec 20 2016
> hazelcast-2016-12-19-1.log
> -rw-r--r-- 1 hazelcast hazelcast 345052 Sep 1 01:59
> hazelcast-2017-08-31-1.log
> -rw-rw-r-- 1 hazelcast hazelcast 92742 Dec 13 10:53 hazelcast.log
> -rw-rw-r-- 1 hazelcast hazelcast 5469748 Sep 15 2016 hazelcast.log.old
> {code}
> All the directories and files concerned by this configuration have the right
> permissions to be read, written or moved by the user running the app.
> We activated the "trace" mode of Log4J, some logs are attached. The problem
> occurred when these logs were produced, but we didn't find anything in them
> to help us figuring out what's happening.
> Any help would be greatly appreciated !
> Thanks in advance,
> Claire
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
