TimeBasedRollingFileAppender deletes log file

[klausholstjacobsen]

I am using log4cplus 2.0.4 and TimeBasedRollingFileAppender with the following config:

---

log4cplus.appender.RollingInfoFile=log4cplus::TimeBasedRollingFileAppender
log4cplus.appender.RollingInfoFile.FilenamePattern=/log/%d{yyyyMMddHH}_info.log

log4cplus.appender.RollingInfoFile.UseLockFile=true
log4cplus.appender.RollingInfoFile.LockFile=/log/info.lock

log4cplus.appender.RollingInfoFile.MaxHistory=7
log4cplus.appender.RollingInfoFile.CleanHistoryOnStart=false
log4cplus.appender.RollingInfoFile.RollOnClose=false
log4cplus.appender.RollingInfoFile.CreateDirs=true
log4cplus.appender.RollingInfoFile.Append=true

log4cplus.appender.RollingInfoFile.layout=log4cplus::PatternLayout
log4cplus.appender.RollingInfoFile.layout.ConversionPattern=[%D{%Y/%m/%d %H:%M:%S.%q}][%-5p] [%X{process_name}][%T] [%b:%L] %m%n

---

As you can see from the file name pattern the file rolls every hour.
I have multiple processes logging with this config thus logging to the same file.

I have a process that logs something every second. Everything seems to run smoothly. The log file is rolled and logging continues in the new log file. No log statements are lost.

Then at some point another process logs something and the original logger stops logging every second.
Suddenly the current log file is deleted and a new identical one is create and logging continues in this file. The end result is that all log statements from when the file was originally created (last roll) until now are lost.

I do not know if this is related to multiple processes logging to the same file or related to the fact that the 1 sec log routine stops logging.

Help would be appreciated.

Rgds Klaus

[wilx]

Try to set either environment variable LOG4CPLUS_LOGLOG_DEBUGENABLED=true or configuration file property configDebug=true to see what is log4cplus doing. I am afraid I do not see any obvious issues with the code.

[klausholstjacobsen]

Thanks for the super quick response.

I will provide the debug logs asap.
In the mean time i've had a look at the source for TimeBasedRollingFileAppender.

It seem to check if it is time to roll over in the append function.
In a multi-process (not multithread) environment one process might have rolled the file and continued to log.
Then some time later another process want to log and also finds out it is time to roll. So it does this effectively wiping out the new log file that was created when the first process rolled the file.

I see no check in the rollover(...) function to check whether the log file was already rolled by another process.

Is this interpretation correct?

Rgds
Klaus

[klausholstjacobsen]

debug logs:

May  9 20:50:21 kvasir02 TaskControlService[25329]: log4cplus: Just opened file: ../log/2021050920_info.log
May  9 21:00:00 kvasir02 TaskControlService[25329]: log4cplus: Just opened file: ../log/2021050921_info.log
May  9 21:00:41 kvasir02 TaskControlService[25329]: log4cplus: Just opened file: ../log/2021050921_info.log

The above logs adds to my suspicion.
2021050921_info.log is opened twice.
After first open, logging continues in the new file.
After the second open, all logs from 21:00:00 to 21:00:41 in that file are gone.

Bonus info: TimeBasedRollingFileAppender never seems to take into account the "Append" property inherited from FileAppenderBase.

Rgds
Klaus