[logback-user] occasional logging exceptions in tomcat

feedly team feedlydev at gmail.com
Fri Aug 31 18:09:48 CEST 2012 

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 at 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]
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20120831/a41deb4b/attachment.html>

More information about the Logback-user mailing list