[
https://issues.apache.org/jira/browse/LOG4J2-535?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma updated LOG4J2-535:
-------------------------------
Description:
Follow-up for issue LOG4J2-531: the main issue (rolled over archives were
overwritten) was resolved but the solution brought to light another issue that
is tracked here:
The distribution of the log files into the folders is odd and it feels like
there might be a flaw in the timestamp logic in there somewhere still.
Test program to reproduce the issue:
{code}
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);
}
}
}
{code}
Sample configuration for LOG4J2-531:
{code}
<?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>
{code}
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.
----
This happens with longer rollover periods as well:
----
Sample configuration based on that for LOG4J2-531, adjusted to roll every hour
and every 64kb (i.e. expect similar number of files per folder):
{code:xml}
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Appenders>
<RollingFile name="Test" fileName="logs/test.log"
filePattern="logs/test/$${date:yyyyMMddHH}/TEST-%d{yyyyMMddHH}-%i.log.gz">
<PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="64 KB"/>
</Policies>
<DefaultRolloverStrategy max="99"/>
</RollingFile>
</Appenders>
<Loggers>
<Root level="debug">
<AppenderRef ref="Test"/>
</Root>
</Loggers>
</Configuration>
{code}
Running this overnight gave a similar pattern, e.g. the folder for
{{2014021100}} contains one file with timestamps {{00:59:42,836}} to
{{00:59:59,851}}, and then 15 others covering timestamps {{01:00:00,101}} to
{{01:59:24,196}}. Only the last file's worth for each hour (the one rotated
based on time) is in the correct folder, and the rest (rotated based on size)
are in the previous hour's folder.
was:
Follow-up for issue LOG4J2-531: the main issue (rolled over archives were
overwritten) was resolved but the solution brought to light another issue that
is tracked here.
Sample configuration based on that for LOG4J2-531, adjusted to roll every hour
and every 64kb (i.e. expect similar number of files per folder):
{code:xml}
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Appenders>
<RollingFile name="Test" fileName="logs/test.log"
filePattern="logs/test/$${date:yyyyMMddHH}/TEST-%d{yyyyMMddHH}-%i.log.gz">
<PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="64 KB"/>
</Policies>
<DefaultRolloverStrategy max="99"/>
</RollingFile>
</Appenders>
<Loggers>
<Root level="debug">
<AppenderRef ref="Test"/>
</Root>
</Loggers>
</Configuration>
{code}
Running this overnight gave a similar pattern, e.g. the folder for
{{2014021100}} contains one file with timestamps {{00:59:42,836}} to
{{00:59:59,851}}, and then 15 others covering timestamps {{01:00:00,101}} to
{{01:59:24,196}}. Only the last file's worth for each hour (the one rotated
based on time) is in the correct folder, and the rest (rotated based on size)
are in the previous hour's folder.
> Rolled log files end up in the wrong directory
> ----------------------------------------------
>
> Key: LOG4J2-535
> URL: https://issues.apache.org/jira/browse/LOG4J2-535
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0-rc1
> Environment: Ubuntu 12.04 and 13.04, java version "1.7.0_51"
> Reporter: Remko Popma
>
> Follow-up for issue LOG4J2-531: the main issue (rolled over archives were
> overwritten) was resolved but the solution brought to light another issue
> that is tracked here:
> The distribution of the log files into the folders is odd and it feels like
> there might be a flaw in the timestamp logic in there somewhere still.
> Test program to reproduce the issue:
> {code}
> 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);
> }
> }
> }
> {code}
> Sample configuration for LOG4J2-531:
> {code}
> <?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>
> {code}
> 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.
> ----
> This happens with longer rollover periods as well:
> ----
> Sample configuration based on that for LOG4J2-531, adjusted to roll every
> hour and every 64kb (i.e. expect similar number of files per folder):
> {code:xml}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration>
> <Appenders>
> <RollingFile name="Test" fileName="logs/test.log"
> filePattern="logs/test/$${date:yyyyMMddHH}/TEST-%d{yyyyMMddHH}-%i.log.gz">
> <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
> <Policies>
> <TimeBasedTriggeringPolicy />
> <SizeBasedTriggeringPolicy size="64 KB"/>
> </Policies>
> <DefaultRolloverStrategy max="99"/>
> </RollingFile>
> </Appenders>
> <Loggers>
> <Root level="debug">
> <AppenderRef ref="Test"/>
> </Root>
> </Loggers>
> </Configuration>
> {code}
> Running this overnight gave a similar pattern, e.g. the folder for
> {{2014021100}} contains one file with timestamps {{00:59:42,836}} to
> {{00:59:59,851}}, and then 15 others covering timestamps {{01:00:00,101}} to
> {{01:59:24,196}}. Only the last file's worth for each hour (the one rotated
> based on time) is in the correct folder, and the rest (rotated based on size)
> are in the previous hour's folder.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
