Logback stops logging after configuration reload

Question

We are evaluating the use of Logback in a multi-server Weblogic environment. On one machine we have two Weblogic server instances (basically two separate JVM processes) running on a same Weblogic domain. The servers log to the same log file (application.log). The Logback configuration (logback.xml) is the same for both servers (shown below):

<configuration scan="true" debug="true">

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>log/application.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>log/application.%d{yyyy-MM-dd}.log</FileNamePattern>
    </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>%d{HH:mm:ss.SSS} [%31.31logger] [%-5level] [%28.-28thread] %msg %xEx %n</pattern>
        </encoder>
    </appender>

    <logger name="org" level="ERROR"/>

    <root level="DEBUG">
        <appender-ref ref="FILE" />
    </root>
</configuration>

Everything works fine until the configuration is edited (e.g. the root logging level changed or a new logger added) after which logging stops completely. Nothing gets printed in the logs, and no Logback error message is visible in the console either. Logback is in debug mode already, which is verified by the following being written to each server's console upon server startup:

18:06:37,949 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
18:06:37,951 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
18:06:37,957 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/opt/bea10/user_projects/KG/resources/config/logback.xml]
18:06:39,457 |-INFO in ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter@158ef4f  - Will scan for changes in file [/opt/bea10/user_projects/KG/resources/config/logback.xml] every 60 seconds.
18:06:39,457 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
18:06:39,471 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
18:06:39,556 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
18:06:40,061 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Pushing component [rollingPolicy] on top of the object stack.
18:06:40,533 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used
18:06:40,563 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern log/application.%d{yyyy-MM-dd}.log for the active file
18:06:40,652 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'log/application.%d{yyyy-MM-dd}.log'.
18:06:40,652 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
18:06:40,654 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Wed Oct 20 17:43:20 EEST 2010
18:06:40,685 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Pushing component [encoder] on top of the object stack.
18:06:41,256 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: log/application.log
18:06:41,257 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [log/application.log]
18:06:41,307 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org] to ERROR
18:06:41,307 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org] to true
18:06:41,307 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
18:06:41,308 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
18:06:41,351 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

The version of Logback is 0.9.24, slf4j is 1.6.0, Weblogic is 10.3 (doubt if that matters) and Java is 1.6.0_12. OS is Solaris. I even tried putting the Java option

-XX:-UseVMInterruptibleIO

because this was suggested to a Logback problem on Solaris here, but this did not help.

Is there a way to make this work? Is it a bad idea altogether to have the two servers to write to the same log file?

Answer 1

Does the prudent property help? It adds overhead but can work around issues with multiple JVMs. I'm not sure your symptoms quite match, but it might be worth a try.

Answer 2

As Alex Poole mentioned earlier, the prudent mode should help. It is also highly recommended to register a status listener, e.g. OnConsoleStatusListener, so that problems occurring during the lifetime of your application, well after logback is initialized, can be reported.

In case the modified configuration file is not well formed logback versions 0.0.29 and later will revert to the previous well-formed configuration file. You did not mention that the new configuration file had a well-formedness problem, si that is why prudent mode is probably the most relevant response.

Answer 3

We have a similar issue, sometimes logback stopping the logging when ever application is redeployed. So we are restarting the application server after every deployment. That resolves the issue.

As restarting Prod servers always is difficult, on further investigation and search we found that is it issue with older versions of logback. We have changed version from 1.1.7 to 1.1.10 and it resolved the issue