Log4j2 rolling file rotation by hour not working

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

Log4j2 rolling file rotation by hour not working

Joan Balagueró - ventusproxy
Hello,

 

I’ve posted this in stackoverflow, with no success. So I’m trying here now.

 

I'm seeing the following behaviour in log4j2, not sure if it's the expected.

 

This is part of my log4j.xml:

<RollingFile name="ACCESS_LOG"

 
filePattern="${sys:log.dir}vproxy_access.%d{${sys:log.rotateAccess}}"

             append="true"

             bufferedIO="true"

             bufferSize="16384"

             immediateFlush="false">

 

<PatternLayout>

    <Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>

</PatternLayout>

 

<Policies>

    <TimeBasedTriggeringPolicy/>

</Policies>

 

</RollingFile>

 

The log.rotateAccess is a system property than can have the values of
'yyyy-MM-dd' for daily rotation or 'yyyy-MM-dd.HH' for hourly rotation.

So, when I start to send requests to my app at 19:01 the
vproxy_access.2017-05-25.19 is correctly created and requests are logged.
This is the first line of this log:

1,88.0.193.186,2017-05-25
19:01:31.733,A,56,A,0,A,190,A,60,N,,,,2716,423,0,53,ok,2017-05-25
19:01:31.852

 

It's ok, but this is the last line:

1,167.114.89.180,2017-05-25
20:59:59.943,A,56,A,66,A,190,A,60,N,,,gzip,213161,323,5853,18,ok,2017-05-25
20:59:59.967

 

The file has rotated at 21:00 instead of 20:00. So the
vproxy_access.2017-05-25.20 contains all requests from 21:00:00 to 21:59:59.

 

And if we check the vproxy_access.2017-05-25.23, the first and last line
are:

1,167.114.89.180,2017-05-25
23:59:59.984,A,56,A,0,A,190,A,60,N,,,gzip,165921,323,4683,12,ok,2017-05-26
00:00:00.002

( . . . )

1,167.114.89.180,2017-05-26
00:59:59.984,A,56,A,0,A,190,A,60,N,,,,147025,323,0,10,ok,2017-05-26
00:59:59.999

 

Furthermore, today we have stopped to send requests at 01:00
(vproxy_access.2017-06-02.00). When we have started to send requests again
at 12:07, the log file vproxy_access.2017-06-02.01 has been created. This is
the first line:

1,167.114.89.180,2017-06-02
12:07:23.561,A,56,A,0,A,190,A,60,N,,167.114.89.180:80,gzip,151749,323,4335,8
,ok,2017-06-02 12:07:23.575

 

I need my vproxy_access.yyyy-MM-dd.HH to contain all lines from HH:00:00 to
HH:59:59

Any help would be very appreciated.

Joan.

Reply | Threaded
Open this post in threaded view
|

Re: Log4j2 rolling file rotation by hour not working

Ralph Goers
This sounds like a bug that has already been reported. I would suggest you try the CronTriggeringPolicy instead o the TimeBasedTriggeringPolicy.

Ralph

> On Jun 2, 2017, at 3:19 AM, Joan Balagueró - ventusproxy <[hidden email]> wrote:
>
> Hello,
>
>
>
> I致e posted this in stackoverflow, with no success. So I知 trying here now.
>
>
>
> I'm seeing the following behaviour in log4j2, not sure if it's the expected.
>
>
>
> This is part of my log4j.xml:
>
> <RollingFile name="ACCESS_LOG"
>
>
> filePattern="${sys:log.dir}vproxy_access.%d{${sys:log.rotateAccess}}"
>
>             append="true"
>
>             bufferedIO="true"
>
>             bufferSize="16384"
>
>             immediateFlush="false">
>
>
>
> <PatternLayout>
>
>    <Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
>
> </PatternLayout>
>
>
>
> <Policies>
>
>    <TimeBasedTriggeringPolicy/>
>
> </Policies>
>
>
>
> </RollingFile>
>
>
>
> The log.rotateAccess is a system property than can have the values of
> 'yyyy-MM-dd' for daily rotation or 'yyyy-MM-dd.HH' for hourly rotation.
>
> So, when I start to send requests to my app at 19:01 the
> vproxy_access.2017-05-25.19 is correctly created and requests are logged.
> This is the first line of this log:
>
> 1,88.0.193.186,2017-05-25
> 19:01:31.733,A,56,A,0,A,190,A,60,N,,,,2716,423,0,53,ok,2017-05-25
> 19:01:31.852
>
>
>
> It's ok, but this is the last line:
>
> 1,167.114.89.180,2017-05-25
> 20:59:59.943,A,56,A,66,A,190,A,60,N,,,gzip,213161,323,5853,18,ok,2017-05-25
> 20:59:59.967
>
>
>
> The file has rotated at 21:00 instead of 20:00. So the
> vproxy_access.2017-05-25.20 contains all requests from 21:00:00 to 21:59:59.
>
>
>
> And if we check the vproxy_access.2017-05-25.23, the first and last line
> are:
>
> 1,167.114.89.180,2017-05-25
> 23:59:59.984,A,56,A,0,A,190,A,60,N,,,gzip,165921,323,4683,12,ok,2017-05-26
> 00:00:00.002
>
> ( . . . )
>
> 1,167.114.89.180,2017-05-26
> 00:59:59.984,A,56,A,0,A,190,A,60,N,,,,147025,323,0,10,ok,2017-05-26
> 00:59:59.999
>
>
>
> Furthermore, today we have stopped to send requests at 01:00
> (vproxy_access.2017-06-02.00). When we have started to send requests again
> at 12:07, the log file vproxy_access.2017-06-02.01 has been created. This is
> the first line:
>
> 1,167.114.89.180,2017-06-02
> 12:07:23.561,A,56,A,0,A,190,A,60,N,,167.114.89.180:80,gzip,151749,323,4335,8
> ,ok,2017-06-02 12:07:23.575
>
>
>
> I need my vproxy_access.yyyy-MM-dd.HH to contain all lines from HH:00:00 to
> HH:59:59
>
> Any help would be very appreciated.
>
> Joan.
>



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

Reply | Threaded
Open this post in threaded view
|

RE: Log4j2 rolling file rotation by hour not working

Joan Balagueró - ventusproxy
Hi,

CronTriggeringPolicy does not work either. We started to send requests at 17:26, the vproxy_access.2017-02-06.17 was correctly created, and it rotated at 18:00. Ok.

But the vproxy_access. 2017-02-06.18 didn't rotate at 19:00. The last line is:
1,167.114.89.180,2017-06-02 19:59:59.969,A,56,A,0,A,190,A,60,N,,167.114.89.180:80,deflate,16708,321,905,1,ok,2017-06-02 19:59:59.971

Apparently it's the same problem that occurs with the TimeBased. The log4j configuration is the same, changing TimeBased by CronTriggeringPolicy:

<Policies>
        <CronTriggeringPolicy schedule="${sys:log.cronAccess}" />
</Policies>

Where log.cronAccess is "0 0 0/1 * * ?"

Joan.

-----Mensaje original-----
De: Ralph Goers [mailto:[hidden email]]
Enviado el: viernes, 2 de junio de 2017 15:55
Para: Log4J Users List
Asunto: Re: Log4j2 rolling file rotation by hour not working

This sounds like a bug that has already been reported. I would suggest you try the CronTriggeringPolicy instead o the TimeBasedTriggeringPolicy.

Ralph

> On Jun 2, 2017, at 3:19 AM, Joan Balagueró - ventusproxy <[hidden email]> wrote:
>
> Hello,
>
>
>
> I致e posted this in stackoverflow, with no success. So I知 trying here now.
>
>
>
> I'm seeing the following behaviour in log4j2, not sure if it's the expected.
>
>
>
> This is part of my log4j.xml:
>
> <RollingFile name="ACCESS_LOG"
>
>
> filePattern="${sys:log.dir}vproxy_access.%d{${sys:log.rotateAccess}}"
>
>             append="true"
>
>             bufferedIO="true"
>
>             bufferSize="16384"
>
>             immediateFlush="false">
>
>
>
> <PatternLayout>
>
>    <Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
>
> </PatternLayout>
>
>
>
> <Policies>
>
>    <TimeBasedTriggeringPolicy/>
>
> </Policies>
>
>
>
> </RollingFile>
>
>
>
> The log.rotateAccess is a system property than can have the values of
> 'yyyy-MM-dd' for daily rotation or 'yyyy-MM-dd.HH' for hourly rotation.
>
> So, when I start to send requests to my app at 19:01 the
> vproxy_access.2017-05-25.19 is correctly created and requests are logged.
> This is the first line of this log:
>
> 1,88.0.193.186,2017-05-25
> 19:01:31.733,A,56,A,0,A,190,A,60,N,,,,2716,423,0,53,ok,2017-05-25
> 19:01:31.852
>
>
>
> It's ok, but this is the last line:
>
> 1,167.114.89.180,2017-05-25
> 20:59:59.943,A,56,A,66,A,190,A,60,N,,,gzip,213161,323,5853,18,ok,2017-
> 05-25
> 20:59:59.967
>
>
>
> The file has rotated at 21:00 instead of 20:00. So the
> vproxy_access.2017-05-25.20 contains all requests from 21:00:00 to 21:59:59.
>
>
>
> And if we check the vproxy_access.2017-05-25.23, the first and last
> line
> are:
>
> 1,167.114.89.180,2017-05-25
> 23:59:59.984,A,56,A,0,A,190,A,60,N,,,gzip,165921,323,4683,12,ok,2017-0
> 5-26
> 00:00:00.002
>
> ( . . . )
>
> 1,167.114.89.180,2017-05-26
> 00:59:59.984,A,56,A,0,A,190,A,60,N,,,,147025,323,0,10,ok,2017-05-26
> 00:59:59.999
>
>
>
> Furthermore, today we have stopped to send requests at 01:00
> (vproxy_access.2017-06-02.00). When we have started to send requests
> again at 12:07, the log file vproxy_access.2017-06-02.01 has been
> created. This is the first line:
>
> 1,167.114.89.180,2017-06-02
> 12:07:23.561,A,56,A,0,A,190,A,60,N,,167.114.89.180:80,gzip,151749,323,
> 4335,8
> ,ok,2017-06-02 12:07:23.575
>
>
>
> I need my vproxy_access.yyyy-MM-dd.HH to contain all lines from
> HH:00:00 to
> HH:59:59
>
> Any help would be very appreciated.
>
> 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]