[logback-user] occasional logging exceptions in tomcat

[feedly team]

I am using logback within tomcat using the sifting appender. Occasionally I
see "IO failure in appender java.nio.channels.ClosedChannelException"
exception in catalina.out. I have prudent mode set to true, and although I
have multiple webapps deployed, only one is actually logging messages,
though it is doing so from shared libraries as well as app code and
multi-threaded. I am using slf4j 1.6.1 and logback 1.0.3. How can I debug
this issue? Configuration and full stack below:

<configuration>

  <statusListener
class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator
class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${contextName}"
class="ch.qos.logback.core.rolling.RollingFileAppender">
        <prudent>true</prudent>
        <rollingPolicy
class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          <!-- daily rollover -->

<fileNamePattern>${catalina.home}/logs/${contextName}.%d{yyyy-MM-dd}.log</fileNamePattern>

          <!-- keep 90 days' worth of history -->
          <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
          <pattern>%logger{35}[%level|%thread|%d{HH:mm:ss}]:
%msg%n</pattern>
        </encoder>
      </appender>
    </sift>
  </appender>

  <root level="INFO">
    <appender-ref ref="SIFT" />
  </root>
</configuration>


10:20:05,777 |-ERROR in
ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - IO failure
in appender java.nio.channels.ClosedChannelException
        at java.nio.channels.ClosedChannelException
        at      at
sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:88)
        at      at
sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:243)
        at      at
ch.qos.logback.core.FileAppender.safeWrite(FileAppender.java:188)
        at      at
ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:204)
        at      at
ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211)
        at      at
ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:148)
        at      at
ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
        at      at
ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
        at      at
ch.qos.logback.core.sift.SiftingAppenderBase.append(SiftingAppenderBase.java:94)
        at      at
ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)
        at      at
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:53)
        at      at
ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:282)
        at      at
ch.qos.logback.classic.Logger.callAppenders(Logger.java:269)
        at      at
ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:470)
        at      at
ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)
        at      at ch.qos.logback.classic.Logger.error(Logger.java:583)

After failure, the appender seems to recover, but I assume I am losing log
messages:

10:25:56,689 |-WARN in
ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - Attempted
to append to non started appender [FILE-jobs.v1].
10:25:56,724 |-WARN in
ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - Attempted
to append to non started appender [FILE-jobs.v1].
10:25:56,738 |-WARN in
ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - Attempted
to append to non started appender [FILE-jobs.v1].
10:25:57,449 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
About to instantiate appender of type
[ch.qos.logback.core.rolling.RollingFileAppender]
10:25:57,449 |-INFO in ch.qos.logback.core.joran.action.AppenderAction -
Naming appender as [FILE-jobs.v1]
10:25:57,450 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No
compression will be used
10:25:57,450 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use
the pattern /etc/webserver/logs/jobs.v1.%d{yyyy-MM-dd}.log for the active
file
10:25:57,450 |-INFO in
c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date
pattern is 'yyyy-MM-dd' from file name pattern
'/etc/webserver/logs/jobs.v1.%d{yyyy-MM-dd}.log'.
10:25:57,450 |-INFO in
c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy -
Roll-over at midnight.
10:25:57,450 |-INFO in
c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting
initial period to Tue Aug 28 10:25:57 PDT 2012
10:25:57,450 |-INFO in
ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default
type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder]
property
10:25:57,451 |-INFO in
ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - Active log
file name: /etc/webserver/logs/jobs.v1.2012-08-28.log
10:25:57,451 |-INFO in
ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - File
property is set to [null]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20120828/8d610b1a/attachment-0001.html>