[logback-user] RollingFileAppender dropping messages

5 May 2016

      Greetings, logback-users.

We recently switched from log4j to logback, and have observed some
concerning behavior with RollingFileAppender - namely, it seems to be
dropping log messages in what turns out to be a predictable manner. I'm
including a simple test program that I wrote to illustrate the issue.
Basically, the output of the test program indicates that the
RollingFileAppender is dropping messages 16, 32, 64, 128, and so on.

Is this a known issue with RollingFileAppender? Is there some sort of error
in our logback configuration? Any help is appreciated!

Regards,
Alex Hall

==========

Operating system: Ubuntu 14.04 LTS
Java version: Oracle JDK 1.8.0u72

Test program:

/lib:
  + logback-classic-1.1.7.jar
  + logback-core-1.1.7.jar
  + slf4j-api-1.7.21.jar

/resources/logback-test.xml:
----------
<configuration>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>logs/test.log</file>
    <encoder>
      <pattern>%d [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="ROLLING-FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>logs/rolling-test.log</file>
    <encoder>
      <pattern>%d [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
    <rollingPolicy
class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">

<fileNamePattern>logs/rolling-test-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy
          class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP" />
      <maxHistory>30</maxHistory>
      <cleanHistoryOnStart>true</cleanHistoryOnStart>
    </rollingPolicy>
  </appender>

  <root level="INFO">
    <appender-ref ref="FILE" />
    <appender-ref ref="ROLLING-FILE" />
  </root>

</configuration>
----------

/src/RollingAppenderTest.java:
----------
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class RollingAppenderTest {
   private static final Logger log =
LoggerFactory.getLogger(RollingAppenderTest.class);

   public static void main(String[] args) throws Exception {
      if (args.length != 1) {
         System.out.println("Usage: java RollingAppenderTest
<num-messages>");
         System.exit(1);
      }

      int nMessages = Integer.parseInt(args[0]);

      for (int i = 1; i <= nMessages; i++) {
         log.info("Hello, " + i);
      }
   }
}
----------

/run-test.sh
----------
#!/bin/sh

rm -rf logs
rm -rf classes

echo "Compiling..."
mkdir classes
javac -cp 'lib/*' -d classes -sourcepath src src/*.java

echo "Running..."
java -cp 'lib/*:classes:resources' RollingAppenderTest $1

echo "FileAppender output lines:        $(wc -l logs/test.log)"
echo "RollingFileAppender output lines: $(wc -l logs/rolling-test.log)"
diff logs/test.log logs/rolling-test.log
----------

Test output:
----------
alex@alex-ubuntu14:~/src/scratch/logback-drops-messages$ ./run-test.sh 1000
Compiling...
Running...
FileAppender output lines:        1000 logs/test.log
RollingFileAppender output lines: 994 logs/rolling-test.log
16d15
< 2016-05-05 14:40:14,365 [main] INFO  RollingAppenderTest - Hello, 16
32d30
< 2016-05-05 14:40:14,366 [main] INFO  RollingAppenderTest - Hello, 32
64d61
< 2016-05-05 14:40:14,380 [main] INFO  RollingAppenderTest - Hello, 64
128d124
< 2016-05-05 14:40:14,383 [main] INFO  RollingAppenderTest - Hello, 128
256d251
< 2016-05-05 14:40:14,405 [main] INFO  RollingAppenderTest - Hello, 256
512d506
< 2016-05-05 14:40:14,439 [main] INFO  RollingAppenderTest - Hello, 512
----------