TimeBasedRollingPolicy делает странные вещи при прокатке - PullRequest
Новая
       6

TimeBasedRollingPolicy делает странные вещи при прокатке

0 голосов
/ 27 февраля 2020

У меня есть веб-приложение, работающее под причалом 9.4.20. Я включил модуль обратного входа и настроил resources/logback.xml со следующей скользящей политикой: 

<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
  <fileNamePattern>logs/%d{yyyy-MM,aux}/my-webapp-%d{dd-MM-yyyy}.log</fileNamePattern>
</rollingPolicy>

Это в основном работает, но со странным паттерном. В большинстве случаев это правильно, поэтому у меня будет файл my-webapp-12-01-2020.log с последним доступом 12 января 23:59. Однако некоторые файлы свернуты неправильно. Например, файл my-webapp-08-01-2020.log имеет последний доступ 10 января 23:59 и содержит записи только с 10 января. Откуда взялись логи от 8 января go? Ну ... они, конечно, в my-webapp-02-01-2020.log, который имеет доступ 8 января 23:59 и действительно содержит все записи журнала за 8 января. Где находятся записи в журнале от 2 января? Их нигде не найти (grep'ed все файлы журналов просто чтобы быть уверенным). Такое смешение происходит каждый месяц в отношении нескольких файлов журнала, и каждый месяц происходит с разными днями.

Как выяснить, почему это происходит?

Это выполняется на AWS узле EC2. и имеет UT C время syn c 'ред. Похоже, искаженные даты не связаны с перезапуском Jetty (ie. Искаженные даты включают дни, когда Jetty работала без перезапуска).

Jetty 9.4.20 с logback означает logbackcore-1.2.3, logback-classic-1.2.3 и slf4j-api-1.7.25.

РЕДАКТИРОВАТЬ: я включил отладку и запуск выглядит хорошо 

Feb 27 13:49:50 c.q.l.core.rolling.TimeBasedRollingPolicy@1310167355 - No compression will be used
Feb 27 13:49:50 c.q.l.core.rolling.TimeBasedRollingPolicy@1310167355 - Will use the pattern logs /%d{yyyy-MM,aux}/my-webapp-%d{dd-MM-yyyy}.log for the active file
Feb 27 13:49:50 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'dd-MM-yyyy' from file name pattern 'logs/%d{yyyy-MM,aux}/my-webapp-%d{dd-MM-yyyy}.log'.
Feb 27 13:49:50 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
Feb 27 13:49:50 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Thu Feb 27 13:49:49 UTC 2020
Feb 27 13:49:50 ch.qos.logback.core.rolling.RollingFileAppender[log] - Active log file name: logs/my-webapp.log
Feb 27 13:49:50 ch.qos.logback.core.rolling.RollingFileAppender[log] - File property is set to [logs/my-webapp.log]

Затем в середине дня происходит один сбой с броском, но затем проходит нормально в течение нескольких дней: 

Feb 28 00:00:03 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Thu Feb 27 13:49:49 UTC 2020
Feb 28 00:00:03 c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/my-webapp.log] to [logs/2020-02/my-webapp-27-02-2020.log]
Feb 28 10:59:45 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Thu Feb 27 13:42:58 UTC 2020
Feb 28 10:59:45 c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/my-webapp.log] to [logs/2020-02/my-webapp-27-02-2020.log]
Feb 29 00:00:07 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Fri Feb 28 00:00:03 UTC 2020
Feb 29 00:00:07 c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/my-webapp.log] to [logs/2020-02/my-webapp-28-02-2020.log]

... и тогда возникает проблема. Первый ролловер в полночь в порядке того, когда это происходит, и каково целевое имя файла. Следующие два абсолютно неправильны: неправильное время ролловера и имя целевого файла: 

Mar  5 00:00:20 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Wed Mar 04 00:00:16 UTC 2020
Mar  5 00:00:20 c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/my-webapp.log] to [logs/2020-03/my-webapp-04-03-2020.log]
Mar  5 09:15:11 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Tue Feb 18 09:18:24 UTC 2020
Mar  5 09:15:11 c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/my-webapp.log] to [logs/2020-02/my-webapp-18-02-2020.log]
Mar  5 09:59:45 c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Fri Feb 28 10:59:45 UTC 2020
Mar  5 09:59:45 c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/my-webapp.log] to [logs/2020-02/my-webapp-28-02-2020.log]

Я начал копаться в исходном коде, чтобы выяснить причину этого странного поведения.

...