[logback-user] RollingFileAppender dropping messages

[Alex Hall]

Hi Ceki,
Indeed, setting the maxFileSize property on SizeAndTimeBasedFNATP resolved
the problem. Thanks as well for the tip on SizeAndTimeBasedRollingPolicy -
turns out that some of our projects are already using that in their
configs, but I happened to be looking at one that wasn't.

Thanks,
Alex

On Fri, May 13, 2016 at 4:12 AM, Ceki Gulcu <ceki at qos.ch> wrote:

> 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
>>
>> _______________________________________________
> logback-user mailing list
> logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20160513/b2d3c37f/attachment.html>