Discussion:
Problem with daily rotation on log4j2 RollingFile
Joan Balagueró - ventusproxy
2018-08-24 16:30:09 UTC
Permalink
Hello,



I’m using RollingFileAppender with full async logging. This is the config:



<Appenders>

<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">

<PatternLayout>

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

</PatternLayout>

<Policies>

<TimeBasedTriggeringPolicy/>

</Policies>

</RollingFile>

<Appenders>



<Loggers>

<Root level="off" additivity="false" />

<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">

<AppenderRef ref="ACCESS_LOG"/>

</Logger>

</Loggers>





I started to send requests the 2018-08-22, the vproxy_access.2018-08-22 was
correctly created and requests started to be logged. These are the first 2
lines:

1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735

1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744



Then I stopped to send requests until 2018-08-24 12:25. The point is these
requests (sent today, day 24) have been logged on the same file, 2018-08-22,
instead of in a newly created log file 2018-08-24. This is the moment (2
lines before, and the first 2 lines today):

1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537

1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977

1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466

1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471



Today I’ve kept on sending requests, and these are the last 2 lines:

1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326

1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795



At 00:00 rotation is performed, this is the new log file (it’s correct):

1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189

1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680

1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,,2700,326,0,256,ok,2018
-08-25 00:00:00.937



But the problem is this log file has been created as 2018-08-24 instead of
2018-08-25.



These are my 2 log files:

-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22

-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24



And this is the system date now:

[***@server02 logs]# date

Sat Aug 25 00:17:37 EDT 2018





So at this point I’m not sure if this is a bug or I simply has something
misconfigured in my log4j.xml



Thanks,



Joan.
Ralph Goers
2018-08-24 17:17:59 UTC
Permalink
The TimeBasedTriggeringPolicy does not check for rollover on every log event to reduce the overhead on busy systems. When you are only logging a few events you will see it log a few records to the prior file before it checks for a rollover. In your case you would be better off using the CronTriggeringPolicy as it has a background thread that checks for the time to rollover.

Ralph
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the vproxy_access.2018-08-22 was
correctly created and requests started to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is these
requests (sent today, day 24) have been logged on the same file, 2018-08-22,
instead of in a newly created log file 2018-08-24. This is the moment (2
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24 instead of
2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I知 not sure if this is a bug or I simply has something
misconfigured in my log4j.xml
Thanks,
Joan.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Joan Balagueró - ventusproxy
2018-08-24 18:32:56 UTC
Permalink
Ok Ralph, understood. With log4j worked, but I suppose that now the implementation is completely different.
Just one more thing, I see you say performance in RollingRandomFile is 20-200% better than RollingRandom. So, in what cases is it better to use RollingFile instead of RollingRandomFile? I understand that with such a high concurrency I have it's better to use RollingRandomFile.

Thanks,
Joan.

-----Mensaje original-----
De: Ralph Goers [mailto:***@dslextreme.com]
Enviado el: viernes, 24 de agosto de 2018 19:18
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile

The TimeBasedTriggeringPolicy does not check for rollover on every log event to reduce the overhead on busy systems. When you are only logging a few events you will see it log a few records to the prior file before it checks for a rollover. In your case you would be better off using the CronTriggeringPolicy as it has a background thread that checks for the time to rollover.

Ralph
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started to
be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,80616,329,25
37,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,140160,328,4
071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same file,
2018-08-22, instead of in a newly created log file 2018-08-24. This is
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,28236,329,12
12,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,gzip,51516,329,1
802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,133122,329,3
903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,205848,329,5
681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,99240,329,30
20,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,34056,327,1
358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,27072,329,11
86,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,82944,327,2
597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,,2700,326,0,256,o
k,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I知 not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Carter Kozak
2018-08-24 18:49:34 UTC
Permalink
Post by Joan Balagueró - ventusproxy
I see you say performance in RollingRandomFile is 20-200% better than RollingRandom
Do you mean "RollingRandomAccessFile is 20-200% better than
RollingFile"? If so, that is correct. If you are using asynchronous
logging, I would recommend setting immediateFlush="false" (the default
value is "true") on the appender to avoid flushing to disk prematurely
under load, which significantly improves throughput.

-ck
On Fri, Aug 24, 2018 at 2:32 PM Joan Balagueró - ventusproxy
Post by Joan Balagueró - ventusproxy
Ok Ralph, understood. With log4j worked, but I suppose that now the implementation is completely different.
Just one more thing, I see you say performance in RollingRandomFile is 20-200% better than RollingRandom. So, in what cases is it better to use RollingFile instead of RollingRandomFile? I understand that with such a high concurrency I have it's better to use RollingRandomFile.
Thanks,
Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:18
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
The TimeBasedTriggeringPolicy does not check for rollover on every log event to reduce the overhead on busy systems. When you are only logging a few events you will see it log a few records to the prior file before it checks for a rollover. In your case you would be better off using the CronTriggeringPolicy as it has a background thread that checks for the time to rollover.
Ralph
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started to
be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,80616,329,25
37,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,140160,328,4
071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same file,
2018-08-22, instead of in a newly created log file 2018-08-24. This is
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,28236,329,12
12,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,gzip,51516,329,1
802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,133122,329,3
903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,205848,329,5
681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,99240,329,30
20,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,34056,327,1
358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,27072,329,11
86,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,82944,327,2
597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,,2700,326,0,256,o
k,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I知 not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Ralph Goers
2018-08-24 19:31:22 UTC
Permalink
It is surprising to me that it would have been any different in Log4j. I believe it used similar logic for rolling over. I’d have to look at the code and check though.

Ralph
Post by Joan Balagueró - ventusproxy
Ok Ralph, understood. With log4j worked, but I suppose that now the implementation is completely different.
Just one more thing, I see you say performance in RollingRandomFile is 20-200% better than RollingRandom. So, in what cases is it better to use RollingFile instead of RollingRandomFile? I understand that with such a high concurrency I have it's better to use RollingRandomFile.
Thanks,
Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:18
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
The TimeBasedTriggeringPolicy does not check for rollover on every log event to reduce the overhead on busy systems. When you are only logging a few events you will see it log a few records to the prior file before it checks for a rollover. In your case you would be better off using the CronTriggeringPolicy as it has a background thread that checks for the time to rollover.
Ralph
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started to
be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,80616,329,25
37,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,140160,328,4
071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same file,
2018-08-22, instead of in a newly created log file 2018-08-24. This is
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,28236,329,12
12,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,gzip,51516,329,1
802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,133122,329,3
903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,205848,329,5
681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,99240,329,30
20,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,34056,327,1
358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,27072,329,11
86,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,82944,327,2
597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,,2700,326,0,256,o
k,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I知 not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Joan Balagueró - ventusproxy
2018-08-24 19:37:41 UTC
Permalink
I promise with log4j, even under this high concurrency, the rotation is perfect. This is the config:

<appender name="ASYNC_ACCESS" class="org.apache.log4j.AsyncAppender">
<param name="bufferSize" value="256"/>
<appender-ref ref="ACCESS_LOG"/>
</appender>


<!-- ACCESS LOG -->
<appender name="ACCESS_LOG" class="org.apache.log4j.rolling.RollingFileAppender">
<param name="append" value="true" />
<param name="encoding" value="ISO-8859-1"/>
<param name="threshold" value="INFO"/>

<param name="immediateFlush" value="false"/>
<param name="bufferedIO" value="true"/>
<param name="bufferSize" value="8192"/>

<rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
<param name="fileNamePattern" value="${log.dir}vproxy_access.%d{yyyy-MM-dd}" />
</rollingPolicy>

<layout class="org.apache.log4j.PatternLayout">
<param name="conversionPattern" value="%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n"/>
</layout>
</appender>

<logger name="LOGGER_ACCESS" additivity="false">
<level value="info"/>
<appender-ref ref="ASYNC_ACCESS"/>
</logger>

-----Mensaje original-----
De: Ralph Goers [mailto:***@dslextreme.com]
Enviado el: viernes, 24 de agosto de 2018 21:31
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile

It is surprising to me that it would have been any different in Log4j. I believe it used similar logic for rolling over. I’d have to look at the code and check though.

Ralph
Post by Joan Balagueró - ventusproxy
Ok Ralph, understood. With log4j worked, but I suppose that now the implementation is completely different.
Just one more thing, I see you say performance in RollingRandomFile is 20-200% better than RollingRandom. So, in what cases is it better to use RollingFile instead of RollingRandomFile? I understand that with such a high concurrency I have it's better to use RollingRandomFile.
Thanks,
Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:18
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
The TimeBasedTriggeringPolicy does not check for rollover on every log event to reduce the overhead on busy systems. When you are only logging a few events you will see it log a few records to the prior file before it checks for a rollover. In your case you would be better off using the CronTriggeringPolicy as it has a background thread that checks for the time to rollover.
Ralph
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,80616,329,2
5
37,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,140160,328,
4
071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,28236,329,1
2
12,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,gzip,51516,329,
1
802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,133122,329,
3
903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,205848,329,
5
681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,99240,329,3
0
20,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,34056,327,
1
358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80,gzip,27072,329,1
1
86,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80,gzip,82944,327,
2
597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,,2700,326,0,256,
o
k,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I知 not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Matt Sicker
2018-08-24 17:18:29 UTC
Permalink
I don't think your filePattern value is correct. You should be using format
specifiers from SimpleDateFormat there, not PatternLayout. Or you could put
the date in a $${} to delay expansion it looks like.

On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the vproxy_access.2018-08-22 was
correctly created and requests started to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is these
requests (sent today, day 24) have been logged on the same file, 2018-08-22,
instead of in a newly created log file 2018-08-24. This is the moment (2
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24 instead of
2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has something
misconfigured in my log4j.xml
Thanks,
Joan.
--
Matt Sicker <***@gmail.com>
Ralph Goers
2018-08-24 17:24:07 UTC
Permalink
Matt, I don’t see anything wrong with the file pattern.

Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using format
specifiers from SimpleDateFormat there, not PatternLayout. Or you could put
the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the vproxy_access.2018-08-22 was
correctly created and requests started to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is these
requests (sent today, day 24) have been logged on the same file, 2018-08-22,
instead of in a newly created log file 2018-08-24. This is the moment (2
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24 instead of
2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has something
misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Joan Balagueró - ventusproxy
2018-08-24 17:57:00 UTC
Permalink
I though of using the CronTriggeringPolicy, but I'm logging more than 10 thousands lines per second. If only one line log is not logged at the correct file, everything will go wrong.

So using the CronTriggeringPolicy to rollover at midnight, have I the guarantee that the last line of 20180825 will be logged on vproxy_access.2018-08-25 and the first line of 20180826 will be logged on vproxy_access.2018-08-26?

Thanks,

Joan.

-----Mensaje original-----
De: Ralph Goers [mailto:***@dslextreme.com]
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile

Matt, I don’t see anything wrong with the file pattern.

Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Ralph Goers
2018-08-24 18:22:05 UTC
Permalink
No. It is impossible to guarantee that as the rollover will be triggered on one thread while you are logging on others, so some events might happen before the rollover process causes events to go to a new file. If you are logging at that volume I would expect CronTriggeringPolicy and TimeBasedTriggeringPolicy to behave about the same.

Ralph
Post by Joan Balagueró - ventusproxy
I though of using the CronTriggeringPolicy, but I'm logging more than 10 thousands lines per second. If only one line log is not logged at the correct file, everything will go wrong.
So using the CronTriggeringPolicy to rollover at midnight, have I the guarantee that the last line of 20180825 will be logged on vproxy_access.2018-08-25 and the first line of 20180826 will be logged on vproxy_access.2018-08-26?
Thanks,
Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Matt Sicker
2018-08-24 19:31:52 UTC
Permalink
Matt, I don’t see anything wrong with the file pattern.
From the manual:

The pattern of the file name of the archived log file. The format of the
pattern is dependent on the RolloverPolicy that is used. The
DefaultRolloverPolicy will accept both a date/time pattern compatible with
SimpleDateFormat and/or a %i which represents an integer counter. The
pattern also supports interpolation at runtime so any of the Lookups (such
as the DateLookup) can be included in the pattern.
This doesn't make any sense if you're not directly quoting everything that
isn't a date format character. In fact, this doesn't tell you how to even
insert the pattern at all unless you find random examples of how it
actually works in other parts of the manual.
--
Matt Sicker <***@gmail.com>
Joan Balagueró - ventusproxy
2018-08-24 19:43:19 UTC
Permalink
Sorry, is the pattern ok or not? Thanks, Joan.

-----Mensaje original-----
De: Ralph Goers [mailto:***@dslextreme.com]
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile

Matt, I don’t see anything wrong with the file pattern.

Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Ralph Goers
2018-08-24 20:47:45 UTC
Permalink
Yes, the pattern is OK. What is meant by the reference to the SimpleDateFormat is that you should using the pattern characters for SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the %d to figure out what the rollover interval is. If you use ${pattern} it will be part of the file name but won’t impact the rollover interval.

Ralph
Post by Joan Balagueró - ventusproxy
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Joan Balagueró - ventusproxy
2018-08-24 23:37:10 UTC
Permalink
Hello,
No luck. I tried with DateLookup, but it doesn't work:
<RollingRandomAccessFile name="ACCESS_LOG" filePattern="${sys:log.dir}vproxy_access.$${date:yyyy-MM-dd}" append="true" immediateFlush="false">

I get: 2018-08-25 00:21:39,881 localhost-startStop-1 ERROR Could not create plugin of type class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: Pattern does not contain a date java.lang.IllegalStateException: Pattern does not contain a date

Obviously there is something here I don't understand. What should I use in filePattern to get the daily rotation working?

Thanks again,
Joan

-----Mensaje original-----
De: Ralph Goers [mailto:***@dslextreme.com]
Enviado el: viernes, 24 de agosto de 2018 22:48
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile

Yes, the pattern is OK. What is meant by the reference to the SimpleDateFormat is that you should using the pattern characters for SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the %d to figure out what the rollover interval is. If you use ${pattern} it will be part of the file name but won’t impact the rollover interval.

Ralph
Post by Joan Balagueró - ventusproxy
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Ralph Goers
2018-08-25 00:25:24 UTC
Permalink
That problem is because your original pattern was correct.

Ralph
Post by Joan Balagueró - ventusproxy
Hello,
<RollingRandomAccessFile name="ACCESS_LOG" filePattern="${sys:log.dir}vproxy_access.$${date:yyyy-MM-dd}" append="true" immediateFlush="false">
I get: 2018-08-25 00:21:39,881 localhost-startStop-1 ERROR Could not create plugin of type class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: Pattern does not contain a date java.lang.IllegalStateException: Pattern does not contain a date
Obviously there is something here I don't understand. What should I use in filePattern to get the daily rotation working?
Thanks again,
Joan
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 22:48
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Yes, the pattern is OK. What is meant by the reference to the SimpleDateFormat is that you should using the pattern characters for SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the %d to figure out what the rollover interval is. If you use ${pattern} it will be part of the file name but won’t impact the rollover interval.
Ralph
Post by Joan Balagueró - ventusproxy
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Matt Sicker
2018-08-25 01:07:52 UTC
Permalink
Right, I confused the syntax a bit. I should update the manual so I stop
confusing myself every time a question about rolling files comes up.
Post by Ralph Goers
That problem is because your original pattern was correct.
Ralph
On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy <
Hello,
<RollingRandomAccessFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.$${date:yyyy-MM-dd}"
append="true" immediateFlush="false">
I get: 2018-08-25 00:21:39,881 localhost-startStop-1 ERROR Could not
create plugin of type class
org.apache.logging.log4j.core.appender.RollingFileAppender for element
RollingFile: java.lang.IllegalStateException: Pattern does not contain a
date java.lang.IllegalStateException: Pattern does not contain a date
Obviously there is something here I don't understand. What should I use
in filePattern to get the daily rotation working?
Thanks again,
Joan
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 22:48
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Yes, the pattern is OK. What is meant by the reference to the
SimpleDateFormat is that you should using the pattern characters for
SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the %d to
figure out what the rollover interval is. If you use ${pattern} it will be
part of the file name but won’t impact the rollover interval.
Ralph
On Aug 24, 2018, at 12:43 PM, Joan Balagueró - ventusproxy <
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
I’m using RollingFileAppender with full async logging. This is the
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
At 00:00 rotation is performed, this is the new log file (it’s
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
--
Matt Sicker <***@gmail.com>
Ralph Goers
2018-08-25 03:03:04 UTC
Permalink
As to the question about log4j 1


I looked at the RollingFileAppender in the log4j project. It only supports rolling on file size and doesn’t support time-based rolling at all. The RollingFileAppender in log4j-extras does support rolling on time and would get the behavior you are looking for. However, this comes with a very large cost as Log4j 1 locks every call to an appender so only 1 thread can be writing at a time. This will have serious consequences on performance in multi-threaded applications and was the source of one of Log4j 1’s fundamental problems - it could get in a deadlock. Google shows many examples as many people experienced this problem. Here are just the first few:

https://dzone.com/articles/log4j-thread-deadlock-case <https://dzone.com/articles/log4j-thread-deadlock-case>
https://stackoverflow.com/questions/7157507/log4j-deadlock-occuring-between-logger-and-appender <https://stackoverflow.com/questions/7157507/log4j-deadlock-occuring-between-logger-and-appender>
https://bz.apache.org/bugzilla/show_bug.cgi?id=41214 <https://bz.apache.org/bugzilla/show_bug.cgi?id=41214> (mentions Log4j 2 as a solution for the problem)

The consequences of the fix in Log4j 2 is that it is now fully thread-safe, does not require locking, but by doing so cannot guarantee that events won’t continue to be written after the rollover time occurs simply because they are not blocked except while the check for rollover and/or the actual rollover are taking place. We could implement a patch to allow the check for rollover to occur on every event, which would probably solve your problem, but the cost would be decreased performance.

Ralph
Post by Matt Sicker
Right, I confused the syntax a bit. I should update the manual so I stop
confusing myself every time a question about rolling files comes up.
Post by Ralph Goers
That problem is because your original pattern was correct.
Ralph
On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy <
Hello,
<RollingRandomAccessFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.$${date:yyyy-MM-dd}"
append="true" immediateFlush="false">
I get: 2018-08-25 00:21:39,881 localhost-startStop-1 ERROR Could not
create plugin of type class
org.apache.logging.log4j.core.appender.RollingFileAppender for element
RollingFile: java.lang.IllegalStateException: Pattern does not contain a
date java.lang.IllegalStateException: Pattern does not contain a date
Obviously there is something here I don't understand. What should I use
in filePattern to get the daily rotation working?
Thanks again,
Joan
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 22:48
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Yes, the pattern is OK. What is meant by the reference to the
SimpleDateFormat is that you should using the pattern characters for
SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the %d to
figure out what the rollover interval is. If you use ${pattern} it will be
part of the file name but won’t impact the rollover interval.
Ralph
On Aug 24, 2018, at 12:43 PM, Joan Balagueró - ventusproxy <
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be using
format specifiers from SimpleDateFormat there, not PatternLayout. Or
you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
I’m using RollingFileAppender with full async logging. This is the
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests started
to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point is
these requests (sent today, day 24) have been logged on the same
file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
At 00:00 rotation is performed, this is the new log file (it’s
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
---------------------------------------------------------------------
--
Joan Balagueró - ventusproxy
2018-09-05 22:10:34 UTC
Permalink
Hi Ralph, Matt

Now using log4j2 RollingRandomAccessFile, with a <CronTriggeringPolicy schedule="0 0 0 * * ?" evaluateOnStartup="true" />

These are the last 5 lines of the log file for 2018-09-05 (once rotated):

[***@server02 logs]# tail -f vproxy_access.2018-09-05
1,192.168.1.248,2018-09-05 23:59:58.816,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,,105060,328,0,1135,ok,2018-09-05 23:59:59.963
1,192.168.1.248,2018-09-05 23:59:59.477,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,135468,328,3959,468,ok,2018-09-05 23:59:59.963
1,192.168.1.248,2018-09-05 23:59:59.204,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,,181215,328,0,744,ok,2018-09-05 23:59:59.964
1,192.168.1.248,2018-09-05 23:59:58.979,A,13,A,39,A,72,A,60,N,,167.114.89.182:80,gzip,177696,329,4983,978,ok,2018-09-05 23:59:59.966
1,192.168.1.248,2018-09-05 23:59:59.799,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,deflate,79452,327,2497,163,ok,2018-09-05 23:59:59.970
1,192.168.1.248,2018-09-05 23:59:59.677,A,13,A,39,A,72,A,60,N,,167.114.89.182:80,,32892,329,0,293,ok,2018-09-05 23:59:59.975
1,192.168.1.248,2018-09-05 23:59:59.477,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,,98076,329,0,493,ok,2018-09-05 23:59:59.976

And these are the first 3 lines of the current log file:

[***@server02 logs]# more vproxy_access
1,192.168.1.248,2018-09-05 23:59:58.579,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,gzip,56172,327,1916,1418,ok,2018-09-06 00:00:00.011
1,192.168.1.248,2018-09-05 23:59:59.695,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,deflate,219924,328,6021,295,ok,2018-09-06 00:00:00.021
1,192.168.1.248,2018-09-05 23:59:59.361,A,13,A,39,A,72,A,60,N,,167.114.89.182:80,deflate,156582,329,4459,638,ok,2018-09-06 00:00:00.021


There are 35ms between the last line of 2018-09-05 (23:59:59.976) and the first line of 2018-09-06 (00:00:00.011). I think it's too much time for not having some requests within this interval.

Is it possible that log lines coming exactly when the rotation is occurring are being lost?

Thanks,

Joan.


-----Mensaje original-----
De: Ralph Goers [mailto:***@dslextreme.com]
Enviado el: sábado, 25 de agosto de 2018 5:03
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile

As to the question about log4j 1…

I looked at the RollingFileAppender in the log4j project. It only supports rolling on file size and doesn’t support time-based rolling at all. The RollingFileAppender in log4j-extras does support rolling on time and would get the behavior you are looking for. However, this comes with a very large cost as Log4j 1 locks every call to an appender so only 1 thread can be writing at a time. This will have serious consequences on performance in multi-threaded applications and was the source of one of Log4j 1’s fundamental problems - it could get in a deadlock. Google shows many examples as many people experienced this problem. Here are just the first few:

https://dzone.com/articles/log4j-thread-deadlock-case <https://dzone.com/articles/log4j-thread-deadlock-case>
https://stackoverflow.com/questions/7157507/log4j-deadlock-occuring-between-logger-and-appender <https://stackoverflow.com/questions/7157507/log4j-deadlock-occuring-between-logger-and-appender>
https://bz.apache.org/bugzilla/show_bug.cgi?id=41214 <https://bz.apache.org/bugzilla/show_bug.cgi?id=41214> (mentions Log4j 2 as a solution for the problem)

The consequences of the fix in Log4j 2 is that it is now fully thread-safe, does not require locking, but by doing so cannot guarantee that events won’t continue to be written after the rollover time occurs simply because they are not blocked except while the check for rollover and/or the actual rollover are taking place. We could implement a patch to allow the check for rollover to occur on every event, which would probably solve your problem, but the cost would be decreased performance.

Ralph
Post by Matt Sicker
Right, I confused the syntax a bit. I should update the manual so I
stop confusing myself every time a question about rolling files comes up.
On Fri, Aug 24, 2018 at 19:25, Ralph Goers
Post by Ralph Goers
That problem is because your original pattern was correct.
Ralph
On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy <
Hello,
<RollingRandomAccessFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.$${date:yyyy-MM-dd}"
append="true" immediateFlush="false">
I get: 2018-08-25 00:21:39,881 localhost-startStop-1 ERROR Could not
create plugin of type class
org.apache.logging.log4j.core.appender.RollingFileAppender for element
RollingFile: java.lang.IllegalStateException: Pattern does not
contain a date java.lang.IllegalStateException: Pattern does not
contain a date
Obviously there is something here I don't understand. What should I use
in filePattern to get the daily rotation working?
Thanks again,
Joan
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 22:48
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Yes, the pattern is OK. What is meant by the reference to the
SimpleDateFormat is that you should using the pattern characters for
SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the
%d to figure out what the rollover interval is. If you use ${pattern}
it will be part of the file name but won’t impact the rollover interval.
Ralph
On Aug 24, 2018, at 12:43 PM, Joan Balagueró - ventusproxy <
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be
using format specifiers from SimpleDateFormat there, not
PatternLayout. Or you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
I’m using RollingFileAppender with full async logging. This is
the
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests
started to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point
is these requests (sent today, day 24) have been logged on the
same file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
At 00:00 rotation is performed, this is the new log file (it’s
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
-------------------------------------------------------------------
-------------------------------------------------------------------
--------------------------------------------------------------------
--------------------------------------------------------------------
---------------------------------------------------------------------
--
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Ralph Goers
2018-09-05 23:08:41 UTC
Permalink
That should not happen. A lock is acquired during rollover so anything logging should wait.

Ralph
Post by Joan Balagueró - ventusproxy
Hi Ralph, Matt
Now using log4j2 RollingRandomAccessFile, with a <CronTriggeringPolicy schedule="0 0 0 * * ?" evaluateOnStartup="true" />
1,192.168.1.248,2018-09-05 23:59:58.816,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,,105060,328,0,1135,ok,2018-09-05 23:59:59.963
1,192.168.1.248,2018-09-05 23:59:59.477,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,gzip,135468,328,3959,468,ok,2018-09-05 23:59:59.963
1,192.168.1.248,2018-09-05 23:59:59.204,A,13,A,39,A,72,A,60,N,,192.168.1.248:80,,181215,328,0,744,ok,2018-09-05 23:59:59.964
1,192.168.1.248,2018-09-05 23:59:58.979,A,13,A,39,A,72,A,60,N,,167.114.89.182:80,gzip,177696,329,4983,978,ok,2018-09-05 23:59:59.966
1,192.168.1.248,2018-09-05 23:59:59.799,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,deflate,79452,327,2497,163,ok,2018-09-05 23:59:59.970
1,192.168.1.248,2018-09-05 23:59:59.677,A,13,A,39,A,72,A,60,N,,167.114.89.182:80,,32892,329,0,293,ok,2018-09-05 23:59:59.975
1,192.168.1.248,2018-09-05 23:59:59.477,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,,98076,329,0,493,ok,2018-09-05 23:59:59.976
1,192.168.1.248,2018-09-05 23:59:58.579,A,13,A,41,A,72,A,60,N,,192.168.1.248:80,gzip,56172,327,1916,1418,ok,2018-09-06 00:00:00.011
1,192.168.1.248,2018-09-05 23:59:59.695,A,13,A,40,A,72,A,60,N,,167.114.89.182:80,deflate,219924,328,6021,295,ok,2018-09-06 00:00:00.021
1,192.168.1.248,2018-09-05 23:59:59.361,A,13,A,39,A,72,A,60,N,,167.114.89.182:80,deflate,156582,329,4459,638,ok,2018-09-06 00:00:00.021
There are 35ms between the last line of 2018-09-05 (23:59:59.976) and the first line of 2018-09-06 (00:00:00.011). I think it's too much time for not having some requests within this interval.
Is it possible that log lines coming exactly when the rotation is occurring are being lost?
Thanks,
Joan.
-----Mensaje original-----
Enviado el: sábado, 25 de agosto de 2018 5:03
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
As to the question about log4j 1…
https://dzone.com/articles/log4j-thread-deadlock-case <https://dzone.com/articles/log4j-thread-deadlock-case>
https://stackoverflow.com/questions/7157507/log4j-deadlock-occuring-between-logger-and-appender <https://stackoverflow.com/questions/7157507/log4j-deadlock-occuring-between-logger-and-appender>
https://bz.apache.org/bugzilla/show_bug.cgi?id=41214 <https://bz.apache.org/bugzilla/show_bug.cgi?id=41214> (mentions Log4j 2 as a solution for the problem)
The consequences of the fix in Log4j 2 is that it is now fully thread-safe, does not require locking, but by doing so cannot guarantee that events won’t continue to be written after the rollover time occurs simply because they are not blocked except while the check for rollover and/or the actual rollover are taking place. We could implement a patch to allow the check for rollover to occur on every event, which would probably solve your problem, but the cost would be decreased performance.
Ralph
Post by Matt Sicker
Right, I confused the syntax a bit. I should update the manual so I
stop confusing myself every time a question about rolling files comes up.
On Fri, Aug 24, 2018 at 19:25, Ralph Goers
Post by Ralph Goers
That problem is because your original pattern was correct.
Ralph
On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy <
Hello,
<RollingRandomAccessFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.$${date:yyyy-MM-dd}"
append="true" immediateFlush="false">
I get: 2018-08-25 00:21:39,881 localhost-startStop-1 ERROR Could not
create plugin of type class
org.apache.logging.log4j.core.appender.RollingFileAppender for element
RollingFile: java.lang.IllegalStateException: Pattern does not
contain a date java.lang.IllegalStateException: Pattern does not
contain a date
Obviously there is something here I don't understand. What should I use
in filePattern to get the daily rotation working?
Thanks again,
Joan
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 22:48
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Yes, the pattern is OK. What is meant by the reference to the
SimpleDateFormat is that you should using the pattern characters for
SimpleDateFormat inside %d{}. TimeBasedTriggeringPolicy requires the
%d to figure out what the rollover interval is. If you use ${pattern}
it will be part of the file name but won’t impact the rollover interval.
Ralph
On Aug 24, 2018, at 12:43 PM, Joan Balagueró - ventusproxy <
Sorry, is the pattern ok or not? Thanks, Joan.
-----Mensaje original-----
Enviado el: viernes, 24 de agosto de 2018 19:24
Para: Log4J Users List
Asunto: Re: Problem with daily rotation on log4j2 RollingFile
Matt, I don’t see anything wrong with the file pattern.
Ralph
Post by Matt Sicker
I don't think your filePattern value is correct. You should be
using format specifiers from SimpleDateFormat there, not
PatternLayout. Or you could put the date in a $${} to delay expansion it looks like.
On Fri, 24 Aug 2018 at 11:30, Joan Balagueró - ventusproxy <
Post by Joan Balagueró - ventusproxy
Hello,
I’m using RollingFileAppender with full async logging. This is
the
<Appenders>
<RollingFile name="ACCESS_LOG"
filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" append="true"
immediateFlush="false">
<PatternLayout>
<Pattern>%m%d{yyyy-MM-dd HH:mm:ss.SSS}%n</Pattern>
</PatternLayout>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingFile>
<Appenders>
<Loggers>
<Root level="off" additivity="false" />
<Logger name="LOGGER_ACCESS" level="info" includeLocation="false"
additivity="false">
<AppenderRef ref="ACCESS_LOG"/>
</Logger>
</Loggers>
I started to send requests the 2018-08-22, the
vproxy_access.2018-08-22 was correctly created and requests
started to be logged. These are the first 2
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,80616,329,2537,202
,ok,2018-08-22 18:11:30.735
1,192.168.1.248,2018-08-22
18:11:30.171,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,140160,328,4071,45
2,ok,2018-08-22 18:11:30.744
Then I stopped to send requests until 2018-08-24 12:25. The point
is these requests (sent today, day 24) have been logged on the
same file, 2018-08-22, instead of in a newly created log file 2018-08-24.
1,192.168.1.248,2018-08-22
18:59:23.415,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,28236,329,1212,121
,ok,2018-08-22 18:59:23.537
1,192.168.1.248,2018-08-22
18:59:23.537,A,13,A,40,A,72,A,60,N,,167.114.89.182:80
,gzip,51516,329,1802,43
7,ok,2018-08-22 18:59:23.977
1,192.168.1.248,2018-08-24
12:25:42.439,A,13,A,39,A,72,A,60,N,,192.168.1.248:80
,gzip,133122,329,3903,18
,ok,2018-08-24 12:25:42.466
1,192.168.1.248,2018-08-24
12:25:42.428,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,205848,329,5681,30
,ok,2018-08-24 12:25:42.471
1,192.168.1.248,2018-08-24
23:59:58.851,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,99240,329,3020,472
,ok,2018-08-24 23:59:59.326
1,192.168.1.248,2018-08-24
23:59:59.326,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,34056,327,1358,46
7,ok,2018-08-24 23:59:59.795
At 00:00 rotation is performed, this is the new log file (it’s
1,192.168.1.248,2018-08-24
23:59:59.796,A,13,A,40,A,72,A,60,N,,192.168.1.248:80
,gzip,27072,329,1186,392
,ok,2018-08-25 00:00:00.189
1,192.168.1.248,2018-08-25
00:00:00.190,A,13,A,41,A,72,A,60,N,,167.114.89.182:80
,gzip,82944,327,2597,48
7,ok,2018-08-25 00:00:00.680
1,192.168.1.248,2018-08-25
00:00:00.681,A,13,A,41,A,72,A,60,N,,192.168.1.248:80
,,2700,326,0,256,ok,2018
-08-25 00:00:00.937
But the problem is this log file has been created as 2018-08-24
instead of 2018-08-25.
-rw-r-----. 1 root root 4382871 Aug 24 23:59
vproxy_access.2018-08-22
-rw-r-----. 1 root root 16224 Aug 25 00:00
vproxy_access.2018-08-24
Sat Aug 25 00:17:37 EDT 2018
So at this point I’m not sure if this is a bug or I simply has
something misconfigured in my log4j.xml
Thanks,
Joan.
--
-------------------------------------------------------------------
-------------------------------------------------------------------
--------------------------------------------------------------------
--------------------------------------------------------------------
---------------------------------------------------------------------
--
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-***@logging.apache.org
For additional commands, e-mail: log4j-user-***@logging.apache.org
Loading...