Turns out this was a permissions issue. We had Write and Execute permissions, but not Read. As a result, the Archive Remover failed (threw an NPE which logback hides unless debug="true" is set in the config
file), which threw off the rollover code (didn't complete properly), which threw off the internal Output Streams, cycling between 3 different but faulty states…
I've submitted a (low priority) usability request that could help others track permissions issues like this down…
Bob Sandiford | Principal Engineer | SirsiDynix
P: 800.288.8020 X6943 | Bob.Sandiford@sirsidynix.com
Join the conversation: Like us on Facebook! Follow
us on Twitter!
From: Logback-user [mailto:logback-user-bounces@qos.ch]
On Behalf Of Bob Sandiford
Sent: Tuesday, May 13, 2014 4:38 PM
To: logback-user@qos.ch
Subject: [logback-user] logback skipping log files on AWS EC2
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@sirsidynix.com
Join the conversation: Like us on Facebook! Follow
us on Twitter!