[logback-user] logback skipping log files on AWS EC2

[Bob Sandiford]

I'm using logback for logging from an app deployed in Tomcat, with a fairly simple setup (see code fragments). We use a RollingFileAppender, with TimeBasedRollingPolicy, set for daily rollover. When running locally, everything appears to be fine. When running in AWS in an EC2 instance, I'm seeing that some log files are missing.
I wrote a really simple app that does nothing but log once per second with a counter, and then a logback config that rolls every minute. For this particular test, we're seeing every third log file is missing.
So, for example, we'll get:
-rw-r--r-- 1 tomcat tomcat  891 May 13 18:46 logtest_tomcat.2014-05-13_1845.0.log.gz
-rw-r--r-- 1 tomcat tomcat  499 May 13 18:47 logtest_tomcat.2014-05-13_1846.0.log.gz
-rw-r--r-- 1 tomcat tomcat  541 May 13 18:49 logtest_tomcat.2014-05-13_1848.0.log.gz
-rw-r--r-- 1 tomcat tomcat  519 May 13 18:50 logtest_tomcat.2014-05-13_1849.0.log.gz
-rw-r--r-- 1 tomcat tomcat  532 May 13 18:52 logtest_tomcat.2014-05-13_1851.0.log.gz
-rw-r--r-- 1 tomcat tomcat  510 May 13 18:53 logtest_tomcat.2014-05-13_1852.0.log.gz
-rw-r--r-- 1 tomcat tomcat  536 May 13 18:55 logtest_tomcat.2014-05-13_1854.0.log.gz
-rw-r--r-- 1 tomcat tomcat 1226 May 13 18:56 logtest_tomcat.2014-05-13_1855.0.log.gz
-rw-r--r-- 1 tomcat tomcat  531 May 13 18:58 logtest_tomcat.2014-05-13_1857.0.log.gz
-rw-r--r-- 1 tomcat tomcat  496 May 13 18:59 logtest_tomcat.2014-05-13_1858.0.log.gz
-rw-r--r-- 1 tomcat tomcat 1244 May 13 19:01 logtest_tomcat.2014-05-13_1900.0.log.gz
-rw-r--r-- 1 tomcat tomcat  496 May 13 19:02 logtest_tomcat.2014-05-13_1901.0.log.gz
-rw-r--r-- 1 tomcat tomcat  514 May 13 19:04 logtest_tomcat.2014-05-13_1903.0.log.gz
-rw-r--r-- 1 tomcat tomcat  500 May 13 19:05 logtest_tomcat.2014-05-13_1904.0.log.gz
-rw-r--r-- 1 tomcat tomcat  522 May 13 19:07 logtest_tomcat.2014-05-13_1906.0.log.gz
The file format is yyyy-mm-dd_HHmm - so you can see that 1847, 1850, 1853, 1856, 1859, 1902, 1905 are all missing.
I've checked the contents - the sequential numbering on the log statements jumps by 60 for the missing logs - so it's not that multiple minutes are being collapsed into a single rolled over log.
We also thought it might be due to our Splunk forwarder - we ran the test both with and without the Splunk forwarder running, and got the same results - every third log file is missing.
Here's the logback appender for this test:
<appender name="daily" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${bc.logs.home}/logtest_tomcat.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <!-- Rollover every minute for this test -->
        <fileNamePattern>${bc.logs.home}/logtest_tomcat.%d{yyyy-MM-dd_HHmm}.%i.log.gz</fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <!-- or whenever the file size reaches 250MB -->
            <maxFileSize>250MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
        <maxHistory>60</maxHistory>
    </rollingPolicy>
    <append>true</append>
    <encoder>
        <pattern>%d{"yyyy-MM-dd HH:mm:ss,SSS z", UTC} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>
And here's my little driver class (the 'BCLog' is a simple wrapper around slf4j logging, instantiated by
        Logger log = LoggerFactory.getLogger(clazz);
)
package com.sirsidynix.logtest.biz.svc.impl;

import com.sirsidynix.bccommon.util.BCLog;
import com.sirsidynix.bccommon.util.BCLogFactory;
import org.springframework.beans.factory.DisposableBean;
import org.springframework.beans.factory.InitializingBean;

public class JustLogIt implements InitializingBean, DisposableBean
{
    private static final BCLog LOG = BCLogFactory.getLog(JustLogIt.class);

    private Thread thread;

    @Override
    public void afterPropertiesSet() throws Exception
    {
        LOG.info("Firing up JustLogIt thread");
        thread = new Thread(){
            @Override
            public void run()
            {
                long iteration = 0;
                while (true)
                {
                    try
                    {
                        Thread.sleep(1000);
                        iteration++;
                        LOG.info("Logging Iteration " + iteration);
                    }
                    catch (InterruptedException e)
                    {
                        LOG.info("LogIt thread sleep interrupted!!!");
                    }
                }
            }
        };
        thread.start();
    }


    @Override
    public void destroy() throws Exception
    {
        LOG.info("Shutting down JustLogIt thread");
        thread.interrupt();
    }
}
Any ideas?
Thanks!


Bob Sandiford | Principal Engineer | SirsiDynix
P: 800.288.8020 X6943 | Bob.Sandiford at sirsidynix.com<mailto:Bob.Sandiford at sirsidynix.com>
www.sirsidynix.com<http://www.sirsidynix.com/>

Join the conversation: Like us on Facebook!<http://www.facebook.com/SirsiDynix> Follow us on Twitter!<http://twitter.com/SirsiDynix>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20140513/a36b0f8c/attachment-0001.html>