Logfiles content lost on rotation at midnight

[umike72]

Description

I'm running a 3rd party application inside Tomcat 9.0.102 that generates a number of logfiles that are supposed to be rotated at midnight. There are 8 appenders like the one shown below configured in the application.

The following is happening:

• Around 1AM the relevant logfiles are rotated. Not sure why the rotation is not occurring around midnight.
• The previous day's logfile contents are lost, replaced instead with logentries from the current day, with timestamps between midnight and 1AM.
• The current logfile contain entries from 1AM onwards.

Update based on observations from log4j debug (see excerpt below):

• The logfile is rotated once at midnight, as expected.
• Then it looks like two more rotations are occurring at 1AM, which would explain that after this rotation entries between mdnight and 1AM are present in the rotated log.

I've reconfigured one of the appenders to rotate on an hourly basis, and I'm seeing the same behavior only for the logfile that is supposed to contain entries between midnight and 1AM. Instead, it contains a couple of entries between 1AM and 1;10 AM. The log entries between midnight and 1AM are lost. The logfiles for the other hours of the day contain the correct entries, it's just the midnight file that is having issues.

TZ configured on the Windows servers is AEST (Sydney). Given this is a 3rd party app, I don't have access to the src code.

Configuration

Version: 2.19.0. I've replaced the log4j jar files with 2.24.3, same result.

Operating system: Windows Server 2016, 2022

JDK: JRE 8b281 (Win 2016) and JRE17.0.14 (Win 2022)

Log4j config for affected appender:

appender.rolling_logfile1.type = RollingFile
appender.rolling_logfile1.name = logfile1
appender.rolling_logfile1.fileName = E:\\logs\\app1.log
appender.rolling_logfile1.filePattern = E:\\logs\\\\app1.log%d{'.'yyyy-MM-dd}
appender.rolling_logfile1.append = true
appender.rolling_logfile1.layout.type = PatternLayout
appender.rolling_logfile1.layout.pattern = %d %p [%t] %C{1} - %m%n
appender.rolling_logfile1.policies.type = Policies
appender.rolling_logfile1.policies.cron.type = CronTriggeringPolicy
appender.rolling_logfile1.policies.cron.schedule = 0 0 0 ? * * *
appender.rolling_logfile1.strategy.type = DefaultRolloverStrategy
appender.rolling_logfile1.strategy.max = 4

Logs

Excerpts from log4j debug entries related to one of the logfiles showing issues. As you can see, there are 3 FileRenameActions occurring (... towards the end). Once at 2025-05-14T00:00:00.201+1000 and then two more at 2025-05-14T01:00:01.193+1000 and 2025-05-14T01:00:01.400+1000. Not sure why the last 2 are occurring...

DEBUG StatusLogger Starting RollingFileManager E:\logs\app1.log
DEBUG StatusLogger RollingFileAppender$Builder(fileName="E:\logs\app1.log", filePattern="E:\logs\app1.log.%d{'.'yyyy-MM-dd}", append="null", locking="null", Policies(CompositeTriggeringPolicy(policies=[CronTriggeringPolicy(schedule=0 0 0 ? * * *)])), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=2147483647, useMax=true)), advertise="null", advertiseUri="null", createOnDemand="null", filePermissions="null", fileOwner="null", fileGroup="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{dd MMM yyyy HH:mm:ss,SSS} %-5p [%t] [%c] %m%n), name="RE_LOGGER", Configuration(Scheduler), Filter=null, ={})
TRACE StatusLogger New file 'E:\logs\app1.log' created = false
DEBUG StatusLogger Returning file creation time for E:\logs\app1.log
DEBUG StatusLogger Starting RollingFileManager E:\logs\app1.log
DEBUG StatusLogger RollingFileManager executing synchronous FileRenameAction[E:\logs\app1.log to E:\logs\app1.log..2025-05-13, renameEmptyFiles=false]
TRACE StatusLogger Renamed file E:\logs\app1.log to E:\logs\app1.log..2025-05-13 with Files.move
DEBUG StatusLogger Now writing to E:\logs\app1.log at 2025-05-14T00:00:00.201+1000
DEBUG StatusLogger RollingFileManager executing synchronous FileRenameAction[E:\logs\app1.log to E:\logs\app1.log..2025-05-13, renameEmptyFiles=false]
TRACE StatusLogger Renamed file E:\logs\app1.log to E:\logs\app1.log..2025-05-13 with Files.move
DEBUG StatusLogger Now writing to E:\logs\app1.log at 2025-05-14T01:00:01.193+1000
DEBUG StatusLogger RollingFileManager executing synchronous FileRenameAction[E:\logs\app1.log to E:\logs\app1.log..2025-05-13, renameEmptyFiles=false]
DEBUG StatusLogger Now writing to E:\logs\app1.log at 2025-05-14T01:00:01.400+1000

Reproduction

N/A, no access to source code.