[logback-dev] [JIRA] Commented: (LBCORE-26) TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file.

[Pavel (JIRA)]

    [ http://jira.qos.ch/browse/LBCORE-26?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11089#action_11089 ] 

Pavel commented on LBCORE-26:
-----------------------------

I experience the described issue with latest 0.9.15 version.
Configuration file:
<?xml version="1.0" encoding="UTF-8" ?>
<configuration debug="true">

    <jmxConfigurator/>


    <!--Production-->

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>D:\My Projects\cgp\Script\src\de\cgp\script\test\${script.name}.%d{yyyy-MM-dd_HH-mm}.log.zip</FileNamePattern>
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>

        <param name="file" value="D:\My Projects\cgp\Script\src\de\cgp\script\test\${script.name}.log"/>

        <layout class="ch.qos.logback.classic.PatternLayout">
            <param name="Pattern" value="%d{ISO8601} %-5p [%t] %c{1}: %m%n"/>
        </layout>
    </appender>

    
    <root level="info">
        <appender-ref ref="FILE"/>
    </root>

</configuration>

Java Code:

public class TestRollOver {

    private static Logger logger = LoggerFactory.getLogger(TestRollOver.class);

    public TestRollOver() {
        //Load Context
        LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
        try {
            JoranConfigurator configurator = new JoranConfigurator();
            configurator.setContext(lc);
            //reset config
            lc.reset();
            //set property
            lc.putProperty("script.name", this.getClass().getSimpleName());
            //configure
            try {
                configurator.doConfigure(new FileInputStream(
                        "somepath\\logback.xml"));
            } catch (FileNotFoundException e) {
                System.err.println(e);
            }
        } catch (JoranException je) {
            System.err.println(je);
        }
        //Test
        logger.info("Test");
        //Second test message
        logger.info("Test");
    }

    public static void main(String[] args) {
        new TestRollOver();
    }
}

if we start the script once per 2-3 minutes - log is written in the same file - expected behavior - roll over every minute. But if in step by step debug we call the first info method, wait for 1 minute and then step to the second call - log file is rolled over as expected. conclusion  - roll over policy seems to be not preserved between application starts (configuration routines).


> TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file.
> ----------------------------------------------------------------------------------------
>
>                 Key: LBCORE-26
>                 URL: http://jira.qos.ch/browse/LBCORE-26
>             Project: logback-core
>          Issue Type: Bug
>          Components: Rolling
>    Affects Versions: unspecified
>         Environment: Operating System: All
> Platform: All
>            Reporter: Tsutomu YANO
>            Assignee: Logback dev list
>            Priority: Critical
>             Fix For: 0.9.12
>
>
> If you use TimeBasedRollingPolicy to rollover a log file and no log wasn't wrote into the log beyond the timing of rollover,  and if you restart your application, the log file doesn't roll, then new log will be appended into old log file.
> EVIDENCE:
> 1. in logback.xml, set your FileNamePattern like 'log.%d{yyyy-MM-dd_HH-mm}.log'.
> 2. Simply do a kind of thing, which will make some logs into your log file.
> 3. Wait for some minutes.
> 4. restart your application.
> 5. do a kind of thing, which will make some logs into your log file.
> the FileNamePattern is 'log.%d{yyyy-MM-dd_HH-mm}.log', so the log file will be roll every minutes. On case 5 of above example, the log file should be roll over, because some minutes already have passed after last logs wrote into the log file. But the file didn't be roll overed.
> THE CAUSE:
> In start() method of TimeBasedRollingPolicy, you initialize a variable 'lastCheck' to System.currentTimeStamp().  So if you restart your application, the last check time will be set to just NOW.
> you should initialize the variable to a last modified time of a current log file.
> See below source code. from '//modified by Tsutomu YANO' to '//until here'.
> SOURCE:  
> public void start() {
> 	// set the LR for our utility object
> 	util.setContext(this.context);
> 	compress.setContext(this.context);
> 	// find out period from the filename pattern
> 	if (fileNamePatternStr != null) {
> 		fileNamePattern = new FileNamePattern(fileNamePatternStr, this.context);
> 		determineCompressionMode();
> 	} else {
> 		addWarn(FNP_NOT_SET);
> 		addWarn(SEE_FNP_NOT_SET);
> 		throw new IllegalStateException(FNP_NOT_SET + SEE_FNP_NOT_SET);
> 	}
> 	DateTokenConverter dtc = fileNamePattern.getDateTokenConverter();
> 	if (dtc == null) {
> 		throw new IllegalStateException("FileNamePattern [" + fileNamePattern.getPattern() + "] does not contain a valid DateToken");
> 	}
> 	int len = fileNamePatternStr.length();
> 	switch (compressionMode) {
> 	case Compress.GZ:
> 		activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 3), this.context);
> 		break;
> 	case Compress.ZIP:
> 		activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 4), this.context);
> 		break;
> 	case Compress.NONE:
> 		activeFileNamePattern = fileNamePattern;
> 	}
> 	addInfo("Will use the pattern " + activeFileNamePattern + " for the active file");
> 	rc = new RollingCalendar();
> 	rc.init(dtc.getDatePattern());
> 	addInfo("The date pattern is '" + dtc.getDatePattern() + "' from file name pattern '" + fileNamePattern.getPattern() + "'.");
> 	rc.printPeriodicity(this);
> 	
> 	//modified by Tsutomu YANO
> 	//if a current log file exists, initialize a 'lastCheck' variable to the 
> 	//last modified date of the file.
> 	File currentFile = new File(getParentFileName());
> 	if(currentFile.exists() && currentFile.canRead()) {
> 		lastCheck.setTime(currentFile.lastModified());
> 	} else {
> 		// currentTime = System.currentTimeMillis();
> 		lastCheck.setTime(getCurrentTime());
> 	}
> 	//until here
> 	
> 	nextCheck = rc.getNextCheckMillis(lastCheck);
> 	// Date nc = new Date();
> 	// nc.setTime(nextCheck);
> }

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira