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.
<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>
<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>
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