[logback-user] RollingFileAppender overwriting old files

Tue Jul 23 09:49:44 CEST 2013

Sean,

Can you reproduce in a small sample project? Perhaps one that logs every 10 seconds, and rolls every minute?

If you can get that to exhibit the behaviour, then we have a better chance of tracking bug down.

Other than that, does the problem go away when you remove the SMTP appender?

David

On 22 Jul 2013, at 22:23, Sean Rhea <sean.c.rhea at gmail.com> wrote:

> All,
> 
> I'm using RollingFileAppender under jetty, and it occasionally seems to overwrite the contents of log files it has rotated in the past. My logback configuration is attached. Also attached is a terminal session in which you can see that the first line of the rotated log files *usually* is from the right timeframe, but occasionally is from a completely different time. For example, the file named jetty/logs/app.2013-07-22-1000.log contains a log message from the 1300 hour. In those cases, the messages that were once in that log file have been overwritten. Also in that terminal session is the contents of /proc/xxx/fd for the jetty process, where you can see that the process is maintaining open file descriptors to past rotated files. That seems like a bug to me. I see this same behavior with both logback versions 0.9.28 and 1.0.13. I'm using jetty 7.3.1.v20110307.
> 
> I would appreciate any pointers you could give to help me track this down. If it's just a simple misconfiguration on my part, I'd love to know that, too, of course. I've searched for past mentions of this behavior and haven't found one. Apologies if I overlooked any that exist.
> 
> Thanks,
> Sean
> 
> 
> === Configuration ===
> 
> <configuration>
>   <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
>     <file>logs/nmr.log</file>
>     <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
>       <fileNamePattern>logs/nmr.%d{yyyy-MM-dd-HH}00.log</fileNamePattern>
>       <maxHistory>672</maxHistory>
>     </rollingPolicy>
>     <encoder>
>       <pattern>%date [%thread] %-5level %msg%n</pattern>
>     </encoder>
>   </appender>
>   <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender">
>     <evaluator class="RateLimitingEvaluator" />
>     <smtpHost>localhost</smtpHost>
>     <to>jetty-errors at company.com</to>
>     <from>Jetty Errors <jetty-errors at company.com></from>
>     <subject>%mdc{environment} %mdc{shard} error: %msg</subject>
>     <layout class="ch.qos.logback.classic.PatternLayout">
>       <pattern>Date: %date%n{}Message: %msg%n{}Context: %mdc%n</pattern>
>     </layout>
>     <cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTrackerImpl">
>       <bufferSize>1</bufferSize> <!-- send just one log entry per email -->
>     </cyclicBufferTracker>
>   </appender>
>   <root level="INFO">
>     <appender-ref ref="FILE" />
>     <appender-ref ref="EMAIL" />
>   </root>
> </configuration>
> 
> 
> === Notes from terminal session ===
> 
> user at host:/var/local/webapp$ head -1 jetty/logs/app.2013-07-22-*
> ==> jetty/logs/app.2013-07-22-0000.log <==
> 2013-07-22 00:00:06,253 [qtp28715691-220085] INFO ...
> ==> jetty/logs/app.2013-07-22-0100.log <==
> 2013-07-22 01:00:04,447 [qtp28715691-220283] INFO ...
> ==> jetty/logs/app.2013-07-22-0200.log <==
> 2013-07-22 10:00:04,406 [qtp28715691-221647] INFO ...
> ==> jetty/logs/app.2013-07-22-0300.log <==
> 2013-07-22 03:00:00,047 [qtp28715691-220456] INFO ...
> ==> jetty/logs/app.2013-07-22-0400.log <==
> 2013-07-22 04:00:00,621 [qtp28715691-220497] INFO ...
> ==> jetty/logs/app.2013-07-22-0500.log <==
> 2013-07-22 05:00:03,765 [qtp28715691-220332] INFO ...
> ==> jetty/logs/app.2013-07-22-0600.log <==
> 2013-07-22 06:00:02,535 [qtp28715691-220805] INFO ...
> ==> jetty/logs/app.2013-07-22-0700.log <==
> 2013-07-22 07:00:02,687 [qtp28715691-221141] INFO ...
> ==> jetty/logs/app.2013-07-22-0800.log <==
> 2013-07-22 08:00:00,891 [qtp28715691-220805] INFO ...
> ==> jetty/logs/app.2013-07-22-0900.log <==
> 2013-07-22 09:00:00,537 [qtp28715691-221493] INFO ...
> ==> jetty/logs/app.2013-07-22-1000.log <==
> 2013-07-22 13:00:00,000 [qtp28715691-222323] INFO ...
> ==> jetty/logs/app.2013-07-22-1100.log <==
> 2013-07-22 11:00:02,096 [qtp28715691-221933] INFO ...
> ==> jetty/logs/app.2013-07-22-1200.log <==
> 2013-07-22 12:00:00,054 [qtp28715691-222149] INFO ...
> ==> jetty/logs/app.2013-07-22-1300.log <==
> 2013-07-22 13:12:57,841 [qtp28715691-222370] INFO ...
> user at host:/var/local/webapp$ ps auxww | grep -v grep | grep jetty
> jetty   13570  2.8  1.3 1153892 870036 ?      Sl   May13 2832:30 /usr/bin/java -Xss1m -Xmx128m -Duser.timezone=America/Los_Angeles -Djetty.port=30800 -jar start.jar
> user at host:/var/local/webapp$ sudo ls -l /proc/13570/fd | grep 'app\.'
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 102 -> /var/local/webapp/jetty/logs/app.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 105 -> /var/local/webapp/jetty/logs/app.2013-06-12-1400.log (deleted)
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 112 -> /var/local/webapp/jetty/logs/app.2013-06-26-1600.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 118 -> /var/local/webapp/jetty/logs/app.2013-07-17-1600.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 122 -> /var/local/webapp/jetty/logs/app.2013-06-11-1100.log (deleted)
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 130 -> /var/local/webapp/jetty/logs/app.2013-07-22-0200.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 144 -> /var/local/webapp/jetty/logs/app.2013-07-22-1000.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 20 -> /var/local/webapp/jetty/logs/app.2013-07-15-1400.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 4 -> /var/local/webapp/jetty/logs/app.2013-07-22-1300.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 85 -> /var/local/webapp/jetty/logs/app.2013-07-10-1200.log
> l-wx------ 1 jetty jetty 64 Jul 22 14:03 99 -> /var/local/webapp/jetty/logs/app.2013-07-10-1000.log
> 
> 
> <logback.txt><logback.xml>_______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20130723/b132a76d/attachment.html>