You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Joan Balagueró - ventusproxy <jo...@ventusproxy.com> on 2018/09/05 22:10:34 UTC
RE: Problem with daily rotation on log4j2 RollingFile
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):
[root@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:
[root@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:ralph.goers@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
> On Aug 24, 2018, at 6:07 PM, Matt Sicker <bo...@gmail.com> wrote:
>
> 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
> <ra...@dslextreme.com>
> wrote:
>
>> That problem is because your original pattern was correct.
>>
>> Ralph
>>
>>> On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy <
>> joan.balaguero@ventusproxy.com> wrote:
>>>
>>> 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:ralph.goers@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
>>>
>>>> On Aug 24, 2018, at 12:43 PM, Joan Balagueró - ventusproxy <
>> joan.balaguero@ventusproxy.com> wrote:
>>>>
>>>> Sorry, is the pattern ok or not? Thanks, Joan.
>>>>
>>>> -----Mensaje original-----
>>>> De: Ralph Goers [mailto:ralph.goers@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
>>>>
>>>>> On Aug 24, 2018, at 10:18 AM, Matt Sicker <bo...@gmail.com> wrote:
>>>>>
>>>>> 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 <
>>>>> joan.balaguero@ventusproxy.com> wrote:
>>>>>
>>>>>> 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:
>>>>>>
>>>>>> [root@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.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>> --
>>>>> Matt Sicker <bo...@gmail.com>
>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> -- To unsubscribe, e-mail:
>>>> log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> -- To unsubscribe, e-mail:
>>>> log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>>
>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>> --
> Matt Sicker <bo...@gmail.com>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Problem with daily rotation on log4j2 RollingFile
Posted by Ralph Goers <ra...@dslextreme.com>.
That should not happen. A lock is acquired during rollover so anything logging should wait.
Ralph
> On Sep 5, 2018, at 3:10 PM, Joan Balagueró - ventusproxy <jo...@ventusproxy.com> wrote:
>
> 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):
>
> [root@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:
>
> [root@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:ralph.goers@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
>
>
>
>> On Aug 24, 2018, at 6:07 PM, Matt Sicker <bo...@gmail.com> wrote:
>>
>> 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
>> <ra...@dslextreme.com>
>> wrote:
>>
>>> That problem is because your original pattern was correct.
>>>
>>> Ralph
>>>
>>>> On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy <
>>> joan.balaguero@ventusproxy.com> wrote:
>>>>
>>>> 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:ralph.goers@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
>>>>
>>>>> On Aug 24, 2018, at 12:43 PM, Joan Balagueró - ventusproxy <
>>> joan.balaguero@ventusproxy.com> wrote:
>>>>>
>>>>> Sorry, is the pattern ok or not? Thanks, Joan.
>>>>>
>>>>> -----Mensaje original-----
>>>>> De: Ralph Goers [mailto:ralph.goers@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
>>>>>
>>>>>> On Aug 24, 2018, at 10:18 AM, Matt Sicker <bo...@gmail.com> wrote:
>>>>>>
>>>>>> 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 <
>>>>>> joan.balaguero@ventusproxy.com> wrote:
>>>>>>
>>>>>>> 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:
>>>>>>>
>>>>>>> [root@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.
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>> --
>>>>>> Matt Sicker <bo...@gmail.com>
>>>>>
>>>>>
>>>>>
>>>>> -------------------------------------------------------------------
>>>>> -- To unsubscribe, e-mail:
>>>>> log4j-user-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> -------------------------------------------------------------------
>>>>> -- To unsubscribe, e-mail:
>>>>> log4j-user-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>> --------------------------------------------------------------------
>>>> - To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>>
>>>>
>>>>
>>>> --------------------------------------------------------------------
>>>> - To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>>
>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>> --
>> Matt Sicker <bo...@gmail.com>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org