Details
-
Bug
-
Resolution: Unresolved
-
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
- 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
.%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.