Hi Alex,

Thank you for the detailed description of the problem allowing its easy reproduction. It turns our that the configuration directives for ROLLING-FILE is lacking a crucial element, namely the "maxFileSize" property.

This would have been evident if you had enabled logback's internal status messages with

<configuration debug="true">
 ...
</configuration>

or with the equivalent

<configuration>
  <statusListener
class="ch.qos.logback.core.status.OnConsoleStatusListener" />
  ...
</configuration>

I have modified the code of SizeAndTimeBasedFNATP to detect the missing the "maxFileSize" property sooner and immediately alert the user.

Also note that more recent versions of logback ship with SizeAndTimeBasedRollingPolicy [1] which offers a more pleasant syntax than the TimeBasedRollingPolicy+SizeAndTimeBasedFNATP combination but with exactly the same functionality.

Cheers,

--
Ceki

[1] http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy

On 5/5/2016 16:42, Alex Hall wrote:

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 <http://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
----------

_______________________________________________
logback-user mailing list
logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user

_______________________________________________
logback-user mailing list
logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user