Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1131

RollingFileAppender rewrites previous day log, when second instance of application starts near the midnight

    XMLWordPrintable

Details

    Description

      Hello Logback team,

      We have an issue with logback:
      We start our application with cron few times a day, and we have missed logs due to following problem:
      We usually check whether application already started in the begin of launch and log an error (it might mean, that something goes wrong or something took more time, that it should) if it's already started.
      When this situation happens with end of day launching and second instance try to start at 00:05 for example, we have only log with this error for previous day.

      How to reproduce:

      package logback.test.concurrent;
 
import java.io.File;
import java.io.IOException;
 
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
 
public class Test {
 
    private static Logger logger = LoggerFactory.getLogger(Test.class);
 
    public static void main(String[] args) {
 
        File check = new File("./lock");
        if (!check.exists()) {
            try {
                check.createNewFile();
            } catch (IOException e) {
                logger.error("Failed to create file: {}", e);
            }
        } else {
            logger.error("Faile already exists");
            System.exit(1);
        }
 
        while (true) {
            logger.warn("event");
            try {
                Thread.sleep(10000);
            } catch (InterruptedException e) {
                logger.error("Interrupted exception occured: {}", e);
            }
        }
    }
 
}

      Logback configuration:

      <?xml version="1.0" encoding="UTF-8"?>
<included>
 
   <property name="root.log.filename" value="test.log" />
 
   <property name="common.log.file.date.pattern" value="yyyy-MM-dd" />
 
   <property name="common.log.conversionpattern" value="[%d{'yyyy-MM-dd HH:mm:ss,SSS'}] [test] [%X{username}] [%t] [%c{0}][%marker] [%p] - %m%n" />
 
 
   <appender name="LOGFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>/PATH/TO/LOGS/${root.log.filename}</file>
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        
         <fileNamePattern>/PATH/TO/LOGS/${root.log.filename}.%d{${common.log.file.date.pattern}}</fileNamePattern>
      </rollingPolicy>
      <encoder>
         <pattern>${common.log.conversionpattern}</pattern>
      </encoder>
   </appender>
    
   <root level="INFO">
      <appender-ref ref="LOGFILE" />
   </root>
    
 
</included>

      To reproduce you have to run the first instance before midnight (I tried at 23:59).
      Run second instance at midnight (before event appeared in log from first instance).
      Wait a bit, while first instance write new event.

      Now you can stop it and you will have two files:
      test.log:

      [2016-02-13 00:00:03,069] [test] [] [main] [Test][] [WARN] - event

      test.log.2016-02-12:

      [2016-02-13 00:00:02,280] [test] [] [main] [Test][] [ERROR] - Faile already exists

      What happens, as I understand:
      The first instance writes log normally until midnight.
      When the second instance started it renames log file to previous day and creates new one; writes event.
      When next event produced by the first instance, it renames log file to previous day (and rewrites existed, created by the second instance) and creates new log file.
      The first instance continues to write into new log file.

      I've reproduce it on 1.0.13, 1.1.3 and 1.1.4

      Thanks,
      Illia Dubinin

      Attachments

        Activity

          People

            logback-dev Logback dev list
            idubinin Illia Dubinin
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated: