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 <[email protected]> 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>[email protected]</to> > <from>Jetty Errors <[email protected]></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@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@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@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 > [email protected] > http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________ Logback-user mailing list [email protected] http://mailman.qos.ch/mailman/listinfo/logback-user
