Search code examples
log4j2rollingfileappender

Why does Log4j OnStartupTriggeringPolicy check the file timestamp?


and/or "How does one safely handle context in a RollingFileAppender TriggeringPolicy?"

I am having problems with OnStartupTriggeringPolicy not fulfilling its stated purpose of

Triggers a rollover on every restart, but only if the file size is greater than zero.

on systems where the "real time clock" might read earlier on one startup than on the previous startup.

Tangent: Yes, clocks jumping backward is annoying. Yes, it creates other problems. Yes, steps have/are/will be taken to avoid it. No, it cannot be sufficiently avoided to tell all involved "Well, that's just too bad".

OnStartupTriggeringPolicy does not trigger a rollover on startup in this case because, at initialization, it checks the file timestamp against the start time of the JVM. I have written an alternative TriggeringPolicy that simply checks at initialization if the file size is greater than zero and this appears to serve the stated purpose.

So the nagging question is "What am I missing? Why does OnStartupTriggeringPolicy go to such great lengths, including evoking reflection to find the JVM start time, to answer a question that would seem to have a fixed answer?".

This SO answer pointed me at LoggerContext.reconfigure, which suggests one case wherein the RollingFileAppender and its Policy objects could be discarded and recreated. That suggests to me that Appenders, Filters, and their subordinate objects must resort to (thread safe) statics to maintain context across this event (and others?).
However, I'm not sure if I'm missing some reason that even that is insufficient/inappropriate.


Solution

  • OnStartupTriggeringPolicy compares the modification time of the log file with the startup of the JVM due to LOG4J2-1440: all logging backends allow a reconfiguration to occur at any time, but the rollover must occur only once.

    That suggests to me that Appenders, Filters, and their subordinate objects must resort to (thread safe) statics to maintain context across this event (and others?).

    Unlike its predecessor and alternatives, Log4j Core does not lose messages during a reconfiguration event. This is accomplished by splitting appenders into two parts:

    • a resource manager that performs the actual work (appending to a file in your case). It is reference-counted (there is a static registry in AbstractManager) and is not stopped unless the reference count goes to 0,
    • an appender, that is recreated at each reconfiguration. Since the old appenders are stopped after the new appenders have already started, there is no interruption of service.