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@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@company.com</to> <from>Jetty Errors <jetty-errors@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@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 Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user