I upgraded to 1.0.6 but still see issues. I noticed a new exception today: 08:26:51,788 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - Appender [FILE-jobs.v1] failed to append. java.nio.channels.OverlappingFileLockException at java.nio.channels.OverlappingFileLockException at at sun.nio.ch.FileChannelImpl$SharedFileLockTable.checkList(FileChannelImpl.java:1166) at at sun.nio.ch.FileChannelImpl$SharedFileLockTable.add(FileChannelImpl.java:1068) at at sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:824) at at java.nio.channels.FileChannel.lock(FileChannel.java:860) at at ch.qos.logback.core.FileAppender.safeWrite(FileAppender.java:187) at at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:204) at at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212) at at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:148) at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) 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:48) 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_2(Logger.java:461) at at ch.qos.logback.classic.Logger.debug(Logger.java:539) This seems strange to me as it looks like OutputStreamAppender.subAppend is synchronizing things. iostat reports that the disks aren't particularly busy and each of my webapps writes to its own file so I am not sure what the problem is here. On Tue, Aug 28, 2012 at 1:45 PM, feedly team <feedlydev@gmail.com> wrote:
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]