[
https://issues.apache.org/jira/browse/LOG4J2-531?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13895846#comment-13895846
]
Remko Popma commented on LOG4J2-531:
------------------------------------
Update: on my home laptop a rollover takes 5 minutes: that is how long it takes
to call {{File.exists()}} 1 million times (and that machine has a fairly fast
SSD drive).
However, this does not explain the loss of the initial zip file. That seems to
be caused by a bug in the archive renaming logic. Here is what I've found so
far.
{code}
2014-02-09 14:42:29,365 DEBUG (main) [log4j2_531.LogTest] - Sequence: 0
2014-02-09 14:42:29,617 DEBUG (main) [log4j2_531.LogTest] - Sequence: 1
2014-02-09 14:42:29,868 DEBUG (main) [log4j2_531.LogTest] - Sequence: 2
2014-02-09 14:42:30,119 DEBUG (main) [log4j2_531.LogTest] - Sequence: 3
2014-02-09 14:42:30,370 DEBUG (main) [log4j2_531.LogTest] - Sequence: 4
2014-02-09 14:42:30,620 DEBUG (main) [log4j2_531.LogTest] - Sequence: 5
2014-02-09 14:42:30,871 DEBUG (main) [log4j2_531.LogTest] - Sequence: 6
2014-02-09 14:42:31,122 DEBUG (main) [log4j2_531.LogTest] - Sequence: 7
2014-02-09 14:42:31,372 DEBUG (main) [log4j2_531.LogTest] - Sequence: 8
2014-02-09 14:42:31,623 DEBUG (main) [log4j2_531.LogTest] - Sequence: 9
2014-02-09 14:42:31,874 DEBUG (main) [log4j2_531.LogTest] - Sequence: 10
2014-02-09 14:42:32,125 DEBUG (main) [log4j2_531.LogTest] - Sequence: 11
2014-02-09 14:42:32,376 DEBUG (main) [log4j2_531.LogTest] - Sequence: 12
2014-02-09 14:42:32,627 DEBUG (main) [log4j2_531.LogTest] - Sequence: 13
2014-02-09 14:47:24,372 TRACE DefaultRolloverStrategy.purge() took
291.484612529 seconds
2014-02-09 14:42:32,879 DEBUG (main) [log4j2_531.LogTest] - Sequence: 14
2014-02-09 14:52:16,386 TRACE DefaultRolloverStrategy.purge() took
291.746054955 seconds
2014-02-09 14:47:24,630 DEBUG (main) [log4j2_531.LogTest] - Sequence: 15
2014-02-09 14:57:09,710 TRACE DefaultRolloverStrategy.purge() took 293.05872818
seconds
2014-02-09 14:52:16,642 DEBUG (main) [log4j2_531.LogTest] - Sequence: 16
2014-02-09 15:02:03,915 TRACE DefaultRolloverStrategy.purge() took
293.942685691 seconds
2014-02-09 14:57:09,964 DEBUG (main) [log4j2_531.LogTest] - Sequence: 17
2014-02-09 15:06:58,657 TRACE DefaultRolloverStrategy.purge() took
294.479377825 seconds
2014-02-09 15:02:04,170 DEBUG (main) [log4j2_531.LogTest] - Sequence: 18
2014-02-09 15:11:55,732 TRACE DefaultRolloverStrategy.purge() took
296.808908234 seconds
2014-02-09 15:06:58,914 DEBUG (main) [log4j2_531.LogTest] - Sequence: 19
{code}
# 14:47 rollover creates {{TEST-201402091447-1.log.zip}} - contains 14 lines
with Sequence 0-13
# 14:52 rollover creates {{TEST-201402091442-1.log.zip}} - contains 1 line with
Sequence 14
# 14:57 rollover *overwrites* {{TEST-201402091447-1.log.zip}} - contains 1 line
with Sequence 15
# 15:02 rollover creates {{TEST-201402091452-1.log.zip}} - contains 1 line with
Sequence 16
# 15:07 rollover creates {{TEST-201402091457-1.log.zip}} - contains 1 line with
Sequence 17
# 15:11 rollover creates {{TEST-201402091502-1.log.zip}} - contains 1 line with
Sequence 18
_(to be continued)_
> 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]
