RollingPolicy MaxHistory not deleting old files

[AlexandrSalin]

seems like it already fixed in
https://jira.qos.ch/browse/LOGBACK-162

but doesn't work for android

my config

      LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
      loggerContext.reset();

      RollingFileAppender<ILoggingEvent> rollingFileAppender = new RollingFileAppender<>();
      rollingFileAppender.setContext(loggerContext);
      rollingFileAppender.setAppend(true);
      rollingFileAppender.setFile(logDirectory + File.separator + logFileName + ".log");

      SizeAndTimeBasedFNATP<ILoggingEvent> fileNamingPolicy = new SizeAndTimeBasedFNATP<>();
      fileNamingPolicy.setContext(loggerContext);
      fileNamingPolicy.setMaxFileSize(fileSizeKB + "KB");

      TimeBasedRollingPolicy<ILoggingEvent> rollingPolicy = new TimeBasedRollingPolicy<>();
      rollingPolicy.setContext(loggerContext);
      rollingPolicy.setFileNamePattern(logDirectory + File.separator + logFileName + ".%d{yyyy-MM-dd}.%i.log");
      rollingPolicy.setMaxHistory(historyLength);
      rollingPolicy.setTimeBasedFileNamingAndTriggeringPolicy(fileNamingPolicy);
      rollingPolicy.setParent(rollingFileAppender);  // parent and context required!
      rollingPolicy.start();

      PatternLayoutEncoder encoder = new PatternLayoutEncoder();
      encoder.setContext(loggerContext);
      encoder.setCharset(Charset.forName("UTF-8"));
      encoder.setPattern("%date %level [%thread] %msg%n");
      encoder.start();

      rollingFileAppender.setRollingPolicy(rollingPolicy);
      rollingFileAppender.setEncoder(encoder);
      rollingFileAppender.start();

      // add the newly created appenders to the root logger;
      // qualify Logger to disambiguate from org.slf4j.Logger
      ch.qos.logback.classic.Logger root = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
      root.setLevel(level);
      root.addAppender(rollingFileAppender);

[FilenkovMaxim]

I have the same issue with simple config

<appender name="FILEFULL" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/dubsapp.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/dubsapp.%d{yyyy-MM-dd}.log</fileNamePattern>
            <!-- keep 7 days' worth of history -->
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <Pattern>%d{dd HH:mm:ss.SSSS}\t [%4.4thread]\t %1.-1level\t %11logger{0}\t %m%n</Pattern>
        </encoder>
    </appender>

[tony19]

I can reproduce the issue with the programmatic config, but not with the XML config.

[FilenkovMaxim]

@tony19 in which moment logback performs deleting? Can you give me the name of this method?
Do I need to call something besides LoggerFactory.getLogger() in my code?

[tony19]

The files are automatically deleted at startup (if configured with cleanHistoryOnStart) and on each log event (e.g., when logger.info(...) is called). For TimeBasedRollingPolicy, the rollover occurs in TimeBasedRollingPolicy#rollover():

logback-android/logback-android/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java

Line 182 in 45c2dba

cleanUpFuture = archiveRemover.cleanAsynchronously(now);

[AlexandrSalin]

@tony19 , do you have any thoughts how we can fix the issue with programmatic config? the logic which setup logback placed in another module and used by several apps. i guess i can't just change it to xml

[FilenkovMaxim]

assets-.zip
@tony19 I've attached my full config. Can you take a look on it?

[FilenkovMaxim]

@tony19 I've created a small example illustrated the problem. Check it, please.

As you can see on a screenshot maxHistory parameter is 2, but there are 5 log files in the logs directory.

[FilenkovMaxim]

@tony19 Hello! Have you any news on it?

[tony19]

@FilenkovMaxim I was able to reproduce the problem with logs not being deleted when the timestamp is using a daily rollover (yyyyMMdd). I will take a closer look.

[FilenkovMaxim]

@tony19 I don't think that is related problems. I checked RollingPolicy in this example without run resetLogs() method.
You can easy reproduce it following these steps:
run app, kill app, set system date next day
repeat this five times
check app folder /data/data/com.example.maxf.logbackexample/files/logs

[tony19]

The daily rollover pattern is indeed related, as it's one way I can reproduce the problem of missed deletions. The rollover seems to work fine when using a second-based rollover pattern (yyyyMMddss) (a contrived but effective pattern for test purposes).

I have a simpler method of reproducing the issue. Add <cleanHistoryOnStart> to TimeBasedRollingPolicy XML config, create multiple files matching the filename pattern, and restart the app. At startup, the extra files should be deleted.

[FilenkovMaxim]

@tony19 I meant #191 is not related to this issue

[tony19]

Here's what's happening:

When a filename pattern contains two date patterns like this:

<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
  <fileNamePattern>${LOG_DIR}/app.%d{yyyyMMdd}_%d{HHmmss,UTC}.log</fileNamePattern>

...the second date pattern (%d{HHmmss,UTC}) prevents TimeBasedArchiveRemover from finding expired files to delete. For instance, TimeBasedArchiveRemover#getFilesInPeriod() tries to find the following files (note the 060000 part):

/data/data/com.example.maxf.logbackexample/files/logs/app.20181110_060000.log
...
/data/data/com.example.maxf.logbackexample/files/logs/app.20181102_060000.log
/data/data/com.example.maxf.logbackexample/files/logs/app.20181101_060000.log
/data/data/com.example.maxf.logbackexample/files/logs/app.20181031_050000.log
...
/data/data/com.example.maxf.logbackexample/files/logs/app.20181022_050000.log
/data/data/com.example.maxf.logbackexample/files/logs/app.20181021_050000.log
/data/data/com.example.maxf.logbackexample/files/logs/app.20181020_050000.log
...
/data/data/com.example.maxf.logbackexample/files/logs/app.20181012_050000.log
/data/data/com.example.maxf.logbackexample/files/logs/app.20181011_050000.log
/data/data/com.example.maxf.logbackexample/files/logs/app.20181010_050000.log

...but the log files are actually named with nonzero times for the second timestamp like this:

/data/data/com.example.maxf.logbackexample/files/logs/app.20181012_054601.log

[FilenkovMaxim]

@tony19 Thanks for finding the source of the issue, do you think you can fix it in the next few days?

[tony19]

Fixed in v_1.3.0-3

[tony19]

@AlexandrSalin I've verified the fix with your config in my test app. Note that the solution implemented for LOGBACK-162 did not actually fix the problem in full, and had critical holes that would allow archive removals to be missed. I've refactored it in logback-android.

[tony19]

@FilenkovMaxim Note your filename pattern contains multiple date specifiers, which prevents logback from finding the correct files to remove:

 ${LOG_DIR}/app.%d{yyyyMMdd}_%d{HHmmss,UTC}.log
                ^^^^^^^^^^^^ ^^^^^^^^^^^^^^

Only one date specifier can be the "primary" one. The auxiliary ones must be marked with aux (see docs):

 ${LOG_DIR}/app.%d{yyyyMMdd,aux}_%d{HHmmss,UTC}.log

[FilenkovMaxim]

@tony19 thank you for explanation, I've changed my config already.
P.S. I got the message Failed to resolve: com.github.tony19:logback-android:1.3.0-3
Seems too early try to download?

[tony19]

I'm working on the release right now. You can download it manually in the meantime for local testing.

I also forgot to mention that when using multiple date specifiers, they all should have the same timezone. logback would still work, but it could be confusing for users to see two different timestamps in the filename. It should look like this:

${LOG_DIR}/app.%d{yyyyMMdd,UTC,aux}_%d{HHmmss,UTC}.log

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.