[logback-dev] [JIRA] (LOGBACK-1390) When using hourly rolling policy, first cleanup after restart does nothing
QOS.CH (JIRA)
noreply-jira at qos.ch
Mon Mar 19 15:35:01 CET 2018
Dmitry Mikhaylov created LOGBACK-1390:
-----------------------------------------
Summary: When using hourly rolling policy, first cleanup after restart does nothing
Key: LOGBACK-1390
URL: https://jira.qos.ch/browse/LOGBACK-1390
Project: logback
Issue Type: Bug
Components: logback-core
Affects Versions: 1.1.11
Environment: AWS, Ubuntu 14.04, Java 8. Not really relevant here. :-)
Reporter: Dmitry Mikhaylov
Assignee: Logback dev list
{code:java}
<appender class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./logs/access_log2</file> <!-- Dot is missing intentionally, to prevent log rotation by OpsWorks -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>./logs/access_log2.%d{yyyyMMddHH}</fileNamePattern>
<maxHistory>8</maxHistory>
<cleanHistoryOnStart>true</cleanHistoryOnStart>
</rollingPolicy>
<encoder class="server.core.AccessLogEncoder"/>
</appender>
{code}
Sometimes results in:
{code:java}
dmitry at prod-empires-alt02:/var/log/empires_alt$ ls -l access_log2*
-rw-r--r-- 1 sgg-app sgg-app 11615 Mar 19 14:19 access_log2
-rw-r--r-- 1 sgg-app sgg-app 36639 Jan 31 01:59 access_log2.2018013101
-rw-r--r-- 1 sgg-app sgg-app 35973 Jan 31 02:59 access_log2.2018013102
-rw-r--r-- 1 sgg-app sgg-app 35235 Jan 31 07:01 access_log2.2018013106
-rw-r--r-- 1 sgg-app sgg-app 31038 Feb 1 00:01 access_log2.2018013123
-rw-r--r-- 1 sgg-app sgg-app 32906 Feb 1 01:00 access_log2.2018020100
-rw-r--r-- 1 sgg-app sgg-app 36420 Feb 2 01:01 access_log2.2018020200
-rw-r--r-- 1 sgg-app sgg-app 33444 Feb 7 07:59 access_log2.2018020707
-rw-r--r-- 1 sgg-app sgg-app 40003 Feb 9 01:01 access_log2.2018020900
-rw-r--r-- 1 sgg-app sgg-app 37604 Feb 14 06:59 access_log2.2018021406
-rw-r--r-- 1 sgg-app sgg-app 34582 Feb 15 04:02 access_log2.2018021503
-rw-r--r-- 1 sgg-app sgg-app 36082 Feb 16 01:01 access_log2.2018021600
-rw-r--r-- 1 sgg-app sgg-app 36266 Feb 16 01:59 access_log2.2018021601
-rw-r--r-- 1 sgg-app sgg-app 37487 Feb 19 01:00 access_log2.2018021900
-rw-r--r-- 1 sgg-app sgg-app 35538 Feb 19 03:00 access_log2.2018021902
-rw-r--r-- 1 sgg-app sgg-app 34022 Feb 20 06:59 access_log2.2018022006
-rw-r--r-- 1 sgg-app sgg-app 622323 Feb 21 03:00 access_log2.2018022102
-rw-r--r-- 1 sgg-app sgg-app 1597083 Feb 21 06:00 access_log2.2018022105
-rw-r--r-- 1 sgg-app sgg-app 2492269 Feb 22 01:00 access_log2.2018022200
-rw-r--r-- 1 sgg-app sgg-app 5160030 Feb 22 09:00 access_log2.2018022208
-rw-r--r-- 1 sgg-app sgg-app 9266590 Feb 22 11:00 access_log2.2018022210
-rw-r--r-- 1 sgg-app sgg-app 12357461 Feb 22 13:00 access_log2.2018022212
-rw-r--r-- 1 sgg-app sgg-app 20258598 Feb 22 15:00 access_log2.2018022214
-rw-r--r-- 1 sgg-app sgg-app 18564007 Feb 23 00:00 access_log2.2018022223
-rw-r--r-- 1 sgg-app sgg-app 15944536 Feb 23 01:00 access_log2.2018022300
-rw-r--r-- 1 sgg-app sgg-app 14619064 Feb 23 03:00 access_log2.2018022302
-rw-r--r-- 1 sgg-app sgg-app 38179 Feb 27 15:00 access_log2.2018022714
-rw-r--r-- 1 sgg-app sgg-app 38860 Feb 28 01:00 access_log2.2018022800
-rw-r--r-- 1 sgg-app sgg-app 38600 Feb 28 02:02 access_log2.2018022801
-rw-r--r-- 1 sgg-app sgg-app 35114 Feb 28 03:00 access_log2.2018022802
-rw-r--r-- 1 sgg-app sgg-app 35161 Feb 28 04:02 access_log2.2018022803
-rw-r--r-- 1 sgg-app sgg-app 33622 Feb 28 04:57 access_log2.2018022804
-rw-r--r-- 1 sgg-app sgg-app 38933 Feb 28 06:00 access_log2.2018022805
-rw-r--r-- 1 sgg-app sgg-app 32738 Feb 28 07:00 access_log2.2018022806
-rw-r--r-- 1 sgg-app sgg-app 38040 Feb 28 08:00 access_log2.2018022807
-rw-r--r-- 1 sgg-app sgg-app 38591 Feb 28 10:02 access_log2.2018022809
-rw-r--r-- 1 sgg-app sgg-app 33940 Mar 2 14:01 access_log2.2018030213
-rw-r--r-- 1 sgg-app sgg-app 35253 Mar 6 02:01 access_log2.2018030601
-rw-r--r-- 1 sgg-app sgg-app 33353 Mar 7 06:01 access_log2.2018030705
-rw-r--r-- 1 sgg-app sgg-app 34459 Mar 9 00:59 access_log2.2018030900
-rw-r--r-- 1 sgg-app sgg-app 10552521 Mar 11 12:00 access_log2.2018031111
-rw-r--r-- 1 sgg-app sgg-app 13693556 Mar 11 13:00 access_log2.2018031112
-rw-r--r-- 1 sgg-app sgg-app 36288 Mar 13 02:00 access_log2.2018031301
-rw-r--r-- 1 sgg-app sgg-app 38856 Mar 13 08:00 access_log2.2018031307
-rw-r--r-- 1 sgg-app sgg-app 36734 Mar 14 11:00 access_log2.2018031410
-rw-r--r-- 1 sgg-app sgg-app 36588 Mar 15 07:59 access_log2.2018031507
-rw-r--r-- 1 sgg-app sgg-app 36579 Mar 15 09:01 access_log2.2018031508
-rw-r--r-- 1 sgg-app sgg-app 34449 Mar 16 07:01 access_log2.2018031606
-rw-r--r-- 1 sgg-app sgg-app 36237 Mar 16 13:01 access_log2.2018031612
-rw-r--r-- 1 sgg-app sgg-app 34586 Mar 17 14:00 access_log2.2018031713
-rw-r--r-- 1 sgg-app sgg-app 29670 Mar 19 06:59 access_log2.2018031906
-rw-r--r-- 1 sgg-app sgg-app 36119 Mar 19 08:02 access_log2.2018031907
-rw-r--r-- 1 sgg-app sgg-app 34581 Mar 19 09:00 access_log2.2018031908
-rw-r--r-- 1 sgg-app sgg-app 36901 Mar 19 10:02 access_log2.2018031909
-rw-r--r-- 1 sgg-app sgg-app 35474 Mar 19 11:01 access_log2.2018031910
-rw-r--r-- 1 sgg-app sgg-app 35497 Mar 19 12:02 access_log2.2018031911
-rw-r--r-- 1 sgg-app sgg-app 30756 Mar 19 13:00 access_log2.2018031912
-rw-r--r-- 1 sgg-app sgg-app 36397 Mar 19 14:00 access_log2.2018031913
dmitry at prod-empires-alt02:/var/log/empires_alt$ date
Mon Mar 19 14:21:30 UTC 2018
{code}
As you can see, most of the logs are cleaned properly, but sometimes there is one or two left. Since this pattern is the same across all instance in our cluster, we suspected that the problem is related to restart. Debugging first cleanup after restart yielded this little [gem|https://github.com/qos-ch/logback/blob/5bae54c53ac3cc429d29e3b782054b1b9b085313/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/RollingCalendar.java#L199]. On the first cleanup after app start, diff is 2768400000 (derived from INACTIVITY_TOLERANCE_IN_MILLIS), and somehow after this conversion it ends up being -424 periods.
In any case this conversion seems to be completely arbitrary, so suggested fix is just to remove it. I'll submit pull request shortly.
Because of legacy code, we are stuck with 1.1.x in this project, so I'd be very grateful if you could put up another official 1.1.x release.
--
This message was sent by Atlassian JIRA
(v7.3.1#73012)
More information about the logback-dev
mailing list