logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ralph Goers (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-535) Rolled log files end up in the wrong directory
Date Fri, 06 Jun 2014 02:26:01 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-535?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14019509#comment-14019509
] 

Ralph Goers commented on LOG4J2-535:
------------------------------------

When a time based rollover occurs the time is supposed to be for the previous time unit (in
this case a second) since all the data would be for that time frame.  from what I can tell
this is working properly.

When a size based rollover occurs it just takes the current filename and increments the counter.
This causes a file to be created with a name containing the previous time unit and the counter
incremented.  This is really incorrect as the data is for the current time period.

> 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.2#6252)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message