Logback daily log rollover leads to main log file removed and .tmp file left behind

[kshitijlimaye]

We have developed a reactive web application using Spring boot 2.7.18 that uses logback 1.2.13 along with Slf4j for logging. The application runs on linux server and generates application and access logs with a log rollover policy set to SizeAndTimeBasedRollingPolicy as described later.

When the application is put under load of thousands of requests per second, we have observed few issues with logging

1. The log files being written into show partially written line at the end
2. The rollover fails to complete leaving .tmp files behind and we don't see the .gz archive file. This is observed intermittently.
3. During daily rollover at 00:00, main log file goes missing and never created back. The last updated file is still a .tmp file. This means the application cannot write to any log file anymore.

The logback-spring.xml is as follows

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" shutdownHook="disable">

    <property name="baseDir" value="${LOG_LOCATION:-/logs}"/>
    <appender name="DefaultFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${baseDir}/APPNAME.log</file>

        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${baseDir}/APPNAME-%d{yyyy-MM-dd}-%i.log.gz</fileNamePattern>
            <!-- size of file before it rolls over -->
            <maxFileSize>2GB</maxFileSize>
            <!-- how many days of history to keep -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>

        <encoder>
            <pattern>[%-5level] [%X{traceId:-}] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>[%-5level] [%X{traceId:-}] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="accessLog" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${baseDir}/access/APPNAME-access.log</file>
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${baseDir}/access/APPNAME-access-%d{yyyy-MM-dd}-%i.log.gz</fileNamePattern>
            <!-- size of file before it rolls over -->
            <maxFileSize>100MB</maxFileSize>
            <!-- how many days of history to keep -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>
    <appender name="async" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="accessLog"/>
    </appender>

    <springProfile name="dev">
        <root level="info">
            <appender-ref ref="DefaultFileAppender"/>
        </root>
        <logger name="com.some.package.here" level="debug"/>
        <logger name="org.springframework.security.web.server.DefaultServerRedirectStrategy" level="debug"/>
        <logger name="reactor.netty.http.server.AccessLog" level="info" additivity="false">
            <appender-ref ref="async"/>
        </logger>
    </springProfile>

    <springProfile name="test">
        <root level="error">
            <appender-ref ref="console"/>
        </root>
        <logger name="com.some.package.here" level="warn"/>
        <logger name="org.springframework" level="warn"/>
    </springProfile>

    <springProfile name="default">
        <root level="info">
            <appender-ref ref="DefaultFileAppender"/>
        </root>
        <logger name="com.some.package.here" level="info"/>
        <logger name="org.springframework.security.web.server.DefaultServerRedirectStrategy" level="debug"/>
        <logger name="reactor.netty.http.server.AccessLog" level="info" additivity="false">
            <appender-ref ref="async"/>
        </logger>
    </springProfile>
</configuration>

The log directory ends up in a state like this

-rw-r--r-- 1 appuser appuser    232756 Sep 11 00:00 appname-access-2024-09-10-0.log.gz
-rw-r--r-- 1 appuser appuser  23487927 Sep 11 14:57 appname-access-2024-09-11-0.log.gz
-rw-r--r-- 1 appuser appuser 104971022 Sep 11 14:59 appname-access-2024-09-11-1.log2010298141560280.tmp
-rw-r--r-- 1 appuser appuser   5890048 Sep 12 23:59 appname-access-2024-09-12-0.log43167099731506.tmp

Here we expected logback to create the new file "appname-access.log" for the application to write into.

Having read a bit more on logback documentation around SizeAndTimeBasedRollingPolicy and suggestion to avoid using it unless absolutely needed, we decided to try TimeBasedRollingPolicy instead. However, with this change we still end up with the same set of issues.

We would like to understand the root cause for these issues to determine the best possible solution.

[kshitijlimaye]

We found out that the gzip compression operation handled by logback was leading to the issues seen above, so we decided to disable it. Also, we decided to use AsyncAppender with higher buffer size to ensure none of the log events were dropped or partially written into the log file. The logback-spring.xml now looks like this

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" shutdownHook="disable">
    <!-- setting the log location property -->
    <property name="baseDir" value="${LOG_LOCATION:-/logs}"/>

    <!-- Configure the application log appender -->
    <appender name="AppLogAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${baseDir}/appname.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${baseDir}/appname-%d{yyyy-MM-dd}-%i.log</fileNamePattern>
            <!-- size of file before it rolls over -->
            <maxFileSize>2GB</maxFileSize>
            <!-- how many days of history to keep -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>[%-5level] [%X{traceId:-}] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- Configure the access log appender -->
    <appender name="AccessLogAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${baseDir}/access/appname-access.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${baseDir}/access/appname-access-%d{yyyy-MM-dd}-%i.log</fileNamePattern>
            <!-- size of file before it rolls over -->
            <maxFileSize>100MB</maxFileSize>
            <!-- how many days of history to keep -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <!-- Configure the AsyncAppender
         queueSize = sets the buffer size for queued log events
         discardingThreshold = when set to 0, no log event is discarded
         neverBlock = when set to true, never block calling thread when buffer is full -->
    <appender name="AccessLogAsync" class="ch.qos.logback.classic.AsyncAppender">
        <queueSize>100000</queueSize>
        <discardingThreshold>0</discardingThreshold>
        <neverBlock>true</neverBlock>
        <appender-ref ref="AccessLogAppender"/>
    </appender>

    <!-- Configure the AsyncAppender
         queueSize = sets the buffer size for queued log events
         discardingThreshold = when set to 0, no log event is discarded
         neverBlock = when set to true, never block calling thread when buffer is full -->
    <appender name="AppLogAsync" class="ch.qos.logback.classic.AsyncAppender">
        <queueSize>100000</queueSize>
        <discardingThreshold>0</discardingThreshold>
        <neverBlock>true</neverBlock>
        <appender-ref ref="AppLogAppender"/>
    </appender>

    <!-- Configure the console appender -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>[%-5level] [%X{traceId:-}] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- Configuration for dev profile -->
    <springProfile name="dev">
        <root level="info">
            <appender-ref ref="AppLogAsync"/>
        </root>
        <logger name="com.some.package.here" level="debug"/>
        <logger name="org.springframework.security.web.server.DefaultServerRedirectStrategy" level="debug"/>
        <logger name="reactor.netty.http.server.AccessLog" level="info" additivity="false">
            <appender-ref ref="AccessLogAsync"/>
        </logger>
    </springProfile>

    <!-- Configuration for test profile -->
    <springProfile name="test">
        <root level="error">
            <appender-ref ref="console"/>
        </root>
        <logger name="com.some.package.here" level="warn"/>
        <logger name="org.springframework" level="warn"/>
    </springProfile>

    <!-- Configuration for default/prod profile -->
    <springProfile name="default">
        <root level="info">
            <appender-ref ref="AppLogAsync"/>
        </root>
        <logger name="com.some.package.here" level="info"/>
        <logger name="org.springframework.security.web.server.DefaultServerRedirectStrategy" level="debug"/>
        <logger name="reactor.netty.http.server.AccessLog" level="info" additivity="false">
            <appender-ref ref="AccessLogAsync"/>
        </logger>
    </springProfile>
</configuration>

This change has helped us to have all log events written into log file without drop and the Size & Time based rollover is happening correctly.