[jira] [Commented] (LOG4J2-2804) RollingRandomAccessFile uses wrong time for filename

["Ian Underhill (Jira)" <ji...@apache.org>]

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

Ian Underhill commented on LOG4J2-2804:
---------------------------------------

Ive noticed this in the 2.13.0 release (no idea when it started). 

A sized based triggering policy will update the time to the next time period. so for example if your time period is a day, your log file jumps ahead a whole day, just when it rolls over due to a size trigger (and then can go back to the original day afterwards)

an example of a very first size based rollover timedate issue
{code:java}
Sep 23 11:28 unittests.2020-09-24-112759-1.log
 {code}

based on a config 
{code}
        <RollingFile name="LOG_FILE"
                     immediateFlush="true"
                     fileName="../logs/unittests.log"
                     filePattern="../logs/unittests.%d{yyyy-MM-dd-HHmmss}-%i.log">
            <PatternLayout pattern="%d %-5p %X{ThreadGroup} %-9t %c{1} - %m%n"/>
            <Policies>
                <OnStartupTriggeringPolicy/>
                <TimeBasedTriggeringPolicy interval="20" modulate="true"/>
                <SizeBasedTriggeringPolicy size="2KB"/>
            </Policies>
            <DefaultRolloverStrategy fileIndex="noMax"/>
        </RollingFile>
{code}


Looking at the sizeBasedTriggingPolicy, it calls update time 
{code:java}
    @Override
    public boolean isTriggeringEvent(final LogEvent event) {
        final boolean triggered = manager.getFileSize() > maxFileSize;
        if (triggered) {
            manager.getPatternProcessor().updateTime();
        }
        return triggered;
    } {code}

and the PatternProcessor just
{code:java}
    public void updateTime() {
    	if (nextFileTime != 0 || !isTimeBased) {
			prevFileTime = nextFileTime;
		}
    }
{code}

This code just doesn't read correctly to me at all (given the nextFileTime could be next day, next year etc).

Also the following code in Pattern processor looks odd to me, updating the previous time based on a getNextTime call :S this can have the effect of changing the previousFile time to be next year etc.

{code}
public long getNextTime(final long currentMillis, final int increment, final boolean modulus) {
    //
    // https://issues.apache.org/jira/browse/LOG4J2-1232
    // Call setMinimalDaysInFirstWeek(7);
    //
    prevFileTime = nextFileTime;
{code}

Stealing those two classes and removing both the call to updateTime and the preFileTime assignment.  Gets it working how I would expect it to work, in my debugger.

could somebody who is familiar with this code base, (and any unit tests that may exist) look at this


> RollingRandomAccessFile uses wrong time for filename
> ----------------------------------------------------
>
>                 Key: LOG4J2-2804
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2804
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 2.13.1
>            Reporter: André Pinto
>            Priority: Major
>
> When there are both size based and time based triggering policies, if the size based policy is triggered, the file is named as if the time based policy was triggered.
> Example config:
> {code:java}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="WARN" name="Mux">
>     <Properties>
>         <Property name="LOG_DIR">logs</Property>
>     </Properties>
>     <Appenders>
>         <Console name="Console" target="SYSTEM_OUT"/>
>         <RollingRandomAccessFile name="main" fileName="${LOG_DIR}/main-current.log-active"
>                                  filePattern="${LOG_DIR}/main-%d{yyyy-MM-dd-HH.mm.ss}.log"
>                                  ignoreExceptions="false" immediateFlush="false"
>                                  bufferSize="1048576">
>             <PatternLayout>
>                 <Pattern>%m\n</Pattern>
>             </PatternLayout>
>             <Policies>
>                 <SizeBasedTriggeringPolicy size="256 B" />
>                 <TimeBasedTriggeringPolicy interval="3600" />
>             </Policies>
>             <DefaultRolloverStrategy fileIndex="nomax" />
>         </RollingRandomAccessFile>
>     </Appenders>
>     <Loggers>
>         <Root level="OFF">
>             <AppenderRef ref="Console" />
>         </Root>
>         <Logger name="main" level="ALL" additivity="false">
>             <AppenderRef ref="main"/>
>         </Logger>
>     </Loggers>
> </Configuration>
> {code}
> With this configuration if I start writing log entries to the "main" logger at 2020-03-09 13:00.00 and immediately trigger the SizeBasedTriggeringPolicy (256 bytes), the name of the file that is rolled over will be:
> main-2020-03-09-14.00.00
> as if the rollover operation had been triggered by the time policy.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)