[jira] [Assigned] (LOG4J2-535) Rolled log files end up in the wrong directory

["Ralph Goers (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/LOG4J2-535?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Ralph Goers reassigned LOG4J2-535:
----------------------------------

    Assignee: Ralph Goers

> 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
>            Assignee: Ralph Goers
>
> 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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org