[
https://issues.apache.org/jira/browse/LOG4J2-2517?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16731679#comment-16731679
]
Jon Hanson edited comment on LOG4J2-2517 at 1/1/19 8:33 PM:
------------------------------------------------------------
I've just tried the project (with log4j2 2.11.1) on a macbook, and the
behaviour seems intermittent. The first rerun it *did* roll the log file, on
subsequent reruns it did *not*.
Regarding your earlier comment:
{quote}Re-reading your original issue description - Why would the log file time
be after the JVM start-up time and if it is after the JVM startup time why
would you want to roll it over?
The OnStartupTriggeringPoliciy's purpose is mainly to insure that each time you
start up your application you use a different file then was used the previous
time the application ran. If the file timestamp is newer than the JVM startup
time then that already has to be true.
{quote}
Sorry, I'm not sure how I can explain this any more clearly. It appears log4j2
is failing to roll the log file because by the time it checks the timestamp of
the base file (logjam.log in my example) it has already re-opened that file for
writing. This changes the file timestamp to a value that is later that the JVM
startup time. So the check fails. If log4j2 opened the file after it did the
check then it would find the timestamp to be before the JVM startup time, and
it would therefore consistently roll the file.
If I put a breakpoint on the first line of the
OnStartupTriggeringPolicy.initialize method and then check the log file
timestamp before I execute that line, I can see the timestamp has changed to
shortly before now. E.g. before I start app logjam.log timestamp was 19:51, and
I expect it to be rolled when I run the app. I then start the app and at the
breakpoint the timestamp has changed to 19:59 (effectively now). If i inspect
the result of manager.getFileTime() it returns 1546372771000 - (1 Jan 2019
19:59:31). Meanwhile OnStartupTriggeringPolicy.JVM_START_TIME is 1546372770321
(1 Jan 2019 19:59:30.321). Hence the log file is deemed to be after the JVM
startup and it doesn't get rolled. Clearly log4j2 is changing the file
timestamp at startup, which interferes with this logic.
was (Author: jonhanson):
I've just tried the project (with log4j2 2.11.1) on a macbook, and the
behaviour seems intermittent. The first rerun it *did* roll the log file, on
subsequent reruns it did *not*.
Regarding your earlier comment:
{quote}Re-reading your original issue description - Why would the log file time
be after the JVM start-up time and if it is after the JVM startup time why
would you want to roll it over?
The OnStartupTriggeringPoliciy's purpose is mainly to insure that each time you
start up your application you use a different file then was used the previous
time the application ran. If the file timestamp is newer than the JVM startup
time then that already has to be true.
{quote}
I'm not sure how I can explain this any more clearly. It appears log4j2 is
failing to roll the log file because by the time it checks the timestamp of the
base file (logjam.log in my example) it has already re-opened that file for
writing. This changes the file timestamp to a value that is later that the JVM
startup time. So the check fails. If log4j2 opened the file after it did the
check then it would find the timestamp to be before the JVM startup time, and
it would therefore consistently roll the file.
If I put a breakpoint on the first line of the
OnStartupTriggeringPolicy.initialize method and then check the log file
timestamp before I execute that line, I can see the timestamp has changed to
shortly before now. E.g. before I start app logjam.log timestamp was 19:51, and
I expect it to be rolled when I run the app. I then start the app and at the
breakpoint the timestamp has changed to 19:59 (effectively now). If i inspect
the result of manager.getFileTime() it returns 1546372771000 - (1 Jan 2019
19:59:31). Meanwhile OnStartupTriggeringPolicy.JVM_START_TIME is 1546372770321
(1 Jan 2019 19:59:30.321). Hence the log file is deemed to be after the JVM
startup and it doesn't get rolled. Clearly log4j2 is changing the file
timestamp at startup, which interferes with this logic.
> RollingFileManager OnStartupTriggeringPolicy never rolls the file on startup
> ----------------------------------------------------------------------------
>
> Key: LOG4J2-2517
> URL: https://issues.apache.org/jira/browse/LOG4J2-2517
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.11.1
> Reporter: Jon Hanson
> Priority: Minor
> Attachments: log4j2.json, log4j2_debug.log
>
>
> I'm trying to get log4j2 (V2.11.1) to roll the existing log file at startup
> before it starts logging into a new file. My config is atached to the jira.
> I'm using a RollingFileManager with a OnStartupTriggeringPolicy with
> minSize=0, which, according to the documentation should be sufficient.
> However what i'm finding is that at startup, the
> {{OnStartupTriggeringPolicy}} class {{initialize}} method compares the
> timestamp of the log file to the JVM startup, and if the log file time is
> after the start-up time then it won't roll the file. If I step through the
> code then I see that at the point that check is made the file time is always
> after the JVM start time, because log4j2 appears to have already opened the
> file for writing at that point.
> More info here:
> [https://stackoverflow.com/questions/53632091/log4j2-rollingfilemanager-onstartuptriggeringpolicy-never-rolls-the-file-on-star]
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
