Logback scan not working

问题:

I am having trouble getting the auto scan functionality of logback to work. It doesn't seem to pick up the changes. I have added debug="true" to section and reading it's output, all seems fine. It clearly says the logback.xml file is being monitored for changes every 30 seconds. I am at a loss as to why changes are not being picked up. Just looking for some guidance on how I can troubleshoot this further. Thank you.

I should mention that logback is logging to the file just fine, just that changes to logback configuration file are not being picked up.

logback.xml file

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds" debug="true">

    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

    <property name="LOGS_PATH" value="C:\\Users\\****\\Desktop\\css_dev\\q_logs" />

    <appender name="scheduledTasksAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOGS_PATH}/scheduledTasks.log</file>

        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
            <fileNamePattern>${LOGS_PATH}/scheduledTasks.%i.log.zip</fileNamePattern>
            <minIndex>1</minIndex>
            <maxIndex>25</maxIndex>
        </rollingPolicy>

        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <maxFileSize>5MB</maxFileSize>
        </triggeringPolicy>

        <encoder>
            <pattern>%d{MMM/dd/yyyy HH:mm:ss} %-5level %logger{50} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="tasks" level="warn" additivity="false">
        <appender-ref ref="scheduledTasksAppender"/>
    </logger>
</configuration>

Output to Tomcat log when web application starts:

|-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
|-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
|-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/*****/Desktop/css_dev/ProjectQ/build/web/WEB-INF/classes/logback.xml]
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds
|-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[C:\Users\*****\Desktop\css_dev\ProjectQ\build\web\WEB-INF\classes\logback.xml]] every 30 seconds. 
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
|-INFO in ch.qos.logback.core.joran.action.StatusListenerAction - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
|-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
|-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
|-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/*****/Desktop/css_dev/ProjectQ/build/web/WEB-INF/classes/logback.xml]
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds
|-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[C:\Users\*****\Desktop\css_dev\ProjectQ\build\web\WEB-INF\classes\logback.xml]] every 30 seconds. 
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
|-INFO in ch.qos.logback.core.joran.action.StatusListenerAction - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
|-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
|-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
|-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [scheduledTasksAppender]
|-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [scheduledTasksAppender]
|-INFO in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@298f464e - Will use zip compression
|-INFO in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@298f464e - Will use zip compression
|-WARN in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@298f464e - Large window sizes are not allowed.
|-WARN in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@298f464e - Large window sizes are not allowed.
|-WARN in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@298f464e - MaxIndex reduced to 21
|-WARN in ch.qos.logback.core.rolling.FixedWindowRollingPolicy@298f464e - MaxIndex reduced to 21
|-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
|-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
|-INFO in ch.qos.logback.core.rolling.RollingFileAppender[scheduledTasksAppender] - Active log file name: C:\Users\*****\Desktop\css_dev\q_logs/scheduledTasks.log
|-INFO in ch.qos.logback.core.rolling.RollingFileAppender[scheduledTasksAppender] - Active log file name: C:\Users\*****\Desktop\css_dev\q_logs/scheduledTasks.log
|-INFO in ch.qos.logback.core.rolling.RollingFileAppender[scheduledTasksAppender] - File property is set to [C:\Users\*****\Desktop\css_dev\q_logs/scheduledTasks.log]
|-INFO in ch.qos.logback.core.rolling.RollingFileAppender[scheduledTasksAppender] - File property is set to [C:\Users\*****\Desktop\css_dev\q_logs/scheduledTasks.log]
|-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [tasks] to WARN
|-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [tasks] to WARN
|-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [tasks] to false
|-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [tasks] to false
|-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [scheduledTasksAppender] to Logger[tasks]
|-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [scheduledTasksAppender] to Logger[tasks]
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
|-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5b63e18f - Registering current configuration as safe fallback point
|-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5b63e18f - Registering current configuration as safe fallback point

回答1:

Update (May, 2019) : The bug seems to be fixed now.

=============================================================================

With logback 1.1.7, scanPeriod needs to be explicitly mentioned. Otherwise logback will not scan for changes. This is due to recently introduced bug (Here is the link).

回答2:

You logback.xml appear to be correct.

This is a behavior stated in the manual: http://logback.qos.ch/manual/configuration.html#autoScan,

Given that ReconfigureOnChangeFilter is invoked every time any logger is invoked, regardless of logger level, ReconfigureOnChangeFilter is absolutely performance critical. So much so that in fact, the check whether the scan period has elapsed or not, is too costly in itself. In order to improve performance, ReconfigureOnChangeFilter is in reality "alive" only once every N logging operations. Depending on how often your application logs, the value of N can be modified on the fly by logback. By default N is 16, although it can go as high as 2^16 (= 65536) for CPU-intensive applications.

In short, when a configuration file changes, it will be automatically reloaded but only after several logger invocations and after a delay determined by the scanning period.

Just try to log some more messages and see if the configuration is correctly loaded.

I hope this help you out.

Best regards,

Miguel

回答3:

Scanning does work actually, but the scanning is done on the logback.xml in the target/build directory, which isn't really helpful...

回答4:

I faced similar issue and the root cause turned out to be the way how I was initializing the logback.

Initial Configuration - Not working:

Below is the code which I used to configure logback using Joran.

LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
JoranConfigurator configurator = new JoranConfigurator();
configurator.setContext(context);
InputStream is = new FileInputStream(logConfigPath); // 'logConfigPath' is String path of logback.xml.
configurator.doConfigure(is);

In addition, my logback xml looked as below:

<configuration scan="true" scanPeriod="60 seconds">
....
</configuration>

Somehow, it was not re-scanning my changes in logback.xml.

Troubleshooting

So, I enabled debug mode in logback.xml by adding debug attribute as below.

<configuration scan="true" scanPeriod="60 seconds" debug="true">
....
</configuration>

When I ran the application again, I observed a log statement showing the root cause of the issue.

12:23:58,462 |-WARN in ch.qos.logback.classic.joran.action.ConfigurationAction - Due to missing top level configuration file, reconfiguration on change (configuration file scanning) cannot be done.

This log is being logged by ConfigurationAction.java class when it is not able to find mainURL property in ConfigurationWatchList.

Modified configuration - Scan working like a charm

So I changed the code where I was configuring logback via JoranConfigurator. Instead of sending InputStream as parameter to configurator.doConfigure(is) I used the overloaded doConfigure method which takes file path itself as parameter. Updated code looked like this:

LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory();
JoranConfigurator configurator = new JoranConfigurator();
configurator.setContext(context);
configurator.doConfigure(logConfigPath);// 'logConfigPath' is String path of logback.xml.

Updated debug log:

12:35:37,173 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/E:/Samples/config/logback.xml]
12:35:37,173 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 60 seconds

Thats it!! Hurray :)

EDIT :

Looking at GenericConfigurator class, it turns out that, mainURL is registered with ConfigurationWatchList if we use doConfigure() method which takes URL, String or File as parameter.

Other three overloads of the method (with parameters InputStream, InputSource or List<SaxEvent>) do not register it.

回答5:

With logback 1.2.3, config file rescanning also seems to silently fail if the path to the file contains a +. E.g. this works:

-Dlogback.configurationFile=etc/logback.xml

while this fails:

-Dlogback.configurationFile=etc+/logback.xml

Logback manages to load logback.xml correctly at initialization; it's just the reloading that fails in the latter case. If + doesn't work, it's possible that other characters are also problematic.

I went to file a bug on it but the JIRA instance linked from https://logback.qos.ch/bugreport.html seems to be currently nonfunctional.