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]