Details
-
Bug
-
Resolution: Fixed
-
Major
-
1.1.7
-
None
-
tc 7.0.69
Description
Hi logback developers,
we are facing an unexpected behaviour with version 1.1.7 of logback-access and -core, which we bundle with tomcat: after the current log period has elapsed, logback fails to log the next period. (Actually we use a daily rotation config, but to provoque this behaviour, I switched to a minutely rotation and the result is the same finally.)
When we use the older 1.1.5 version of both libs, everything is fine with the exact same config, except for setting the full path to the logback-access.xml.
catalina logs:
12:17:31,342 |-INFO in ch.qos.logback.access.joran.action.ConfigurationAction - debug attribute not set 12:17:31,343 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 12:17:31,368 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ACCESS-LOG] 12:17:31,615 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1100361396 - No compression will be used 12:17:31,618 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1100361396 - Will use the pattern /var/log/APP/PECSOMEFE-APP15/PECSOMEFE-APP15.access.log.%d{yyyy-MM-dd'T'HH_mm} for the active file 12:17:31,622 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd'T'HH_mm' from file name pattern '/var/log/APP/MYAPP/MYAPP.access.log.%d{yyyy-MM-dd'T'HH_mm}'. 12:17:31,622 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over every minute. 12:17:31,623 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Mon May 23 12:17:31 CEST 2016 12:17:31,624 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[ACCESS-LOG] - Active log file name: /var/log/APP/MYAPP/MYAPP.access.log.2016-05-23T12_17 12:17:31,624 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[ACCESS-LOG] - File property is set to [null] 12:17:31,625 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ACCESS-LOG] to ch.qos.logback.access.tomcat.LogbackValve[null] 12:17:31,625 |-INFO in ch.qos.logback.access.joran.action.ConfigurationAction - End of configuration. 12:17:31,626 |-INFO in ch.qos.logback.access.joran.JoranConfigurator@3c9f2e3d - Registering current configuration as safe fallback point 12:17:31,627 |-INFO in ch.qos.logback.access.tomcat.LogbackValve[null] - Done configuring 12:18:05,737 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Mon May 23 12:17:31 CEST 2016 12:18:05,742 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[ACCESS-LOG] - Appender [ACCESS-LOG] failed to append. java.lang.UnsupportedOperationException at java.lang.UnsupportedOperationException at at ch.qos.logback.access.tomcat.LogbackValve.getScheduledExecutorService(LogbackValve.java:452) at at ch.qos.logback.core.rolling.helper.TimeBasedArchiveRemover.cleanAsynchronously(TimeBasedArchiveRemover.java:232) at at ch.qos.logback.core.rolling.TimeBasedRollingPolicy.rollover(TimeBasedRollingPolicy.java:178) at at ch.qos.logback.core.rolling.RollingFileAppender.attemptRollover(RollingFileAppender.java:204) at at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:183) at at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:224) at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100) at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:268) at at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) at at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436) at at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078) at at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) at at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) at at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at at java.lang.Thread.run(Thread.java:745)
relevant line in server.xml is:
<Valve className="ch.qos.logback.access.tomcat.LogbackValve" quiet="false" filename="conf/logback-access-localhost.xml" />
and our logback-access-localhost.xml:
<?xml version="1.0" encoding="UTF-8"?> <configuration> <appender name="ACCESS-LOG" class="ch.qos.logback.core.rolling.RollingFileAppender"> <append>true</append> <encoder class="ch.qos.logback.access.PatternLayoutEncoder"> <charset>utf-8</charset> <pattern>%h %l %u %t "%r" %s %b "%i{Referer}" "%i{User-Agent}" %D "%i{X-Forwarded-For}" %i{x-request-id}</pattern> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>/var/log/APP/MYAPP/MYAPP.access.log.%d{yyyy-MM-dd'T'HH_mm}</fileNamePattern> <maxHistory>60<!-- days --></maxHistory> </rollingPolicy> </appender> <appender-ref ref="ACCESS-LOG" /> </configuration>
Thanks in advance and best regards,
Andreas
Attachments
Issue Links
- is duplicated by
-
LOGBACK-1218 LogbackValve conflict with TimeBasedRollingPolicy
- Resolved