英文:
Logback sift RollingFileAppender not rotating when run from WAR
问题
我有一个logback配置，可以将日志记录到多个文件，包括名为servernexus.log的主日志文件。每个日志文件都应该由RollingFileAppender进行轮换。当我从eclipse运行，使用logback配置文件和$CLASSPATH中的其他所有内容时，logback会正确地对servernexus.log进行轮换。但当我从生产WAR文件运行时，日志记录工作正常，但servernexus.log的轮换从未发生。
以下是logback-server-win32event.xml的内容：
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="SiftAppender" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
<key>discriminatorId</key>
<defaultValue>${cmb.log.file.name}</defaultValue>
</discriminator>
<sift>
<appender name="FILE-${discriminatorId}" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${cmb.log.dir}/${discriminatorId}.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- daily rollover -->
<fileNamePattern>${cmb.log.dir}/archive/${discriminatorId}.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
<!-- keep ${maxbackupindex} days' worth of history capped at ${maxfilesize} total size -->
<maxHistory>${cmb.log.maxbackupindex}</maxHistory>
<totalSizeCap>${cmb.log.maxfilesize}</totalSizeCap>
</rollingPolicy>
<encoder>
<pattern>%date{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %msg%n</pattern>
</encoder>
</appender>
</sift>
</appender>
<!-- ...其他logger配置... -->
<root level="WARN">
<appender-ref ref="SiftAppender" />
</root>
</configuration>
如您所见，我使用了一个判别器，该判别器在logback初始化之前在运行时设置为系统属性。您可以在下面的输出中看到"cmb.log.file.name"属性。
当我从eclipse运行时，它工作并报告了预期的TimeBasedRollingPolicy行：
11:19:40,144 INFO Log Configurator T1 | Logging PROP cmb.log.file = C:\Users\mcooper\ws\cmb.0\run\server\log\servernexus.log
11:19:40,194 INFO Log Configurator T1 | Configuring log to file for logback var "log.file.name" = "servernexus"
11:19:40,194 INFO Log Configurator T1 | Logging PROP cmb.log.file.name = servernexus
11:19:40,194 INFO Log Configurator T1 | Logging PROP cmb.log.maxfilesize = 50MB
11:19:40,194 INFO Log Configurator T1 | Logging PROP cmb.log.maxbackupindex = 5
...
11:19:41,015 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2076287037 - Will use gz compression
11:19:41,017 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2076287037 - Will use the pattern C:/Users/mcooper/ws/cmb/6.0/run/server/log/archive/servernexus.%d{yyyy-MM-dd}.log for the active file
...
11:19:41,066 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE-servernexus] - Active log file name: C:\Users\mcooper\ws\cmb.0\run\server\log/servernexus.log
但当我从生产WAR文件运行时，logback输出不会报告任何TimeBasedRollingPolicy内容：
10:55:10,673 INFO Log Configurator T1 | Logging PROP cmb.log.dir = C:\ProgramData\XXX\YYY\log
10:55:10,673 INFO Log Configurator T1 | Logging PROP cmb.log.file = C:\ProgramData\XXX\YYY\log\servernexus.log
...
10:55:10,782 INFO Log Configurator T1 | Logging [servernexus.log] to C:\ProgramData\XXX\YYY\log\servernexus.log using logback-server-win32event.xml
...
希望这个翻译对您有帮助。如有任何问题，请随时提问。
英文:
I have a logback config that logs to multiple files including the primary log file called servernexus.log. Each log file is suppose to be rotated by RollingFileAppender. When I run from eclipse with the logback config file and everything else in my $CLASSPATH the servernexus.log is rotated properly by logback. When I run from my production WAR file logging works but the servernexus.log rotation never happens.
Here's the logback-server-win32event.xml:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="SiftAppender" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
<key>discriminatorId</key>
<defaultValue>${cmb.log.file.name}</defaultValue>
</discriminator>
<sift>
<appender name="FILE-${discriminatorId}" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${cmb.log.dir}/${discriminatorId}.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- daily rollover -->
<fileNamePattern>${cmb.log.dir}/archive/${discriminatorId}.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
<!-- keep ${maxbackupindex} days' worth of history capped at ${maxfilesize} total size -->
<maxHistory>${cmb.log.maxbackupindex}</maxHistory>
<totalSizeCap>${cmb.log.maxfilesize}</totalSizeCap>
</rollingPolicy>
<encoder>
<pattern>%date{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %msg%n</pattern>
</encoder>
</appender>
</sift>
</appender>
<logger name="org.apache" level="WARN"/>
<logger name="org.hibernate" level="INFO"/>
<logger name="org.hibernate.type" level="ERROR"/>
<logger name="org.hibernate.id" level="ERROR"/>
<logger name="org.hibernate.cfg.annotations" level="WARN"/>
<logger name="org.hibernate.tool.hbm2ddl" level="WARN"/>
<!-- DEBUG output shows db user password: -->
<logger name="org.hibernate.jpa.internal.util.LogHelper" level="WARN"/>
<!-- DEBUG output shows db user password: -->
<logger name="org.hibernate.internal.util.EntityPrinter" level="WARN"/>
<logger name="com.mchange" level="INFO"/>
<logger name="org.springframework" level="WARN"/>
<logger name="org.quartz" level="INFO"/>
<!-- HtmlUnit - turn off debug by debug -->
<logger name="com.gargoylesoftware.htmlunit" level="INFO"/>
<logger name="org.eclipse" level="WARN"/>
<!-- Disable "WARN XXX scanned from multiple locations" -->
<logger name="org.eclipse.jetty.annotations.AnnotationParser" level="ERROR"/>
<if condition='isDefined("logging.jetty.level")'>
<then>
<logger name="org.eclipse.jetty" level="${logging.jetty.level}"/>
</then>
<else>
<logger name="org.eclipse.jetty" level="INFO"/>
</else>
</if>
<root level="WARN">
<appender-ref ref="SiftAppender" />
</root>
</configuration>
As you can see I'm using a discriminator which is set as a system property at runtime prior to logback being initialized. You can see the "cmb.log.file.name" property in the output below.
When I run from eclipse it works and reports the expected TimeBasedRollingPolicy lines:
11:19:40,144 INFO Log Configurator T1 | Logging PROP cmb.log.file = C:\Users\mcooper\ws\cmb.0\run\server\log\servernexus.log
11:19:40,194 INFO Log Configurator T1 | Configuring log to file for logback var "log.file.name" = "servernexus"
11:19:40,194 INFO Log Configurator T1 | Logging PROP cmb.log.file.name = servernexus
11:19:40,194 INFO Log Configurator T1 | Logging PROP cmb.log.maxfilesize = 50MB
11:19:40,194 INFO Log Configurator T1 | Logging PROP cmb.log.maxbackupindex = 5
11:19:40,303 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-server-win32event.xml] at [file:/C:/Users/mcooper/ws/cmb/6.0/CmbProduct/Common/bin/main/logback-server-win32event.xml]
11:19:40,440 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.sift.SiftingAppender]
11:19:40,455 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SiftAppender]
11:19:40,478 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.sift.MDCBasedDiscriminator] for [discriminator] property
11:19:40,493 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.mangogrove.logbackwela.Win32EventLogAppender]
11:19:40,496 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [EventLogAppender]
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache] to WARN
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate] to INFO
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.type] to ERROR
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.id] to ERROR
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.cfg.annotations] to WARN
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.tool.hbm2ddl] to WARN
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.jpa.internal.util.LogHelper] to WARN
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.internal.util.EntityPrinter] to WARN
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.mchange] to INFO
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework] to WARN
11:19:40,501 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.quartz] to INFO
11:19:40,502 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.gargoylesoftware.htmlunit] to INFO
11:19:40,502 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse] to WARN
11:19:40,872 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty] to INFO
11:19:40,872 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
11:19:40,872 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SiftAppender] to Logger[ROOT]
11:19:40,873 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EventLogAppender] to Logger[ROOT]
11:19:40,873 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
11:19:40,878 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@64485a47 - Registering current configuration as safe fallback point
2020-09-01 11:19:40.952:INFO::main: Logging initialized @1106ms to org.eclipse.jetty.util.log.StdErrLog
11:19:40,979 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
11:19:40,985 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE-servernexus]
11:19:40,993 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2076287037 - setting totalSizeCap to 50 MB
11:19:41,015 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2076287037 - Will use gz compression
11:19:41,017 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2076287037 - Will use the pattern C:/Users/mcooper/ws/cmb/6.0/run/server/log/archive/servernexus.%d{yyyy-MM-dd}.log for the active file
11:19:41,024 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'C:/Users/mcooper/ws/cmb/6.0/run/server/log/archive/servernexus.%d{yyyy-MM-dd}.log.gz'.
11:19:41,024 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
11:19:41,026 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Tue Sep 01 11:17:12 PDT 2020
11:19:41,028 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
11:19:41,066 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE-servernexus] - Active log file name: C:\Users\mcooper\ws\cmb.0\run\server\log/servernexus.log
11:19:41,066 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE-servernexus] - File property is set to [C:\Users\mcooper\ws\cmb.0\run\server\log/servernexus.log]
When I run from production WAR file the logback output does not report anything for TimeBasedRollingPolicy:
10:55:10,673 INFO Log Configurator T1 | Logging PROP cmb.log.dir = C:\ProgramData\XXX\YYY\log
10:55:10,673 INFO Log Configurator T1 | Logging PROP cmb.log.file = C:\ProgramData\XXX\YYY\log\servernexus.log
10:55:10,767 INFO Log Configurator T1 | Configuring log to file for logback var "log.file.name" = "servernexus"
10:55:10,767 INFO Log Configurator T1 | Logging PROP cmb.log.file.name = servernexus
10:55:10,767 INFO Log Configurator T1 | Logging PROP cmb.log.maxfilesize = 50MB
10:55:10,767 INFO Log Configurator T1 | Logging PROP cmb.log.maxbackupindex = 5
10:55:10,782 INFO Log Configurator T1 | Logging [servernexus.log] to C:\ProgramData\XXX\YYY\log\servernexus.log using logback-server-win32event.xml
2020-09-01 10:55:12.236:INFO::main: Logging initialized @1792ms to org.eclipse.jetty.util.log.StdErrLog
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/s-cmbtest/AppData/Local/Temp/yyy_console_wartmp_6.0.79/webapp/WEB-INF/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/Program%20Files/XXX/YYY/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
10:55:59,322 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-server-win32event.xml] at [jar:file:/C:/Users/s-cmbtest/AppData/Local/Temp/yyy_console_wartmp_6.0.79/webapp/WEB-INF/lib/Common-6.0.79.jar!/logback-server-win32event.xml]
10:55:59,322 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback-server-win32event.xml] occurs multiple times on the classpath.
10:55:59,322 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback-server-win32event.xml] occurs at [jar:file:/C:/Users/s-cmbtest/AppData/Local/Temp/yyy_console_wartmp_6.0.79/webapp/WEB-INF/lib/Common-6.0.79.jar!/logback-server-win32event.xml]
10:55:59,322 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback-server-win32event.xml] occurs at [jar:file:/C:/Program%20Files/XXX/YYY/lib/Common-6.0.79.jar!/logback-server-win32event.xml]
10:55:59,338 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@1f05b63d - URL [jar:file:/C:/Users/s-cmbtest/AppData/Local/Temp/yyy_console_wartmp_6.0.79/webapp/WEB-INF/lib/Common-6.0.79.jar!/logback-server-win32event.xml] is not of type file
10:55:59,448 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
10:55:59,448 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.sift.SiftingAppender]
10:55:59,448 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SiftAppender]
10:55:59,463 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.sift.MDCBasedDiscriminator] for [discriminator] property
10:55:59,463 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.mangogrove.logbackwela.Win32EventLogAppender]
10:55:59,479 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [EventLogAppender]
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache] to WARN
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate] to INFO
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.type] to ERROR
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.id] to ERROR
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.cfg.annotations] to WARN
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.tool.hbm2ddl] to WARN
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.jpa.internal.util.LogHelper] to WARN
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.internal.util.EntityPrinter] to WARN
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.mchange] to INFO
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework] to WARN
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.quartz] to INFO
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.gargoylesoftware.htmlunit] to INFO
10:55:59,479 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse] to WARN
10:55:59,775 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty] to INFO
10:55:59,775 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
10:55:59,775 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SiftAppender] to Logger[ROOT]
10:55:59,775 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EventLogAppender] to Logger[ROOT]
10:55:59,775 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
10:55:59,775 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@524b1c70 - Registering current configuration as safe fallback point
答案1
得分: 0
我不是这方面的专家，但我认为以下建议可能有助于找到问题。在配置中启用调试以检查logback，并且您缺少了%i。从logback文档中的第4章的Appenders中可以看到以下内容：
"请注意，除了%d之外，还有"%i"转换标记。 %i和%d标记都是强制性的。每当当前日志文件在当前时间段结束之前达到maxFileSize时，它将以递增的索引进行归档，从0开始。"
英文:
I am not a expert of this but here is what I think should help find the issue. Enable debug in the configuration to check logback and you are missing the %i . From the Chapter 4 of the Appenders in logback documentation
"Note the "%i" conversion token in addition to "%d". Both the %i and %d tokens are mandatory. Each time the current log file reaches maxFileSize before the current time period ends, it will be archived with an increasing index, starting at 0."
答案2
得分: 0
我终于搞清楚了。Jetty 会将 logback、slf4j 等类加载两次。解决方法是告诉 Jetty 将这些类视为系统类：
WebAppContext.addSystemClasses(server, "org.slf4j.", "ch.qos.logback.", "org.apache.commons.logging.", "org.apache.log4j.", "org.codehaus.janino.");
如此简单，对吧？ 
英文:
I finally figured this out. The logback, slf4j, etc classes where being loaded twice by jetty. The fix was to tell jetty to treat these classes as system classes:
WebAppContext.addSystemClasses(server, "org.slf4j.", "ch.qos.logback.", "org.apache.commons.logging.", "org.apache.log4j.", "org.codehaus.janino.");
So simple right?
通过集体智慧和协作来改善编程学习和解决问题的方式。致力于成为全球开发者共同参与的知识库，让每个人都能够通过互相帮助和分享经验来进步。
评论