Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

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

Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan ventusproxy
Hello,

We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:

<RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
        <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
        <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?" evaluateOnStartup="true" /></Policies>
</RollingRandomAccessFile>

<Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
        <AppenderRef ref="ACCESS_LOG"/>
</Logger>

So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...

-rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
-rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
-rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
-rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
-rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
-rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
-rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
-rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
-rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
-rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05

Is this a bug or some misconfiguration in our log4j.xml file?

Thanks for any help you can provide,

Joan.


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Ralph Goers
What version of Log4j are you using?

If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?

Ralph

> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hello,
>
> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>
> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?" evaluateOnStartup="true" /></Policies>
> </RollingRandomAccessFile>
>
> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
> <AppenderRef ref="ACCESS_LOG"/>
> </Logger>
>
> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>
> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>
> Is this a bug or some misconfiguration in our log4j.xml file?
>
> Thanks for any help you can provide,
>
> Joan.
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan ventusproxy
Hi Ralph,

Log4j version is 2.11.2. Below the output requested:

2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.043+0100
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.043+0100
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.043+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.045+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.045+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.045+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100

Files after rotation:

-rw-r-----. 1 root        root         487529 Feb  6 00:00 vproxy_access
-rw-r-----. 1 root        root        2437185 Feb  6 00:00 vproxy_access.2020-02-05
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
-rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-06
-rw-r-----. 1 root        root          12490 Feb  6 00:00 vproxy_error
-rw-r-----. 1 root        root          20756 Feb  6 00:00 vproxy_error.2020-02-06
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_system
-rw-r-----. 1 root        root          14484 Feb  5 23:59 vproxy_system.2020-02-05

Thanks,

Joan.


-----Original Message-----
From: Ralph Goers <[hidden email]>
Sent: Wednesday, February 5, 2020 8:06 PM
To: Log4J Users List <[hidden email]>
Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

What version of Log4j are you using?

If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?

Ralph

> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hello,
>
> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>
> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?"
> evaluateOnStartup="true" /></Policies> </RollingRandomAccessFile>
>
> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
> <AppenderRef ref="ACCESS_LOG"/>
> </Logger>
>
> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>
> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>
> Is this a bug or some misconfiguration in our log4j.xml file?
>
> Thanks for any help you can provide,
>
> Joan.
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]




---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan ventusproxy
In reply to this post by Ralph Goers
Hi Ralph,

Do you think this is a bug or a misconfiguration on my side?

Thanks,

Joan.

-----Original Message-----
From: Joan ventusproxy <[hidden email]>
Sent: Thursday, February 6, 2020 6:21 PM
To: 'Log4J Users List' <[hidden email]>
Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Hi Ralph,

Log4j version is 2.11.2. Below the output requested:

2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.043+0100
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.043+0100
2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.043+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.045+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.045+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.045+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100

Files after rotation:

-rw-r-----. 1 root        root         487529 Feb  6 00:00 vproxy_access
-rw-r-----. 1 root        root        2437185 Feb  6 00:00 vproxy_access.2020-02-05
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
-rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-06
-rw-r-----. 1 root        root          12490 Feb  6 00:00 vproxy_error
-rw-r-----. 1 root        root          20756 Feb  6 00:00 vproxy_error.2020-02-06
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_system
-rw-r-----. 1 root        root          14484 Feb  5 23:59 vproxy_system.2020-02-05

Thanks,

Joan.


-----Original Message-----
From: Ralph Goers <[hidden email]>
Sent: Wednesday, February 5, 2020 8:06 PM
To: Log4J Users List <[hidden email]>
Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

What version of Log4j are you using?

If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?

Ralph

> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hello,
>
> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>
> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?"
> evaluateOnStartup="true" /></Policies> </RollingRandomAccessFile>
>
> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
> <AppenderRef ref="ACCESS_LOG"/>
> </Logger>
>
> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>
> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>
> Is this a bug or some misconfiguration in our log4j.xml file?
>
> Thanks for any help you can provide,
>
> Joan.
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]




---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Ralph Goers
Joan,

I apologize but I have only had time to glance at the log. It doesn’t look correct. Is it possible you could test with 2.13.0 just to rule out that it might have already been fixed?

Ralph


> On Feb 11, 2020, at 9:30 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hi Ralph,
>
> Do you think this is a bug or a misconfiguration on my side?
>
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Joan ventusproxy <[hidden email]>
> Sent: Thursday, February 6, 2020 6:21 PM
> To: 'Log4J Users List' <[hidden email]>
> Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> Hi Ralph,
>
> Log4j version is 2.11.2. Below the output requested:
>
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>
> Files after rotation:
>
> -rw-r-----. 1 root        root         487529 Feb  6 00:00 vproxy_access
> -rw-r-----. 1 root        root        2437185 Feb  6 00:00 vproxy_access.2020-02-05
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
> -rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-06
> -rw-r-----. 1 root        root          12490 Feb  6 00:00 vproxy_error
> -rw-r-----. 1 root        root          20756 Feb  6 00:00 vproxy_error.2020-02-06
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_system
> -rw-r-----. 1 root        root          14484 Feb  5 23:59 vproxy_system.2020-02-05
>
> Thanks,
>
> Joan.
>
>
> -----Original Message-----
> From: Ralph Goers <[hidden email]>
> Sent: Wednesday, February 5, 2020 8:06 PM
> To: Log4J Users List <[hidden email]>
> Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> What version of Log4j are you using?
>
> If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?
>
> Ralph
>
>> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>>
>> Hello,
>>
>> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>>
>> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
>> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
>> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?"
>> evaluateOnStartup="true" /></Policies> </RollingRandomAccessFile>
>>
>> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
>> <AppenderRef ref="ACCESS_LOG"/>
>> </Logger>
>>
>> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>>
>> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
>> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
>> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
>> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
>> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
>> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
>> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
>> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
>> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
>> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>>
>> Is this a bug or some misconfiguration in our log4j.xml file?
>>
>> Thanks for any help you can provide,
>>
>> Joan.
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan ventusproxy
Hi Ralph,

Similar with 2.13.0 I'd say:

2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.011+0100
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-10 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.011+0100
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.011+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.013+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.013+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.013+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100

And logs:
-rw-r-----. 1 root        root        3725082 Feb  6 00:01 vproxy_access
-rw-r-----. 1 root        root         795226 Feb  6 00:00 vproxy_access.2020-02-06
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
-rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-05
-rw-r-----. 1 root        root          40514 Feb  6 00:01 vproxy_error
-rw-r-----. 1 root        root          12463 Feb  5 23:59 vproxy_error.2020-02-06
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
-rw-r-----. 1 root        root           2640 Feb  6 00:00 vproxy_system
-rw-r-----. 1 root        root          15865 Feb  5 23:59 vproxy_system.2020-02-05

Regards,

Joan.


-----Original Message-----
From: Ralph Goers <[hidden email]>
Sent: Tuesday, February 11, 2020 7:18 PM
To: Log4J Users List <[hidden email]>
Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan,

I apologize but I have only had time to glance at the log. It doesn’t look correct. Is it possible you could test with 2.13.0 just to rule out that it might have already been fixed?

Ralph


> On Feb 11, 2020, at 9:30 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hi Ralph,
>
> Do you think this is a bug or a misconfiguration on my side?
>
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Joan ventusproxy <[hidden email]>
> Sent: Thursday, February 6, 2020 6:21 PM
> To: 'Log4J Users List' <[hidden email]>
> Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> Hi Ralph,
>
> Log4j version is 2.11.2. Below the output requested:
>
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>
> Files after rotation:
>
> -rw-r-----. 1 root        root         487529 Feb  6 00:00 vproxy_access
> -rw-r-----. 1 root        root        2437185 Feb  6 00:00 vproxy_access.2020-02-05
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
> -rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-06
> -rw-r-----. 1 root        root          12490 Feb  6 00:00 vproxy_error
> -rw-r-----. 1 root        root          20756 Feb  6 00:00 vproxy_error.2020-02-06
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_system
> -rw-r-----. 1 root        root          14484 Feb  5 23:59 vproxy_system.2020-02-05
>
> Thanks,
>
> Joan.
>
>
> -----Original Message-----
> From: Ralph Goers <[hidden email]>
> Sent: Wednesday, February 5, 2020 8:06 PM
> To: Log4J Users List <[hidden email]>
> Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> What version of Log4j are you using?
>
> If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?
>
> Ralph
>
>> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>>
>> Hello,
>>
>> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>>
>> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
>> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
>> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?"
>> evaluateOnStartup="true" /></Policies> </RollingRandomAccessFile>
>>
>> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
>> <AppenderRef ref="ACCESS_LOG"/>
>> </Logger>
>>
>> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>>
>> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
>> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
>> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
>> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
>> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
>> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
>> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
>> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
>> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
>> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>>
>> Is this a bug or some misconfiguration in our log4j.xml file?
>>
>> Thanks for any help you can provide,
>>
>> Joan.
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]




---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan ventusproxy
In reply to this post by Ralph Goers
Hi Ralph,

Is this a bug definitely? Do you want I open an issue?

Thanks,

Joan.

-----Original Message-----
From: Joan ventusproxy <[hidden email]>
Sent: Tuesday, February 11, 2020 7:36 PM
To: 'Log4J Users List' <[hidden email]>
Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Hi Ralph,

Similar with 2.13.0 I'd say:

2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.011+0100
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-10 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.011+0100
2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.011+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-06, renameEmptyFiles=false]
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.013+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.013+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.013+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100

And logs:
-rw-r-----. 1 root        root        3725082 Feb  6 00:01 vproxy_access
-rw-r-----. 1 root        root         795226 Feb  6 00:00 vproxy_access.2020-02-06
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
-rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-05
-rw-r-----. 1 root        root          40514 Feb  6 00:01 vproxy_error
-rw-r-----. 1 root        root          12463 Feb  5 23:59 vproxy_error.2020-02-06
-rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
-rw-r-----. 1 root        root           2640 Feb  6 00:00 vproxy_system
-rw-r-----. 1 root        root          15865 Feb  5 23:59 vproxy_system.2020-02-05

Regards,

Joan.


-----Original Message-----
From: Ralph Goers <[hidden email]>
Sent: Tuesday, February 11, 2020 7:18 PM
To: Log4J Users List <[hidden email]>
Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Joan,

I apologize but I have only had time to glance at the log. It doesn’t look correct. Is it possible you could test with 2.13.0 just to rule out that it might have already been fixed?

Ralph


> On Feb 11, 2020, at 9:30 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hi Ralph,
>
> Do you think this is a bug or a misconfiguration on my side?
>
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Joan ventusproxy <[hidden email]>
> Sent: Thursday, February 6, 2020 6:21 PM
> To: 'Log4J Users List' <[hidden email]>
> Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> Hi Ralph,
>
> Log4j version is 2.11.2. Below the output requested:
>
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.043+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.045+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>
> Files after rotation:
>
> -rw-r-----. 1 root        root         487529 Feb  6 00:00 vproxy_access
> -rw-r-----. 1 root        root        2437185 Feb  6 00:00 vproxy_access.2020-02-05
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
> -rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-06
> -rw-r-----. 1 root        root          12490 Feb  6 00:00 vproxy_error
> -rw-r-----. 1 root        root          20756 Feb  6 00:00 vproxy_error.2020-02-06
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_system
> -rw-r-----. 1 root        root          14484 Feb  5 23:59 vproxy_system.2020-02-05
>
> Thanks,
>
> Joan.
>
>
> -----Original Message-----
> From: Ralph Goers <[hidden email]>
> Sent: Wednesday, February 5, 2020 8:06 PM
> To: Log4J Users List <[hidden email]>
> Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> What version of Log4j are you using?
>
> If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?
>
> Ralph
>
>> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>>
>> Hello,
>>
>> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>>
>> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
>> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
>> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?"
>> evaluateOnStartup="true" /></Policies> </RollingRandomAccessFile>
>>
>> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
>> <AppenderRef ref="ACCESS_LOG"/>
>> </Logger>
>>
>> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>>
>> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
>> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
>> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
>> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
>> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
>> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
>> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
>> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
>> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
>> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>>
>> Is this a bug or some misconfiguration in our log4j.xml file?
>>
>> Thanks for any help you can provide,
>>
>> Joan.
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]




---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy

Ralph Goers
Whether it is a bug or not I still can’t say, but please open an issue and attach all of this information. A sample project that demonstrates the problem would be extremely helpful.  We have tests and, as far as I know, none of them exhibit this behavior.

Ralph

> On Feb 25, 2020, at 4:12 AM, Joan ventusproxy <[hidden email]> wrote:
>
> Hi Ralph,
>
> Is this a bug definitely? Do you want I open an issue?
>
> Thanks,
>
> Joan.
>
> -----Original Message-----
> From: Joan ventusproxy <[hidden email]>
> Sent: Tuesday, February 11, 2020 7:36 PM
> To: 'Log4J Users List' <[hidden email]>
> Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> Hi Ralph,
>
> Similar with 2.13.0 I'd say:
>
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
> 2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,006 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,009 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.011+0100
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-10 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.011+0100
> 2020-02-06 00:00:01,011 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.011+0100
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,012 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-06, renameEmptyFiles=false]
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.013+0100
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.013+0100
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.013+0100
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
> 2020-02-06 00:00:01,013 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>
> And logs:
> -rw-r-----. 1 root        root        3725082 Feb  6 00:01 vproxy_access
> -rw-r-----. 1 root        root         795226 Feb  6 00:00 vproxy_access.2020-02-06
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
> -rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-05
> -rw-r-----. 1 root        root          40514 Feb  6 00:01 vproxy_error
> -rw-r-----. 1 root        root          12463 Feb  5 23:59 vproxy_error.2020-02-06
> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
> -rw-r-----. 1 root        root           2640 Feb  6 00:00 vproxy_system
> -rw-r-----. 1 root        root          15865 Feb  5 23:59 vproxy_system.2020-02-05
>
> Regards,
>
> Joan.
>
>
> -----Original Message-----
> From: Ralph Goers <[hidden email]>
> Sent: Tuesday, February 11, 2020 7:18 PM
> To: Log4J Users List <[hidden email]>
> Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>
> Joan,
>
> I apologize but I have only had time to glance at the log. It doesn’t look correct. Is it possible you could test with 2.13.0 just to rule out that it might have already been fixed?
>
> Ralph
>
>
>> On Feb 11, 2020, at 9:30 AM, Joan ventusproxy <[hidden email]> wrote:
>>
>> Hi Ralph,
>>
>> Do you think this is a bug or a misconfiguration on my side?
>>
>> Thanks,
>>
>> Joan.
>>
>> -----Original Message-----
>> From: Joan ventusproxy <[hidden email]>
>> Sent: Thursday, February 6, 2020 6:21 PM
>> To: 'Log4J Users List' <[hidden email]>
>> Subject: RE: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>>
>> Hi Ralph,
>>
>> Log4j version is 2.11.2. Below the output requested:
>>
>> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-12 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
>> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-10 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
>> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
>> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
>> 2020-02-06 00:00:01,001 Log4j2-TF-13-Scheduled-11 DEBUG Setting prev file time to 2020-02-05T00:00:01.000+0100
>> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,037 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-11 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-10 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-12 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,040 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580857201000
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-10 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_access to /home/ventusproxy/logs/vproxy_access.2020-02-05, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/http.log to /home/ventusproxy/logs/http.2020-02-05, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-11 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_system to /home/ventusproxy/logs/vproxy_system.2020-02-05, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_cluster to /home/ventusproxy/logs/vproxy_cluster.2020-02-05, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_monitor to /home/ventusproxy/logs/vproxy_monitor.2020-02-05, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-12 DEBUG Now writing to /home/ventusproxy/logs/vproxy_cluster at 2020-02-06T00:00:01.043+0100
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/http.log at 2020-02-06T00:00:01.043+0100
>> 2020-02-06 00:00:01,043 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_monitor at 2020-02-06T00:00:01.043+0100
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-12 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Setting prev file time to 2020-02-06T00:00:01.000+0100
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1580857201000, prevFileTime=1580943601000
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-8 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_error to /home/ventusproxy/logs/vproxy_error.2020-02-06, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,044 Log4j2-TF-13-Scheduled-9 DEBUG RollingFileManager executing synchronous FileRenameAction[/home/ventusproxy/logs/vproxy_datametrycs to /home/ventusproxy/logs/vproxy_datametrycs.2020-02-06, renameEmptyFiles=false]
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Now writing to /home/ventusproxy/logs/vproxy_error at 2020-02-06T00:00:01.045+0100
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Now writing to /home/ventusproxy/logs/vproxy_datametrycs at 2020-02-06T00:00:01.045+0100
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Now writing to /home/ventusproxy/logs/vproxy_system at 2020-02-06T00:00:01.045+0100
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-10 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-8 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-9 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>> 2020-02-06 00:00:01,045 Log4j2-TF-13-Scheduled-11 DEBUG Log4j2 ConfigurationScheduler Cron expression 1 0 0 * * ? scheduled to fire again at 2020-02-07T00:00:01.000+0100
>>
>> Files after rotation:
>>
>> -rw-r-----. 1 root        root         487529 Feb  6 00:00 vproxy_access
>> -rw-r-----. 1 root        root        2437185 Feb  6 00:00 vproxy_access.2020-02-05
>> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_cluster
>> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_datametrycs
>> -rw-r-----. 1 root        root            771 Feb  6 00:00 vproxy_datametrycs.2020-02-06
>> -rw-r-----. 1 root        root          12490 Feb  6 00:00 vproxy_error
>> -rw-r-----. 1 root        root          20756 Feb  6 00:00 vproxy_error.2020-02-06
>> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_monitor
>> -rw-r-----. 1 root        root              0 Feb  6 00:00 vproxy_system
>> -rw-r-----. 1 root        root          14484 Feb  5 23:59 vproxy_system.2020-02-05
>>
>> Thanks,
>>
>> Joan.
>>
>>
>> -----Original Message-----
>> From: Ralph Goers <[hidden email]>
>> Sent: Wednesday, February 5, 2020 8:06 PM
>> To: Log4J Users List <[hidden email]>
>> Subject: Re: Wrong extensions when rotating files using RollingRandomAccessFile with CronTriggeringPolicy
>>
>> What version of Log4j are you using?
>>
>> If you add status=DEBUG to the configuration element you will see logs appear in stdout that identify some things that are useful for debugging issues during rollover. Could you provide that please?
>>
>> Ralph
>>
>>> On Feb 5, 2020, at 9:50 AM, Joan ventusproxy <[hidden email]> wrote:
>>>
>>> Hello,
>>>
>>> We have 5 async logs in our log4j2 configuration that rotates every day at 00:01. This is the config for one of them:
>>>
>>> <RollingRandomAccessFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access" filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true" immediateFlush="false">
>>> <PatternLayout><Pattern>%m%d{HH:mm:ss.SSS}%n</Pattern></PatternLayout>
>>> <Policies><CronTriggeringPolicy schedule="1 0 0 * * ?"
>>> evaluateOnStartup="true" /></Policies> </RollingRandomAccessFile>
>>>
>>> <Logger name="LOGGER_ACCESS" level="info" includeLocation="false" additivity="false">
>>> <AppenderRef ref="ACCESS_LOG"/>
>>> </Logger>
>>>
>>> So at 5 Feb 00:01 we expected to have 5 logs with the '2020-02-04' extension, but we see files with '2020-02-05' extension. This sometimes happens to some files, sometimes to other files ... it's not always happening to the same files. Some days rotation is ok, some days rotation fails just in 1 file, sometimes in 2 files, ...
>>>
>>> -rw-r-----. 1 root        root        1649483171 Feb  5 16:22 vproxy_access
>>> -rw-r-----. 1 root        root         225670559 Feb  5 00:00 vproxy_access.2020-02-04
>>> -rw-r-----. 1 root        root          42650335 Feb  5 16:29 vproxy_cluster
>>> -rw-r-----. 1 root        root              8052 Feb  4 17:58 vproxy_cluster.2020-02-04
>>> -rw-r-----. 1 root        root        1222846577 Feb  5 17:26 vproxy_datametrycs
>>> -rw-r-----. 1 root        root         167707641 Feb  5 00:00 vproxy_datametrycs.2020-02-05
>>> -rw-r-----. 1 root        root        1448754527 Feb  5 16:22 vproxy_error
>>> -rw-r-----. 1 root        root         199048217 Feb  5 00:00 vproxy_error.2020-02-04
>>> -rw-r-----. 1 root        root           3683378 Feb  5 17:41 vproxy_system
>>> -rw-r-----. 1 root        root           2238045 Feb  4 23:59 vproxy_system.2020-02-05
>>>
>>> Is this a bug or some misconfiguration in our log4j.xml file?
>>>
>>> Thanks for any help you can provide,
>>>
>>> Joan.
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]