March 2018 - logback-dev - mailman3.qos.ch

[JIRA] (LOGBACK-1390) When using hourly rolling policy, first cleanup after restart does nothing
by QOS.CH (JIRA) 19 Mar '18

19 Mar '18

1 0

[JIRA] (LOGBACK-1390) When using hourly rolling policy, first cleanup after restart does nothing
by QOS.CH (JIRA) 19 Mar '18

19 Mar '18

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>  <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@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 {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/5bae54c53ac3cc429d29e3b782054b1b…] 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)

1 0

[JIRA] (LOGBACK-747) maxHistory doesnot normally work in SizeAndTimeBasedFNATP
by QOS.CH (JIRA) 14 Mar '18

14 Mar '18

1 0

[JIRA] (LOGBACK-1389) OnConsoleStatusListener example does not start
by QOS.CH (JIRA) 11 Mar '18

11 Mar '18

Hontvári József created LOGBACK-1389: ---------------------------------------- Summary: OnConsoleStatusListener example does not start Key: LOGBACK-1389 URL: https://jira.qos.ch/browse/LOGBACK-1389 Project: logback Issue Type: Bug Components: logback-core Affects Versions: 1.2.3 Reporter: Hontvári József Assignee: Logback dev list Priority: Minor The example in https://logback.qos.ch/manual/configuration.html#statusListener is missing an OnConsoleStatusListener::start call. Without that it will not print anything to the console. -- This message was sent by Atlassian JIRA (v7.3.1#73012)

1 0

[JIRA] (LOGBACK-1388) ServerSocketReceiver adds an unnecessary error status
by QOS.CH (JIRA) 11 Mar '18

11 Mar '18

Hontvári József created LOGBACK-1388: ---------------------------------------- Summary: ServerSocketReceiver adds an unnecessary error status Key: LOGBACK-1388 URL: https://jira.qos.ch/browse/LOGBACK-1388 Project: logback Issue Type: Bug Components: logback-core Affects Versions: 1.2.3 Reporter: Hontvári József Assignee: Logback dev list Priority: Minor If ConcurrentServerRunner stopped it correctly closes the listening socket. This causes a "listener: jjava.net.SocketException: Socket closed" internal status error message. The message is reported from the run method. The exception may indeed indicate a problem, but in case of shutdown it is expected, so it should not be reported as an error during shutdown.. -- This message was sent by Atlassian JIRA (v7.3.1#73012)

1 0

[JIRA] (LOGBACK-1219) logback-access exceptions during logout
by QOS.CH (JIRA) 10 Mar '18

10 Mar '18

1 0

[JIRA] (LOGBACK-1387) to generate a log file by a specified minute
by QOS.CH (JIRA) 05 Mar '18

05 Mar '18

ganxiaojian created LOGBACK-1387: ------------------------------------ Summary: to generate a log file by a specified minute Key: LOGBACK-1387 URL: https://jira.qos.ch/browse/LOGBACK-1387 Project: logback Issue Type: Improvement Components: logback-core Affects Versions: 1.1.7 Reporter: ganxiaojian Assignee: Logback dev list Priority: Trivial {color:#008000}TimeBasedRollingPolicy {color}may not be able to generate a log file by a specified minute.(For example: generate log file every 15 minutes.) Could you help check if it is resonable to extend the rolling-policy mentioned above? or there already exist one? -- This message was sent by Atlassian JIRA (v7.3.1#73012)

1 0

[JIRA] (LOGBACK-1386) Incorrect rolling files by TimeBasedArchiveRemover if totalSizeCap limit is exceeded
by QOS.CH (JIRA) 04 Mar '18

04 Mar '18

1 0

[JIRA] (LOGBACK-1386) Incorrect rolling files by TimeBasedArchiveRemover if totalSizeCap limit is exceeded
by QOS.CH (JIRA) 04 Mar '18

04 Mar '18

Aleksei Lebedev created LOGBACK-1386: ---------------------------------------- Summary: Incorrect rolling files by TimeBasedArchiveRemover if totalSizeCap limit is exceeded Key: LOGBACK-1386 URL: https://jira.qos.ch/browse/LOGBACK-1386 Project: logback Issue Type: Bug Components: logback-core Affects Versions: 1.3.0-alpha4, 1.1.8 Environment: Mac OS X, JDK8/9 Reporter: Aleksei Lebedev Assignee: Logback dev list Priority: Critical TimeBasedArchiveRemover doesn't get into account the oldest history files when rollover happens and totalSizeCap limit is exceeded. In the worst case this leads to an increase in the total log file size up to 2 times above totalCapSize. It can be reproduced with following configuration: {code:xml} <configuration scan="true" scanPeriod="10 seconds" debug="true"> <appender name="ROLLING" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>mylog.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>mylog-%d{yyyyMMdd-HHmm}.%i.log</fileNamePattern> <maxFileSize>2KB</maxFileSize> <maxHistory>1</maxHistory> <totalSizeCap>10KB</totalSizeCap> <cleanHistoryOnStart>true</cleanHistoryOnStart> </rollingPolicy> <encoder> <pattern>%msg%n</pattern> </encoder> </appender> <root level="DEBUG"> <appender-ref ref="ROLLING"/> </root> </configuration>{code} and simple application: {code:java} public class Main { private static final Logger log = LoggerFactory.getLogger(Main.class); private static final long ONE_MILLION = 1_000_000L; public static void main(String[] args) throws InterruptedException { for (int i = 0; i < 10000; i++) { log.info("I write in log {} times", ONE_MILLION + i); Thread.sleep(100L); } } } {code} Example of execution result of such configuration: {noformat} 2.0K Mar 21:44 mylog-20180304-2144.3.log <- this one should be removed 2.0K Mar 21:44 mylog-20180304-2144.4.log 2.0K Mar 21:44 mylog-20180304-2144.5.log 2.0K Mar 21:44 mylog-20180304-2144.6.log 2.0K Mar 21:44 mylog-20180304-2144.7.log 2.1K Mar 21:45 mylog-20180304-2145.0.log <- but this will be removed instead 2.0K Mar 21:45 mylog-20180304-2145.1.log 2.0K Mar 21:45 mylog-20180304-2145.2.log 2.0K Mar 21:45 mylog-20180304-2145.3.log 2.0K Mar 21:45 mylog.log {noformat} and in a moment: {noformat} 2.0K Mar 21:44 mylog-20180304-2144.3.log 2.0K Mar 21:44 mylog-20180304-2144.4.log 2.0K Mar 21:44 mylog-20180304-2144.5.log 2.0K Mar 21:44 mylog-20180304-2144.6.log 2.0K Mar 21:44 mylog-20180304-2144.7.log 2.0K Mar 21:45 mylog-20180304-2145.1.log 2.0K Mar 21:45 mylog-20180304-2145.2.log 2.0K Mar 21:45 mylog-20180304-2145.3.log 2.0K Mar 21:45 mylog-20180304-2145.4.log 174B Mar 21:45 mylog.log {noformat} -- This message was sent by Atlassian JIRA (v7.3.1#73012)

1 0

[JIRA] (LOGBACK-1204) AbstractSocketAppender swallows InterruptedException
by QOS.CH (JIRA) 02 Mar '18

02 Mar '18

1 0