
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]