logback SizeAndTimeBasedRollingPolicy not working and filling up the storage

[vgvsre]

Hi Team,

In our recent rollout, we had a bug in code, which started generating a very high volume of logs and we are expecting logback to remove old logs and keep the storage space in control.
However this was not the case, log files were not removed and storage was filling and bringing the entire appliance to a halt.

log back config:
maxHistory: 2
maxFileSize: 25MB
totalSizeCap: 75MB

Logs generated per sec: 25MB(1.5 GB per minute/ 1 million lines per minute)
Max file size: 25MB, so every second one log file is generated.
Max CAP size: 75MB
within 3 sec the MAX cap is met.
Storage available is 24 GB.
The time taken to fill up the storage is 16Min(1.5 GB per minute generation rate)

I can see logs are successfully written into files but old files are not deleted.

The expectation here is that logback has to clean up old files every 3 seconds to keep up with config and maintain storage. I am not sure this functionality working.

and I need below info if some can help me:

1. Is maxFileSize, maxHistory, and totalSizeCap is checked for each log message event?
2. In the documentation it says the async process, Does it mean writing to log files and removal of old files are independent?
3. Is removing old files serialized?

Below are config we used
`

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>${CONSOLE_PATTERN}</pattern>
    </encoder>
</appender>
<appender name="ASYNC_STDOUT" class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>0</discardingThreshold>
    <queueSize>10000</queueSize>
    <appender-ref ref="STDOUT"/>
    <includeCallerData>true</includeCallerData>
</appender>

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/spring.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <FileNamePattern>${LOG_DIR}/spring-%d{yyyyMMdd}.%i.log</FileNamePattern>
        <maxHistory>2</maxHistory>
        <maxFileSize>25MB</maxFileSize>
        <totalSizeCap>75MB</totalSizeCap>
    </rollingPolicy>
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>${FILE_PATTERN}</pattern>
    </encoder>
</appender>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>0</discardingThreshold>
    <queueSize>10000</queueSize>
    <appender-ref ref="FILE"/>
    <includeCallerData>true</includeCallerData>
</appender>

<logger name="org.springframework.scheduling.support.TaskUtils" level="OFF"/>
<logger name="io.jaegertracing.internal" level="OFF"/>
<logger name="org.apache.ignite.internal" level="OFF"/>
<logger name="org.springframework.web.client" level="OFF"/>

<root level="${SERVICE_LOG_LEVEL}">
    <appender-ref ref="ASYNC_STDOUT"/>
    <appender-ref ref="ASYNC_FILE"/>
</root>

`

[ceki]

Hi @vgvsre,

I am puzzled by your set up. If log files have a life expectancy of few seconds, then why have them in the first place? Maybe you are testing the limits of the system?

Anyway, logback will check for file size every 10 seconds and not for every event. I happen to think that even every 10 seconds is too frequent.

Renaming operations are synchronous whereas compression is performed asynchronously.

[vgvsre]

@ceki We are using centralized logback config files for all our containers. All the logs are instantly shipped to the cloud and written to the log file.

Our containers regularly generate logs varying from 1MB to 20GB daily.

This was a special case because a bug in a container that regularly produces 100MB logs started generating 1.5GB per minute.

Hi @vgvsre,

I am puzzled by your set up. If log files have a life expectancy of few seconds, then why have them in the first place? Maybe you are testing the limits of the system?

Anyway, logback will check for file size every 10 seconds and not for every event. I happen to think that even every 10 seconds is too frequent.

Renaming operations are synchronous whereas compression is performed asynchronously.

[ceki]

@vgvsre You can set a shorter checkIncrement property in SizeAndTimeBasedRollingPolicy in units of milliseconds. Note that in version 1.3.12/1.4.12 the checkIncrement can be specified as a Duration type. In earlier versions, only integers representing milliseconds were allowed.

[andrej-roki]

@ceki I have the same problem as @vgvsre. Creation of new archived logs .log.gz using maxFileSize is working, but deletion based on maxHistory and totalSizeCap is not working. We end up with full disk.
We used this tutorial for configuration: https://howtodoinjava.com/logback/rollingfileappender/

Do we have something that we are not configuring well?

[joca-bt]

I have a similar issue. maxHistory doesn't seem to be respected for RollingFileAppender with SizeAndTimeBasedRollingPolicy.

This is how I configure the appender and policy:

SizeAndTimeBasedRollingPolicy<ILoggingEvent> policy = new SizeAndTimeBasedRollingPolicy<>();
policy.setFileNamePattern("%s.%%d.%%i".formatted(file.toString()));
policy.setMaxFileSize(new FileSize(2 * KB_COEFFICIENT));
policy.setMaxHistory(2);
policy.setContext(context);

RollingFileAppender<ILoggingEvent> appender = new RollingFileAppender<>();
appender.setFile(file.toString());
appender.setRollingPolicy(policy);
appender.setEncoder(encoder);
appender.setContext(context);

Then I make lots of writes and the filesystem looks like:

log
log.2023-11-10.0
log.2023-11-10.1
log.2023-11-10.2
log.2023-11-10.3

I'd expect for the older logs (log.2023-11-10.0 and log.2023-11-10.1) to be deleted.

I was trying to debug. From what I understood, the cleaner only takes the datetime policy when cleaning up and ignores the size part. That's why I have more than 2 logs. It will only remove the logs for 2 days older. Is this the expected behavior?

[sealexer]

Hello @vgvsre,

Could you please clarify what logback version was used in your setup?
And in case it was 1.2.x, have you tried 1.3.x/1.4.x?

There are differences in SizeAndTimeBasedRollingPolicy-related codepaths (e.g. different InvocationGate implementations are used: 1.2.x vs 1.3.x).

[yuzhaojun]

hi @ceki , we have meet the same issue with version 1.4.14. the logback configuration below:

<appender name="TRACE_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${log.base}/${log.name}-trace.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>${log.base}/${log.name}-trace.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
        <maxHistory>30</maxHistory>
        <maxFileSize>30MB</maxFileSize>
        <totalSizeCap>5GB</totalSizeCap>
    </rollingPolicy>
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <charset>UTF-8</charset>
        <pattern>${PATTERN}</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>DEBUG</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
</appender>

we found the maxFileSize and totalSizeCap is not working. Our log have been as large as 200G in one single log file.

[nodejh]

Prior to version 1.5.8, the file rollover was managed by the checkIncrement property ( checkIncrement ), which had a default value of 1 minute. Starting with version 1.5.8, this property is no longer necessary, as Logback now tracks the number of bytes written to the file. Therefore, I suggest updating to the latest version of Logback.

[ceki]

I urge users to upgrade to version 1.5.9. As mentioned by @nodejh logback now tracks the number of bytes written to the file. The issue mentioned here should be solved.

[enicolaescu]

I am having the same issue even on 1.5.9 using the example configuration from the docs

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE configuration>

<configuration>
  <import class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"/>
  <import class="ch.qos.logback.core.rolling.RollingFileAppender"/>
  <import class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"/>

  <appender name="ROLLING" class="RollingFileAppender">
    <file>mylog.txt</file>
    <rollingPolicy class="SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>mylog-%d{yyyy-MM-dd}.%i.txt</fileNamePattern>
      <maxFileSize>100MB</maxFileSize>
      <maxHistory>60</maxHistory>
      <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <encoder class="PatternLayoutEncoder">
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="ROLLING"/>
  </root>
</configuration>

I set the maxFileSize to 1MB and 1KB and the logs keep getting written to the same 3MB file instead of rotating. I am on windows 10, can it be related?

I enabled debug logs for logback and the only reference to the size is in this line which mentions only archive files, not the current log file

INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1130894323 - Archive files will be limited to [1 MB] each.

[ceki]

@enicolaescu The message "Archive files will be limited to [1 MB] each." does not match the specification <maxFileSize>100MB</maxFileSize>. Is it possible that another configuration file is being read?

[enicolaescu]

@enicolaescu The message "Archive files will be limited to [1 MB] each." does not match the specification 100MB. Is it possible that another configuration file is being read?

I only posted the configuration for reference, in my instance I change the 100MB to 1KB and 1MB

[ceki]

If the file mylog.txt is opened by another application, then rollover cannot occur. I suggest to remove <file>mylog.txt</file> as recommended in the documentation.

[enicolaescu]

If the file mylog.txt is opened by another application, then rollover cannot occur. I suggest to remove mylog.txt as recommended in the documentation.

I am sure the file is not opened by any other process. I removed the line you suggested but a new file based on size is not created, it keeps writing to the same file even after its size goes over the configured max size

When I ran the application today for the first time it rolled over the old log file based on date though

[ceki]

@enicolaescu Does the version of logback-core.jar match that of logback-classic.jar? Is it 1.5.9 for both artifacts?

Can you provide your the config file?

[enicolaescu]

@enicolaescu Does the version of logback-core.jar match that of logback-classic.jar? Is it 1.5.9 for both artifacts?

Can you provide your the config file?

I finally understand what happened, logback doesn't check the actual size of the file, it only tracks the bytes written since the application started, which is why there is no rotation if my application logs a single line and the file exceeds the configured max size but it will rotate if my application logs maxFileSize bytes before terminating

[ceki]

@enicolaescu Not taking into account the initial file size is indeed a bug in logback-core. Can you please create a new issue describing the problem as you have done above?