Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1390

When using hourly rolling policy, first cleanup after restart does nothing

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.1.11
    • Fix Version/s: None
    • Component/s: logback-core
    • Labels:
      None
    • Environment:

      AWS, Ubuntu 14.04, Java 8. Not really relevant here.

      Description

                  <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>
      

      Sometimes results in:

      dmitry@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@prod-empires-alt02:/var/log/empires_alt$ date
      Mon Mar 19 14:21:30 UTC 2018
      

      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. 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.

        Attachments

          Activity

            People

            • Assignee:
              logback-dev Logback dev list
              Reporter:
              MrBagheera Dmitry Mikhaylov
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: