[logback-user] RollingFileAppender overwriting old files

Sean Rhea sean.c.rhea at gmail.com
Mon Jul 22 23:23:59 CEST 2013 

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20130722/86be9e2d/attachment.html>
-------------- next part --------------
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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: logback.xml
Type: text/xml
Size: 1217 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20130722/86be9e2d/attachment.xml>

More information about the Logback-user mailing list