Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1181

RollingFileAppender throws UnsupportedOperationEx after elapsed period

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Major Major
    • 1.1.9
    • 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

        Activity

          People

            ceki Ceki Gülcü
            aroepenack Andreas von Röpenack
            Votes:
            2 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: