[
https://issues.apache.org/jira/browse/LOG4J2-531?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13896639#comment-13896639
]
Geoff Ballinger edited comment on LOG4J2-531 at 2/10/14 3:11 PM:
-----------------------------------------------------------------
I can confirm that using your staged artefacts log files / lines are no longer
being lost which is the main thing!
The distribution of the log files into the folders is a bit odd however and it
feels like there might be a flaw in the timestamp logic in there somewhere
still.
I kicked off the test run at {{14:29:11}} using my example setup from the first
post above more or less as is - but with a more sensible {{max=99}}.
The initial folder created was {{201402101429}} and contained 27 numbered files
prefixed {{TEST-201402101429-}}. Numbers 1-12 contained 16 log lines each with
timestamps {{14:29:11,667}} to {{14:29:59,649}}, number 13 a single log line
with timestamp {{14:29:59,899}}, and numbers 14-27 again contain 16 lines each
with timestamps {{14:30:00,164}} to {{14:30:56,155}}.
The second folder created was {{201402101430}} and contained 15 numbered files.
The first file contained 15 log lines with timestamps {{14:30:56,405}} to
{{14:30:59,919}}. The subsequent files contained 16 log lines each with
timestamps {{14:31:00,170}} to {{14:31:56,123}}.
The third folder created was {{201402101431}}. The first file contained 15 log
lines with timestamps {{14:31:56,373}} to {{14:31:59,886}}. The subsequent
files contained 16 log lines each with timestamps from {{14:32:00,136}} onwards.
So in summary after the first minute the majority of log lines from minute X
end up in the folder for minute X-1. The exception are the last file of lines
which end up in the correct folder.
Geoff.
was (Author: geoffballinger):
I can confirm that using your staged artefacts log files / lines are no longer
being lost which is the main thing!
The distribution of the log files into the folders is a bit odd however and it
feels like there might be a flaw in the timestamp logic in there somewhere
still.
I kicked off the test run at {{14:14:09}} using my example setup from the first
post above more or less as is - but with a more sensible {{max=99}}.
The initial folder created was {{201402101429}} and contained 27 numbered files
prefixed {{TEST-201402101429-}}. Numbers 1-12 contained 16 log lines each with
timestamps {{14:29:11,667}} to {{14:29:59,649}}, number 13 a single log line
with timestamp {{14:29:59,899}}, and numbers 14-27 again contain 16 lines each
with timestamps {{14:30:00,164}} to {{14:30:56,155}}.
The second folder created was {{201402101430}} and contained 15 numbered files.
The first file contained 15 log lines with timestamps {{14:30:56,405}} to
{{14:30:59,919}}. The subsequent files contained 16 log lines each with
timestamps {{14:31:00,170}} to {{14:31:56,123}}.
The third folder created was {{201402101431}}. The first file contained 15 log
lines with timestamps {{14:31:56,373}} to {{14:31:59,886}}. The subsequent
files contained 16 log lines each with timestamps from {{14:32:00,136}} onwards.
So in summary after the first minute the majority of log lines from minute X
end up in the folder for minute X-1. The exception are the last file of lines
which end up in the correct folder.
Geoff.
> 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
> Assignee: Remko Popma
> Fix For: 2.0-rc1
>
>
> 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: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
