How to configure log4j2 to rollover with time stamp on startup? (OR: feature request)

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

How to configure log4j2 to rollover with time stamp on startup? (OR: feature request)

Hachey, Philip
Hello.  This is a question about how to achieve a particular result with log4j2, but I expect may instead be a *feature request*.

I have a Java application that runs for a few minutes each hour via a cron job (java -jar...). It runs in its own JVM, *not* in a continuously running environment like Tomcat. I am using Log4j 2.11 to do logging. Within the application, I have a particular logger with specific rollover requirements:

1. Log to "rolling.log"
2. At the end of each day (or on the first logging event of a new day), rolling.log should be rolled over to rolling-yyyy-MM-dd.log.gz and new logging events added to a fresh rolling.log.

I cannot get this to work.  It appears to me that time-based rollovers are only ever triggered if the application is running at the time the rollover would happen.

For an example of how log4j2 handles things currently, suppose this order of events for a logger configured to rollover daily.

23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
00:00 -- new day; rollover would happen here but application is not running
00:30 -- cronjob runs application for 10 minutes, still logging to rolling.log and no rollover happens

Result: both days of application log messages are logged to the same file: rolling.log, without any rollover.


Feature Request (assuming there is not already a way do this): Allow time-based rollover to trigger if, upon application execution, it is noted that the time a rollover should have happened was after the previous application execution.

E.g.:
23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
00:00 -- new day; rollover would happen here but application is not running
00:30 -- cronjob runs application for 10 minutes; at start of execution (or first log message), log4j2 notes that a rollover should have happened and so rolls over the existing rolling.log and adds all new log messages to a new rolling.log file.

Hint: to do this, log4j will likely need to record a timestamp of the last log message or when the application previously terminated, then read this time stamp on application start (or first log message).

Note: I originally posted this question on Stack Overflow and additional details, including test code and my attempts at log4j2 configuration, may be found there:
https://stackoverflow.com/questions/48874164/how-to-configure-log4j2-to-rollover-with-time-stamp-on-startup

Thank you,
Philip
Reply | Threaded
Open this post in threaded view
|

Re: How to configure log4j2 to rollover with time stamp on startup? (OR: feature request)

Matt Sicker
Are you using OnStartupTriggeringPolicy?
http://logging.apache.org/log4j/2.x/manual/appenders.html#RollingFileAppender

On 14 May 2018 at 12:47, Hachey, Philip <[hidden email]>
wrote:

> Hello.  This is a question about how to achieve a particular result with
> log4j2, but I expect may instead be a *feature request*.
>
> I have a Java application that runs for a few minutes each hour via a cron
> job (java -jar...). It runs in its own JVM, *not* in a continuously running
> environment like Tomcat. I am using Log4j 2.11 to do logging. Within the
> application, I have a particular logger with specific rollover requirements:
>
> 1. Log to "rolling.log"
> 2. At the end of each day (or on the first logging event of a new day),
> rolling.log should be rolled over to rolling-yyyy-MM-dd.log.gz and new
> logging events added to a fresh rolling.log.
>
> I cannot get this to work.  It appears to me that time-based rollovers are
> only ever triggered if the application is running at the time the rollover
> would happen.
>
> For an example of how log4j2 handles things currently, suppose this order
> of events for a logger configured to rollover daily.
>
> 23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
> 00:00 -- new day; rollover would happen here but application is not running
> 00:30 -- cronjob runs application for 10 minutes, still logging to
> rolling.log and no rollover happens
>
> Result: both days of application log messages are logged to the same file:
> rolling.log, without any rollover.
>
>
> Feature Request (assuming there is not already a way do this): Allow
> time-based rollover to trigger if, upon application execution, it is noted
> that the time a rollover should have happened was after the previous
> application execution.
>
> E.g.:
> 23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
> 00:00 -- new day; rollover would happen here but application is not running
> 00:30 -- cronjob runs application for 10 minutes; at start of execution
> (or first log message), log4j2 notes that a rollover should have happened
> and so rolls over the existing rolling.log and adds all new log messages to
> a new rolling.log file.
>
> Hint: to do this, log4j will likely need to record a timestamp of the last
> log message or when the application previously terminated, then read this
> time stamp on application start (or first log message).
>
> Note: I originally posted this question on Stack Overflow and additional
> details, including test code and my attempts at log4j2 configuration, may
> be found there:
> https://stackoverflow.com/questions/48874164/how-to-
> configure-log4j2-to-rollover-with-time-stamp-on-startup
>
> Thank you,
> Philip
>



--
Matt Sicker <[hidden email]>
Reply | Threaded
Open this post in threaded view
|

Re: How to configure log4j2 to rollover with time stamp on startup? (OR: feature request)

Hachey, Philip
Yes.  As a test, I set the configuration to rollover every minute.  Running a test application that takes negligible time to run and then running it again a few minutes later produces no rollover. Log messages from both executions get logged to the same file.

Here are the contents of the log4j2.xml:

*******

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE Configuration>
<Configuration status="WARN">
    <Appenders>
        <RollingFile name="RollingLogFile"
            fileName="logs/rolling.log"
            filePattern="logs/rolling-%d{yyyy-MM-dd-HH-mm}.log.gz"
            createOnDemand="true">
            <PatternLayout
                pattern="%d{HH:mm:ss.SSS} %-5level - %msg%n" />
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"
                    interval="1" />
                <OnStartupTriggeringPolicy />
            </Policies>
            <DefaultRolloverStrategy />
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root level="error">
            <AppenderRef ref="RollingLogFile" />
        </Root>
    </Loggers>
</Configuration>

*******

On 2018-05-14 01:55 PM, Matt Sicker wrote:

Are you using OnStartupTriggeringPolicy?
http://logging.apache.org/log4j/2.x/manual/appenders.html#RollingFileAppender

On 14 May 2018 at 12:47, Hachey, Philip <[hidden email]><mailto:[hidden email]>
wrote:



Hello.  This is a question about how to achieve a particular result with
log4j2, but I expect may instead be a *feature request*.

I have a Java application that runs for a few minutes each hour via a cron
job (java -jar...). It runs in its own JVM, *not* in a continuously running
environment like Tomcat. I am using Log4j 2.11 to do logging. Within the
application, I have a particular logger with specific rollover requirements:

1. Log to "rolling.log"
2. At the end of each day (or on the first logging event of a new day),
rolling.log should be rolled over to rolling-yyyy-MM-dd.log.gz and new
logging events added to a fresh rolling.log.

I cannot get this to work.  It appears to me that time-based rollovers are
only ever triggered if the application is running at the time the rollover
would happen.

For an example of how log4j2 handles things currently, suppose this order
of events for a logger configured to rollover daily.

23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
00:00 -- new day; rollover would happen here but application is not running
00:30 -- cronjob runs application for 10 minutes, still logging to
rolling.log and no rollover happens

Result: both days of application log messages are logged to the same file:
rolling.log, without any rollover.


Feature Request (assuming there is not already a way do this): Allow
time-based rollover to trigger if, upon application execution, it is noted
that the time a rollover should have happened was after the previous
application execution.

E.g.:
23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
00:00 -- new day; rollover would happen here but application is not running
00:30 -- cronjob runs application for 10 minutes; at start of execution
(or first log message), log4j2 notes that a rollover should have happened
and so rolls over the existing rolling.log and adds all new log messages to
a new rolling.log file.

Hint: to do this, log4j will likely need to record a timestamp of the last
log message or when the application previously terminated, then read this
time stamp on application start (or first log message).

Note: I originally posted this question on Stack Overflow and additional
details, including test code and my attempts at log4j2 configuration, may
be found there:
https://stackoverflow.com/questions/48874164/how-to-
configure-log4j2-to-rollover-with-time-stamp-on-startup

Thank you,
Philip








Reply | Threaded
Open this post in threaded view
|

Re: How to configure log4j2 to rollover with time stamp on startup? (OR: feature request)

Franz Wong
Is it more suitable to use CronTriggeringPolicy?

-Franz

On Tue, May 15, 2018 at 4:21 AM, Hachey, Philip <
[hidden email]> wrote:

> Yes.  As a test, I set the configuration to rollover every minute.
> Running a test application that takes negligible time to run and then
> running it again a few minutes later produces no rollover. Log messages
> from both executions get logged to the same file.
>
> Here are the contents of the log4j2.xml:
>
> *******
>
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE Configuration>
> <Configuration status="WARN">
>     <Appenders>
>         <RollingFile name="RollingLogFile"
>             fileName="logs/rolling.log"
>             filePattern="logs/rolling-%d{yyyy-MM-dd-HH-mm}.log.gz"
>             createOnDemand="true">
>             <PatternLayout
>                 pattern="%d{HH:mm:ss.SSS} %-5level - %msg%n" />
>             <Policies>
>                 <TimeBasedTriggeringPolicy modulate="true"
>                     interval="1" />
>                 <OnStartupTriggeringPolicy />
>             </Policies>
>             <DefaultRolloverStrategy />
>         </RollingFile>
>     </Appenders>
>     <Loggers>
>         <Root level="error">
>             <AppenderRef ref="RollingLogFile" />
>         </Root>
>     </Loggers>
> </Configuration>
>
> *******
>
> On 2018-05-14 01:55 PM, Matt Sicker wrote:
>
> Are you using OnStartupTriggeringPolicy?
> http://logging.apache.org/log4j/2.x/manual/appenders.
> html#RollingFileAppender
>
> On 14 May 2018 at 12:47, Hachey, Philip <[hidden email]>
> <mailto:[hidden email]>
> wrote:
>
>
>
> Hello.  This is a question about how to achieve a particular result with
> log4j2, but I expect may instead be a *feature request*.
>
> I have a Java application that runs for a few minutes each hour via a cron
> job (java -jar...). It runs in its own JVM, *not* in a continuously running
> environment like Tomcat. I am using Log4j 2.11 to do logging. Within the
> application, I have a particular logger with specific rollover
> requirements:
>
> 1. Log to "rolling.log"
> 2. At the end of each day (or on the first logging event of a new day),
> rolling.log should be rolled over to rolling-yyyy-MM-dd.log.gz and new
> logging events added to a fresh rolling.log.
>
> I cannot get this to work.  It appears to me that time-based rollovers are
> only ever triggered if the application is running at the time the rollover
> would happen.
>
> For an example of how log4j2 handles things currently, suppose this order
> of events for a logger configured to rollover daily.
>
> 23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
> 00:00 -- new day; rollover would happen here but application is not running
> 00:30 -- cronjob runs application for 10 minutes, still logging to
> rolling.log and no rollover happens
>
> Result: both days of application log messages are logged to the same file:
> rolling.log, without any rollover.
>
>
> Feature Request (assuming there is not already a way do this): Allow
> time-based rollover to trigger if, upon application execution, it is noted
> that the time a rollover should have happened was after the previous
> application execution.
>
> E.g.:
> 23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
> 00:00 -- new day; rollover would happen here but application is not running
> 00:30 -- cronjob runs application for 10 minutes; at start of execution
> (or first log message), log4j2 notes that a rollover should have happened
> and so rolls over the existing rolling.log and adds all new log messages to
> a new rolling.log file.
>
> Hint: to do this, log4j will likely need to record a timestamp of the last
> log message or when the application previously terminated, then read this
> time stamp on application start (or first log message).
>
> Note: I originally posted this question on Stack Overflow and additional
> details, including test code and my attempts at log4j2 configuration, may
> be found there:
> https://stackoverflow.com/questions/48874164/how-to-
> configure-log4j2-to-rollover-with-time-stamp-on-startup
>
> Thank you,
> Philip
>
>
>
>
>
>
>
>
>
Reply | Threaded
Open this post in threaded view
|

Re: How to configure log4j2 to rollover with time stamp on startup? (OR: feature request)

Hachey, Philip
Thank you. After experimenting a bit with CronTriggeringPolicy and initially unable to get it to work even in the simplest of configurations, I found the precise condition that was preventing rollover from happening: including createOnDemand="true" in the RollingFile element.  After excluding that attribute, the following configuration works exactly as I would expect (rolling over at startup, at most every minute):

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE Configuration>
<Configuration status="WARN">
    <Appenders>
        <RollingFile name="RollingLogFile" fileName="logs/rolling.log" filePattern="logs/rolling-%d{yyyy-MM-dd-HH-mm}.log.gz">
            <TimeBasedTriggeringPolicy />
            <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level - %msg%n" />
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root level="error">
            <AppenderRef ref="RollingLogFile" />
        </Root>
    </Loggers>
</Configuration>

This may or may not be a bug, depending on the precise intention behind createOnDemand, but it turns out that this attribute is thankfully not a requirement for me.

Regards,

Philip

On 2018-05-15 06:36 AM, Franz Wong wrote:

Is it more suitable to use CronTriggeringPolicy?

-Franz

On Tue, May 15, 2018 at 4:21 AM, Hachey, Philip <
[hidden email]<mailto:[hidden email]>> wrote:



Yes.  As a test, I set the configuration to rollover every minute.
Running a test application that takes negligible time to run and then
running it again a few minutes later produces no rollover. Log messages
from both executions get logged to the same file.

Here are the contents of the log4j2.xml:

*******

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE Configuration>
<Configuration status="WARN">
    <Appenders>
        <RollingFile name="RollingLogFile"
            fileName="logs/rolling.log"
            filePattern="logs/rolling-%d{yyyy-MM-dd-HH-mm}.log.gz"
            createOnDemand="true">
            <PatternLayout
                pattern="%d{HH:mm:ss.SSS} %-5level - %msg%n" />
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"
                    interval="1" />
                <OnStartupTriggeringPolicy />
            </Policies>
            <DefaultRolloverStrategy />
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root level="error">
            <AppenderRef ref="RollingLogFile" />
        </Root>
    </Loggers>
</Configuration>

*******

On 2018-05-14 01:55 PM, Matt Sicker wrote:

Are you using OnStartupTriggeringPolicy?
http://logging.apache.org/log4j/2.x/manual/appenders.
html#RollingFileAppender

On 14 May 2018 at 12:47, Hachey, Philip <[hidden email]><mailto:[hidden email]>
<mailto:[hidden email]><mailto:[hidden email]>
wrote:



Hello.  This is a question about how to achieve a particular result with
log4j2, but I expect may instead be a *feature request*.

I have a Java application that runs for a few minutes each hour via a cron
job (java -jar...). It runs in its own JVM, *not* in a continuously running
environment like Tomcat. I am using Log4j 2.11 to do logging. Within the
application, I have a particular logger with specific rollover
requirements:

1. Log to "rolling.log"
2. At the end of each day (or on the first logging event of a new day),
rolling.log should be rolled over to rolling-yyyy-MM-dd.log.gz and new
logging events added to a fresh rolling.log.

I cannot get this to work.  It appears to me that time-based rollovers are
only ever triggered if the application is running at the time the rollover
would happen.

For an example of how log4j2 handles things currently, suppose this order
of events for a logger configured to rollover daily.

23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
00:00 -- new day; rollover would happen here but application is not running
00:30 -- cronjob runs application for 10 minutes, still logging to
rolling.log and no rollover happens

Result: both days of application log messages are logged to the same file:
rolling.log, without any rollover.


Feature Request (assuming there is not already a way do this): Allow
time-based rollover to trigger if, upon application execution, it is noted
that the time a rollover should have happened was after the previous
application execution.

E.g.:
23:30 -- cronjob runs application for 10 minutes, logging to rolling.log
00:00 -- new day; rollover would happen here but application is not running
00:30 -- cronjob runs application for 10 minutes; at start of execution
(or first log message), log4j2 notes that a rollover should have happened
and so rolls over the existing rolling.log and adds all new log messages to
a new rolling.log file.

Hint: to do this, log4j will likely need to record a timestamp of the last
log message or when the application previously terminated, then read this
time stamp on application start (or first log message).

Note: I originally posted this question on Stack Overflow and additional
details, including test code and my attempts at log4j2 configuration, may
be found there:
https://stackoverflow.com/questions/48874164/how-to-
configure-log4j2-to-rollover-with-time-stamp-on-startup

Thank you,
Philip