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

Logback fails to create gz files on next day when doing rollover based on time and size

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Critical Critical
    • None
    • 1.1.3
    • None
    • None

    Description

      This problem has occurred when after I upgraded from logback 1.1.2 to logback 1.1.3

      I have a configuration with a SizeAndTimeBasedFNATP, with a date in the filename and a size restriction and file compression (gz). Now when I start my application a new files get created correctly, with a rollover as expected, and the debug output reports no problems with my configuration.
      Until midnight the rollover continues to work without error (roughly every 5MB = 60 minutes). After midnight however I get tmp files (uncompressed), instead of correctly named compressed files

      Possibly the problem is that the date is in a different timezone (UTC) than the system (+2:00, CEST). This worked like a charm in v1.1.2, but the files were created based on the date in the local timezone, and not the UTC timezone (which is not a surprise because this feature was added in v1.1.3, hence my upgrade).

      I did two runs, one where I found the issue on the 22nd to the 23rd and around 6 hours later one where I turned on logback debug logging on the 23rd to the 24th.

      After starting I get the following logback warning:
      17:33:37,044 |-WARN in ReconfigureOnChangeFilter

      {invocationCounter=0}

      - Due to missing top level configuration file, automatic reconfiguration is impossible.
      I don't think this was here before, also it doesn't seem relevent.

      I get the following warnings in my console (timestamps are local time, and probably are at the time of the rollowever
      18:12:00,453 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      19:01:27,046 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      19:52:31,045 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      20:51:25,044 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      21:44:09,045 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      22:38:10,646 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      23:35:08,245 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      00:00:00,045 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      00:00:42,813 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@1550481 - Unexpected periodsElapsed value 0
      00:59:41,645 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      00:59:41,645 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.0.log.gz] exist already. Aborting file compression.
      02:00:06,045 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      02:00:06,045 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.1.log.gz] exist already. Aborting file compression.
      02:58:23,846 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      02:58:23,847 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.2.log.gz] exist already. Aborting file compression.
      03:53:51,446 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      03:53:51,446 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.3.log.gz] exist already. Aborting file compression.
      04:53:19,846 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      04:53:19,846 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.4.log.gz] exist already. Aborting file compression.
      05:53:13,046 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      05:53:13,046 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.5.log.gz] exist already. Aborting file compression.
      06:49:48,045 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      06:49:48,045 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.6.log.gz] exist already. Aborting file compression.
      07:46:35,245 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      07:46:35,245 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/orbit/orbit-log/./gps-2015-06-23.7.log.gz] exist already. Aborting file compression.

      Note that the first lines correspond to compression that did work.

      The last 2 warnings are contained in the following log block:

      2015-06-24T05:46:21.264Z I [MyThread[1]] My log message
      07:46:35,244 |-INFO in c.q.l.co.rolling.helper.RenameUtil - Renaming file [/home/orbit/orbit-log/./gps.log] to [/home/orbit/orbit-log/./gps.log142143386539207.tmp]
      07:46:35,245 |-WARN in ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover@bc464 - Unexpected periodsElapsed value 0
      07:46:35,245 |-WARN in ch.qos.logback.core.rolling.helper.Compressor - The target compressed file named [/home/me/log/./gps-2015-06-23.7.log.gz] exist already. Aborting file compression.
      2015-06-24T05:46:46.291Z I [MyThread[1]] My log message

      Note that the file tries to create a file for 2015-06-23, while the date already is 2015-06-24 in both local timezone and UTC.

      The following files are created:
      rw-rr- 1 me me 1,4M jun 24 08:28 debug.log
      rw-rr- 1 me me 443K jun 22 10:45 gps-2015-06-22.0.log.gz
      rw-rr- 1 me me 790K jun 22 20:54 gps-2015-06-22.10.log.gz
      rw-rr- 1 me me 504K jun 22 21:44 gps-2015-06-22.11.log.gz
      rw-rr- 1 me me 667K jun 22 22:39 gps-2015-06-22.12.log.gz
      rw-rr- 1 me me 606K jun 22 23:32 gps-2015-06-22.13.log.gz
      rw-rr- 1 me me 305K jun 23 00:00 gps-2015-06-22.14.log.gz
      rw-rr- 1 me me 445K jun 22 11:35 gps-2015-06-22.1.log.gz
      rw-rr- 1 me me 444K jun 22 12:25 gps-2015-06-22.2.log.gz
      rw-rr- 1 me me 451K jun 22 13:15 gps-2015-06-22.3.log.gz
      rw-rr- 1 me me 463K jun 22 14:04 gps-2015-06-22.4.log.gz
      rw-rr- 1 me me 465K jun 22 16:34 gps-2015-06-22.5.log.gz
      rw-rr- 1 me me 465K jun 22 17:23 gps-2015-06-22.6.log.gz
      rw-rr- 1 me me 472K jun 22 18:13 gps-2015-06-22.7.log.gz
      rw-rr- 1 me me 467K jun 22 19:02 gps-2015-06-22.8.log.gz
      rw-rr- 1 me me 617K jun 22 19:55 gps-2015-06-22.9.log.gz
      rw-rr- 1 me me 540K jun 23 18:12 gps-2015-06-23.0.log.gz
      rw-rr- 1 me me 467K jun 23 19:01 gps-2015-06-23.1.log.gz
      rw-rr- 1 me me 491K jun 23 19:52 gps-2015-06-23.2.log.gz
      rw-rr- 1 me me 841K jun 23 20:51 gps-2015-06-23.3.log.gz
      rw-rr- 1 me me 589K jun 23 21:44 gps-2015-06-23.4.log.gz
      rw-rr- 1 me me 631K jun 23 22:38 gps-2015-06-23.5.log.gz
      rw-rr- 1 me me 765K jun 23 23:35 gps-2015-06-23.6.log.gz
      rw-rr- 1 me me 338K jun 24 00:00 gps-2015-06-23.7.log.gz
      rw-rr- 1 me me 4,0M jun 24 08:28 gps.log
      rw-rr- 1 me me 5,1M jun 24 00:59 gps.log117729785907984.tmp
      rw-rr- 1 me me 5,1M jun 24 02:00 gps.log121354186583311.tmp
      rw-rr- 1 me me 5,1M jun 24 02:58 gps.log124851987521238.tmp
      rw-rr- 1 me me 5,1M jun 24 03:53 gps.log128179587434968.tmp
      rw-rr- 1 me me 5,1M jun 24 04:53 gps.log131747987324007.tmp
      rw-rr- 1 me me 5,1M jun 24 05:53 gps.log135341187168934.tmp
      rw-rr- 1 me me 5,1M jun 24 06:49 gps.log138736186478923.tmp
      rw-rr- 1 me me 5,1M jun 24 07:46 gps.log142143386539207.tmp
      rw-rr- 1 me me 5,1M jun 23 00:56 gps.log31136498179814.tmp
      rw-rr- 1 me me 5,1M jun 23 01:56 gps.log34724898094749.tmp
      rw-rr- 1 me me 5,1M jun 23 02:56 gps.log38335098833090.tmp
      rw-rr- 1 me me 5,1M jun 23 03:48 gps.log41436897868386.tmp
      rw-rr- 1 me me 5,1M jun 23 04:37 gps.log44389898817954.tmp
      rw-rr- 1 me me 5,1M jun 23 05:27 gps.log47402097911265.tmp
      rw-rr- 1 me me 5,1M jun 23 06:22 gps.log50717897411081.tmp
      rw-rr- 1 me me 5,1M jun 23 07:19 gps.log54092097393732.tmp
      rw-rr- 1 me me 5,1M jun 23 08:16 gps.log57567298020701.tmp
      rw-rr- 1 me me 5,1M jun 23 09:10 gps.log60805298522413.tmp
      rw-rr- 1 me me 5,1M jun 23 10:00 gps.log63755698125678.tmp
      rw-rr- 1 me me 5,1M jun 23 10:51 gps.log66864097980152.tmp
      rw-rr- 1 me me 2,9K jun 23 00:00 system-2015-06-22.0.log.gz
      rw-rr- 1 me me 6,3K jun 24 00:00 system-2015-06-23.0.log.gz
      rw-rr- 1 me me 41K jun 24 08:28 system.log

      The relevant configuration for the gps is:

      <appender name="GpsLogFileAppender"
      class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${GPSLOG_FILEBASE}.log</file>
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- rollover daily -->
      <fileNamePattern>${GPSLOG_FILEBASE}-%d

      {yyyy-MM-dd,UTC}

      .%i.log.gz</fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy
      class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
      <maxFileSize>5MB</maxFileSize>
      </timeBasedFileNamingAndTriggeringPolicy>
      <maxHistory>10</maxHistory>
      <cleanHistoryOnStart>true</cleanHistoryOnStart>
      </rollingPolicy>

      <encoder>
      <pattern>${SYSTEMLOG_PARTTERN}</pattern>
      </encoder>
      </appender>

      I will attach the full configuration file, note that the variable instancename is not set here. In v1.1.2 I used the same config file (except for the debug="true" part).

      This is ran using debian 7.1 linux.

      Attachments

        Activity

          People

            logback-dev Logback dev list
            mlodder Menno Lodder
            Votes:
            2 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated: