I upgraded to 1.0.6 but still see issues. I noticed a new exception today:<div><br></div><div><div>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</div>
<div> at java.nio.channels.OverlappingFileLockException</div><div> at at sun.nio.ch.FileChannelImpl$SharedFileLockTable.checkList(FileChannelImpl.java:1166)</div><div> at at sun.nio.ch.FileChannelImpl$SharedFileLockTable.add(FileChannelImpl.java:1068)</div>
<div> at at sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:824)</div><div> at at java.nio.channels.FileChannel.lock(FileChannel.java:860)</div><div> at at ch.qos.logback.core.FileAppender.safeWrite(FileAppender.java:187)</div>
<div> at at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:204)</div><div> at at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)</div><div> at at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:148)</div>
<div> at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)</div><div> at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)</div>
<div> at at ch.qos.logback.core.sift.SiftingAppenderBase.append(SiftingAppenderBase.java:94)</div><div> at at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)</div><div> at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)</div>
<div> at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:282)</div><div> at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:269)</div><div> at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:470)</div>
<div> at at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:461)</div><div> at at ch.qos.logback.classic.Logger.debug(Logger.java:539)</div><div> </div><div>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.</div>
<br><div class="gmail_quote">On Tue, Aug 28, 2012 at 1:45 PM, feedly team <span dir="ltr"><<a href="mailto:feedlydev@gmail.com" target="_blank">feedlydev@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
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:<div>
<br></div><div><div><configuration></div><div><br></div><div> <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" /></div><div><br></div><div> <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender"></div>
<div> <discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator"></div><div> <defaultValue>unknown</defaultValue></div><div> </discriminator></div><div> <sift></div>
<div> <appender name="FILE-${contextName}" class="ch.qos.logback.core.rolling.RollingFileAppender"></div><div> <prudent>true</prudent></div><div> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"></div>
<div> <!-- daily rollover --></div><div> <fileNamePattern>${catalina.home}/logs/${contextName}.%d{yyyy-MM-dd}.log</fileNamePattern></div><div><br></div><div> <!-- keep 90 days' worth of history --></div>
<div> <maxHistory>90</maxHistory></div><div> </rollingPolicy></div><div> <encoder></div><div> <pattern>%logger{35}[%level|%thread|%d{HH:mm:ss}]: %msg%n</pattern></div>
<div> </encoder></div><div> </appender></div><div> </sift></div><div> </appender></div><div><br></div><div> <root level="INFO"></div><div> <appender-ref ref="SIFT" /></div>
<div> </root></div><div></configuration></div><div><br></div><div><br></div><div>10:20:05,777 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - IO failure in appender java.nio.channels.ClosedChannelException</div>
<div><div> at java.nio.channels.ClosedChannelException</div><div> at at sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:88)</div><div> at at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:243)</div>
<div> at at ch.qos.logback.core.FileAppender.safeWrite(FileAppender.java:188)</div><div> at at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:204)</div><div> at at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211)</div>
<div> at at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:148)</div><div> at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)</div>
<div> at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)</div><div> at at ch.qos.logback.core.sift.SiftingAppenderBase.append(SiftingAppenderBase.java:94)</div>
<div> at at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)</div><div> at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:53)</div>
<div> at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:282)</div><div> at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:269)</div><div> at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:470)</div>
<div> at at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)</div><div> at at ch.qos.logback.classic.Logger.error(Logger.java:583)</div></div><div><br></div></div><div>After failure, the appender seems to recover, but I assume I am losing log messages:</div>
<div><br></div><div><div>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].</div><div>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].</div>
<div>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].</div><div>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]</div>
<div>10:25:57,449 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE-jobs.v1]</div><div>10:25:57,450 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used</div>
<div>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</div><div>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'.</div>
<div>10:25:57,450 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.</div><div>10:25:57,450 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Tue Aug 28 10:25:57 PDT 2012</div>
<div>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</div><div>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</div>
<div>10:25:57,451 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE-jobs.v1] - File property is set to [null]</div></div><div><br></div>
</blockquote></div><br></div>