[logback-user] RollingFileAppender dropping messages

[Ceki Gulcu]

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 at 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 at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
>