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 > <[email protected]> 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:[email protected]] > 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 <[email protected]> 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 >> <[email protected]> >> wrote: >> >>> That problem is because your original pattern was correct. >>> >>> Ralph >>> >>>> On Aug 24, 2018, at 4:37 PM, Joan Balagueró - ventusproxy < >>> [email protected]> 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:[email protected]] >>>> 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 < >>> [email protected]> wrote: >>>>> >>>>> Sorry, is the pattern ok or not? Thanks, Joan. >>>>> >>>>> -----Mensaje original----- >>>>> De: Ralph Goers [mailto:[email protected]] >>>>> 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 <[email protected]> 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 < >>>>>> [email protected]> 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 <[email protected]> >>>>> >>>>> >>>>> >>>>> ------------------------------------------------------------------- >>>>> -- To unsubscribe, e-mail: >>>>> [email protected] >>>>> For additional commands, e-mail: [email protected] >>>>> >>>>> >>>>> >>>>> >>>>> ------------------------------------------------------------------- >>>>> -- To unsubscribe, e-mail: >>>>> [email protected] >>>>> For additional commands, e-mail: [email protected] >>>>> >>>>> >>>> >>>> >>>> >>>> -------------------------------------------------------------------- >>>> - To unsubscribe, e-mail: [email protected] >>>> For additional commands, e-mail: [email protected] >>>> >>>> >>>> >>>> >>>> -------------------------------------------------------------------- >>>> - To unsubscribe, e-mail: [email protected] >>>> For additional commands, e-mail: [email protected] >>>> >>>> >>> >>> >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: [email protected] >>> For additional commands, e-mail: [email protected] >>> >>> -- >> Matt Sicker <[email protected]> > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
