[
https://issues.apache.org/jira/browse/LOG4J2-531?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13895903#comment-13895903
]
Remko Popma commented on LOG4J2-531:
------------------------------------
Well, this is a nasty one... Sorry if what follows is a long story, but it has
taken me all day to figure this out.
At rollover, the name of the archive file is based on a date format and an
index (assuming both TimeBased and SizeBased triggering).
* The index is determined based on a scan of the target directory.
* The date-time is _not_ the current date-time, but the date-time of the
_previous_ rollover.
This is by design: for example, if you roll over once a day, you want the
archive containing Wednesday's log files to be called "Wednesday.log.zip", even
if the rollover happens on Thursday at midnight.
This behaviour is implemented in {{PatternProcessor}} (the class responsible
for producing the post-rollover file name) by remembering the previous rollover
time in an instance variable.
The current implementation assumes that rollover will not take longer than the
rollover period specified in the date format. Since the
{{DefaultRolloverStrategy}} is configured with {{max=999999}}, and a directory
scan takes 5 minutes, this assumption no longer holds: we are supposed to roll
over every minute but the rollover process takes five minutes.
This highlights three problems in the current implementation:
*1. Initialization is incorrect*
* At startup, {{PatternProcessor.prevFileTime}} (the field storing previous
rollover time) is not initialized (its value is copied from {{nextFileTime}}
which is still zero).
* At the same time, {{PatternProcessor.nextFileTime}} is initialized to the log
file's lastModified time (for example 10:00).
* For the first rollover, the directory is scanned. This completes at 10:05.
* The archive file is created based on {{PatternProcessor.prevFileTime}}. Since
this is not initialized yet, the logic falls back to the current time (10:05).
{color:blue}Rollover creates archive <...>1005.1.log.zip{color}
* The next log event is processed. Event time is 10:00:01, triggering another
rollback. Also, {{PatternProcessor.nextFileTime}} is copied to {{prevFileTime}}
and re-initialized to the current time. So, now {{prevFileTime=10:00}} and
{{nextFileTime=10:05}}.
* For the second rollback, the directory is scanned again. This completes at
10:10.
* The archive file is created based on {{PatternProcessor.prevFileTime}}, which
is 10:00. {color:red}Rollover creates archive <...>1000.1.log.zip *_(And we
just went back in time...)_*{color}
* The next log event is processed. Event time is 10:00:02, triggering another
rollback. Also, {{PatternProcessor.nextFileTime}} is copied to {{prevFileTime}}
and re-initialized to the current time. So, now {{prevFileTime=10:05}} and
{{nextFileTime=10:10}}.
* For the third rollback, the directory is scanned again. This completes at
10:15.
* The archive file is created based on {{PatternProcessor.prevFileTime}}, which
is 10:05. {color:red}Rollover overwrites archive <...>1005.1.log.zip
_(Overwriting an existing archive file... but that is problem #2, see
below.)_{color}
* The next log event is processed. Event time is 10:00:03, triggering another
rollback. Also, {{PatternProcessor.nextFileTime}} is copied to {{prevFileTime}}
and re-initialized to the current time. So, now {{prevFileTime=10:10}} and
{{nextFileTime=10:15}}.
* For the third rollback, the directory is scanned again. This completes at
10:20.
* The archive file is created based on {{PatternProcessor.prevFileTime}}, which
is 10:10. {color:blue}Rollover creates archive <...>1010.1.log.zip. From here
on rollover should work correctly.{color}
In my opinion, the {{PatternProcessor.prevFileTime}} should be initialized to
the log file's last modified time at startup.
That would prevent the "going back in time" phenomenon we're seeing above.
*2. Rollover overwrites existing archives*
If an archive {{<datetime>-1.zip}} already exists, I would expect it to be
renamed to {{<datetime>-2.zip}} before the new archive file is created. This is
not happening...
Ater much digging, I found the reason. The check for existing files is with a
different method than the method used to generate the new archive name...
In our config,
{{filePattern="logs/test/$$\{date:yyyyMMddHHmm}/TEST-%d\{yyyyMMddHHmm}-%i.log.zip"}}.
Now here is the fun bit: the directory pattern $$\{date:yyyyMMddHHmm} has two
dollar chars and is evaluated dynamically.
So if our scan starts at 10:10 and we work down from {{maxIndex}}, then by the
time we reach index 1, five minutes have passed and the logic checks if file
"logs/test/20140209{color:red}*1015*{color}/TEST-20140209{color:red}1010{color}-1.log.zip"
exists.
After the scan the log file is zipped to
"logs/test/20140209{color:red}*1010*{color}/TEST-20140209{color:red}1010{color}-1.log.zip".
This file _did_ exist but was not found during the scan.
The fix for this is that the directory scan *must* use the same pattern
evaluation logic as used to generate the rolled-over archive file name.
*3. Directory scan time linear with {{DefaultRolloverStrategy.maxIndex}}*
Ideally I'd like a faster implementation that does not call {{File.exists()}}
{{maxIndex}} times.
One alternative implementation would be to build a list of all files in all
subdirectories of the top-most directory in the file pattern, and do
string-matching on that list.
This is possible, but not trivial either. I may take a stab at this later.
I'll work on solutions for the first two issues.
> Rolled log files overwritten by RollingFile appender with composite time and
> size based policies
> ------------------------------------------------------------------------------------------------
>
> Key: LOG4J2-531
> URL: https://issues.apache.org/jira/browse/LOG4J2-531
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0-beta9
> Environment: Ubuntu 12.04 and 13.04, java version "1.7.0_51"
> Reporter: Geoff Ballinger
>
> We have a system which generates high volume logs which are required to be
> preserved for audit purposes, and have been having problems with files being
> unexpectedly overwritten.
> We are using a RollingFile appender with day granularity, time based and size
> based triggering policies, and a rollover strategy with a suitably large max
> value.
> I have created a simple test case with minute granularity to quickly
> illustrate the problem, which is v. similar to the example given in the
> documentation:
> {noformat}
> import org.apache.logging.log4j.LogManager;
> import org.apache.logging.log4j.Logger;
> public class LogTest
> {
> private static final Logger logger = LogManager.getLogger("TestLogger");
> public static void main(String[] args) throws Exception
> {
> for (long i=0; ; i+=1) {
> logger.debug("Sequence: " + i);
> Thread.sleep(250);
> }
> }
> }
> {noformat}
> ... with a config of:
> {noformat}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration>
> <Appenders>
> <RollingFile name="Test" fileName="logs/test.log"
> filePattern="logs/test/$${date:yyyyMMddHHmm}/TEST-%d{yyyyMMddHHmm}-%i.log.gz">
> <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
> <Policies>
> <TimeBasedTriggeringPolicy />
> <SizeBasedTriggeringPolicy size="1 KB"/>
> </Policies>
> <DefaultRolloverStrategy max="999999"/>
> </RollingFile>
> </Appenders>
> <Loggers>
> <Root level="debug">
> <AppenderRef ref="Test"/>
> </Root>
> </Loggers>
> </Configuration>
> {noformat}
> If this is run as is many of the rollover logfiles have other files written
> over them and are lost, as can clearly be seen by the gaps in the remaining
> sequence numbers, and the order the sequence numbers appear in the resulting
> files.
> If the time based policy is removed from the config and it is re-run then all
> sequence numbers are correctly stored and in the expected order., Without the
> time based trigger some are carried over into the folder for the next period
> which is not ideal, though is what we are using at present to avoid data loss.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
