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<mailto:Bob.Sandiford@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>
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<mailto:Bob.Sandiford@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> 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<mailto:Bob.Sandiford@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>
I think a usability request without a pull request or a repeatible test case is not likely to see much action. If you could supply either of those it's more likely to get worked on. Thanks David -- View this message in context: http://logback.10977.n7.nabble.com/logback-skipping-log-files-on-AWS-EC2-tp1... Sent from the Users mailing list archive at Nabble.com.
participants (2)
-
Bob Sandiford -
diroussel