JBoss logback scan=true not reloading the changes automatically
Hi All, We are using logback as the logger in our application. The environment details are JBoss 5.1, logback logback 0.9.29 and SL4j 1.6.1. The application is in ear format. As per the document, i ve placed scan = true and specified a scan period. Now when i change the logger level when the application is running, it is not reloaded automatically even after the specified time interval. Once i restart the app server, the changes are detected. We tried <jmxConfigurator/> and then changed the levels using jmx console. That approach has worked fine and logger levels are changed dynamically. My requirement is to get a solution with out using jmx. so that when i change the level, it has to reflect with out restarting the server. My logback.xml is modelled as per the documentation site, i would like to know, if there is anything more specific to be done? I wanted to minimize the dependency of logback api in our code, so i am using sl4j as wrapper. Any additional properties need to be set, other than scan=true? All the configuration properties are logged in the console when i start the server. It even logs, the reload time period which i ve given. Thanks for the help. K Nair -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
Hello, You should be aware of the fact that auto scan requires several logging requests. From the documentation [1]: Behind the scenes, when you set the scan attribute to true, a TurboFilter called ReconfigureOnChangeFilter will be installed. TurboFilters are described in a later chapter. As a consequence, scanning is done "in-thread", that is any time a printing method of logger is invoked. For example, for a logger named myLogger, when you write "myLogger.debug("hello");", and if the scan attribute is set to true, then ReconfigureOnChangeFilter will be invoked. Moreover, the said filter will be invoked even if myLogger is disabled for the DEBUG level. 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. [1] http://logback.qos.ch/manual/configuration.html#autoScan On 12.04.2013 08:43, KNair wrote:
Hi All,
We are using logback as the logger in our application. The environment details are JBoss 5.1, logback logback 0.9.29 and SL4j 1.6.1. The application is in ear format. As per the document, i ve placed scan = true and specified a scan period. Now when i change the logger level when the application is running, it is not reloaded automatically even after the specified time interval. Once i restart the app server, the changes are detected.
We tried <jmxConfigurator/> and then changed the levels using jmx console. That approach has worked fine and logger levels are changed dynamically.
My requirement is to get a solution with out using jmx. so that when i change the level, it has to reflect with out restarting the server. My logback.xml is modelled as per the documentation site, i would like to know, if there is anything more specific to be done? I wanted to minimize the dependency of logback api in our code, so i am using sl4j as wrapper. Any additional properties need to be set, other than scan=true?
All the configuration properties are logged in the console when i start the server. It even logs, the reload time period which i ve given.
Thanks for the help.
K Nair
-- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com. _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
-- Ceki 65% of statistics are made up on the spot
Thanks for the quick response. I understood the situation, my application is heavily threaded and logs various events almost every second. The scan period is set as 30 seconds. Is there a way to find the value of N which is calculated by logback? Or even force it to reload? If an upgrade of logback helps me in this, i can upgrade it, but as we are using JBoss 5.1, which will be the best logback and sl4j combination? Thanks K Nair -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
slf4j 1.7.x series is fully backward compatible with the 1.6.x series. So you should be able to upgrade to the latest slf4j and logback versions without problems. Please report whether this helped. N=16 in logback version 1.0.1 and earlier. Only in 1.0.2 and later does N vary. Currently there is no way to see the value of N, if you deem it necessary, please create a bug report and ask for this feature. On 12.04.2013 09:08, KNair wrote:
Thanks for the quick response.
I understood the situation, my application is heavily threaded and logs various events almost every second. The scan period is set as 30 seconds. Is there a way to find the value of N which is calculated by logback? Or even force it to reload? If an upgrade of logback helps me in this, i can upgrade it, but as we are using JBoss 5.1, which will be the best logback and sl4j combination?
Thanks K Nair
-- Ceki 65% of statistics are made up on the spot
I ll upgrade sl4j and logback and try again. Will report after trying this. Thanks K Nair -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
Hi I ve upgraded SL4J and Logback, still no luck, this time i tried with a relatively less complex application(Lesser number of logging), still its not picking up. Only jmx approach seem to be working for me. I used SL4j1.7.5 and logback 1.0.11. I ve put a debug on LOG variable and inspected it. I could see in TurboFilter, inside ReConfigureChangeFilter,maxCallerDataDepth = 8 and invocationCounter = 542202, will these have any effects? Or is there is any particular watch point that will help me to identify what is delaying the reload? Here is my logback xml. Is it because some thing is wrong in my xml? But even then it picks up when i restart the application. <configuration scan="true" scanPeriod="30 seconds"> <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${jboss.server.home.dir}/log/server.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern> <maxHistory>30</maxHistory> </rollingPolicy> <encoder> <pattern>%date %-5level [%logger] %msg%n</pattern> </encoder> </appender> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%date %-5level [%logger] %msg%n</pattern> </encoder> </appender> <logger name="org.apache" level="WARN"/> <logger name="com.opensymphony.oscache" level="ERROR"/> <logger name="org.hibernate" level="WARN"/> <logger name="org.activemq" level="WARN"/> <logger name="org.jnp" level="WARN"/> <logger name="com.ourapp" level="INFO"/> <logger name="com.ourapp.settings" level="WARN"/> <logger name="com.ourapp.commons.utilities" level="ERROR"/> <logger name="org.quartz" level="WARN"/> <root level="INFO"> <appender-ref ref="CONSOLE"/> </root> </configuration> Thanks K Nair -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
Access to logback's internal messages should be helpful. Please try setting the debug attribute of config element to true: <configuration debug="true" scan=... > See also [1]. The internal messages should indicate whether ReConfigureChangeFilter is active or not. http://logback.qos.ch/manual/configuration.html#automaticStatusPrinting On 13.04.2013 09:02, KNair wrote:
Hi
I ve upgraded SL4J and Logback, still no luck, this time i tried with a relatively less complex application(Lesser number of logging), still its not picking up. Only jmx approach seem to be working for me. I used SL4j1.7.5 and logback 1.0.11.
I ve put a debug on LOG variable and inspected it. I could see in TurboFilter, inside ReConfigureChangeFilter,maxCallerDataDepth = 8 and invocationCounter = 542202, will these have any effects? Or is there is any particular watch point that will help me to identify what is delaying the reload?
Here is my logback xml. Is it because some thing is wrong in my xml? But even then it picks up when i restart the application.
<configuration scan="true" scanPeriod="30 seconds">
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${jboss.server.home.dir}/log/server.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy> <encoder> <pattern>%date %-5level [%logger] %msg%n</pattern> </encoder> </appender>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%date %-5level [%logger] %msg%n</pattern> </encoder> </appender>
<logger name="org.apache" level="WARN"/> <logger name="com.opensymphony.oscache" level="ERROR"/>
<logger name="org.hibernate" level="WARN"/>
<logger name="org.activemq" level="WARN"/>
<logger name="org.jnp" level="WARN"/>
<logger name="com.ourapp" level="INFO"/> <logger name="com.ourapp.settings" level="WARN"/> <logger name="com.ourapp.commons.utilities" level="ERROR"/> <logger name="org.quartz" level="WARN"/>
<root level="INFO"> <appender-ref ref="CONSOLE"/> </root>
</configuration>
Thanks
K Nair
-- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com. _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
-- Ceki 65% of statistics are made up on the spot
Our application is not coupled with logback during compile time, so it wont be possible to do StatusPrint for me. But i feel ReConfigurationFilter is active, as every time my debugger catch it, i can see next fire time is set. By setting debug = true , it prints Log statements during start time, yes there are some logs like 12:48:40,693 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. After this, there is no more INFO statement from joran packages printed when i change logger level. I m still waiting for my other application to reach 2^16 logging statements Thanks for the quick response. K Nair -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
Could you please post the internal status messages? More in-line. On 13.04.2013 09:53, KNair wrote:
Our application is not coupled with logback during compile time, so it wont be possible to do StatusPrint for me. But i feel ReConfigurationFilter is active, as every time my debugger catch it, i can see next fire time is set.
The debug="true" configuration directives enables output of internal status messages. You do not need to invoke StatusPrinter directly from your code. Please read the whole section, *all* twelve or so paragraphs in http://goo.gl/oR9SL Status messages give important clues as whether ReconfigureOnChangeFilter is installed, active (started=true), the actual files it is scanning as well as the scanning frequency. Are there any *status* messages by ReconfigureOnChangeFilter ? If not, it may mean that ReconfigureOnChangeFilter has not been installed, probably because there is another logback.xml configuration file picked up before your intended logback.xml configuration file. Quoting from the documentation: In the absence of status messages, tracking down a rogue logback.xml configuration file can be difficult, especially in production where the application source cannot be easily modified. To help identify the location of a rogue configuration file, you can set a StatusListener via the "logback.statusListenerClass" system property (defined below) to force output of status messages. The "logback.statusListenerClass" system property can also be used to silence output automatically generated in case of errors. To track a rogue configuratoin file, you should to set the "logback.statusListenerClass" system property to "ch.qos.logback.core.status.OnConsoleStatusListener" as explained at http://logback.qos.ch/manual/configuration.html#logback.statusLC
By setting debug = true , it prints Log statements during start time, yes there are some logs like 12:48:40,693 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. After this, there is no more INFO statement from joran packages printed when i change logger level.
I m still waiting for my other application to reach 2^16 logging statements
We are not sadists. :-) It would be ridiculous to ask users to log 65536 times for auto-scanning to be active. The 2^16 limit is reached dynamically in *extremely* busy systems just after a few seconds. Under regular load, the limit is much lower and corresponds to just a few seconds of logging. I suspect that there is something else going on, for example that there is another rogue logback.xml configuration file in your setup.
Thanks for the quick response.
K Nair
-- Ceki 65% of statistics are made up on the spot
Hi I think that has helped me to nail the issue, Thanks a lot In Logs SLF4J: Class path contains multiple SLF4J bindings. SLF4J: Found binding in [vfszip:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/lib/logback-classic-1.0.11.jar/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: Found binding in [vfszip:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/common/lib/slf4j-jboss-logging.jar/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. 11:14:33,784 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 11:14:33,791 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 11:14:33,792 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] 11:14:33,851 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@9fb5f1 - URL [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] is not of type file 11:14:33,784 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 11:14:33,791 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 11:14:33,792 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] 11:14:33,851 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@9fb5f1 - URL [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] *is not of type file* 11:14:33,959 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds 11:14:33,959 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds 11:14:33,959 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in *[[]] *every 30 seconds. 11:14:33,959 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[]] every 30 seconds. 11:14:33,960 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter 11:14:33,960 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter 11:14:33,966 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin 11:14:33,966 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin 11:14:33,974 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 11:14:33,974 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 11:14:33,993 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 11:14:33,993 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 11:14:34,164 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used 11:14:34,164 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used 11:14:34,179 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern logFile.%d{yyyy-MM-dd}.log for the active file 11:14:34,179 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern logFile.%d{yyyy-MM-dd}.log for the active file 11:14:34,195 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'logFile.%d{yyyy-MM-dd}.log'. Now in property-service.xml (Jboss) i set <attribute name="Properties"> logback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener logback.configurationFile=file:///D:/myapps/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml </attribute> It's reloading on the fly :) Is this the right approach? Thanks K Nair -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
As you are probably already aware, ReconfigureOnChangeFilter does not know how to handle URLs of type "vfsfile://", i.e. JBoss' virtual file system. Excplicitly setting the path to the configuration file with logback.configurationFile=file:///path seems like a reasonable approach. Cheers, On 15.04.2013 09:27, KNair wrote:
Hi
I think that has helped me to nail the issue, Thanks a lot In Logs
SLF4J: Class path contains multiple SLF4J bindings. SLF4J: Found binding in [vfszip:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/lib/logback-classic-1.0.11.jar/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: Found binding in [vfszip:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/common/lib/slf4j-jboss-logging.jar/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. 11:14:33,784 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 11:14:33,791 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 11:14:33,792 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] 11:14:33,851 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@9fb5f1 - URL [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] is not of type file 11:14:33,784 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 11:14:33,791 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 11:14:33,792 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] 11:14:33,851 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@9fb5f1 - URL [vfsfile:/D:/myapps/apps/jbossback/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml] *is not of type file* 11:14:33,959 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds 11:14:33,959 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds 11:14:33,959 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in *[[]] *every 30 seconds. 11:14:33,959 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[]] every 30 seconds. 11:14:33,960 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter 11:14:33,960 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter 11:14:33,966 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin 11:14:33,966 |-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin 11:14:33,974 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 11:14:33,974 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender] 11:14:33,993 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 11:14:33,993 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 11:14:34,164 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used 11:14:34,164 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used 11:14:34,179 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern logFile.%d{yyyy-MM-dd}.log for the active file 11:14:34,179 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern logFile.%d{yyyy-MM-dd}.log for the active file 11:14:34,195 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'logFile.%d{yyyy-MM-dd}.log'.
Now in property-service.xml (Jboss) i set <attribute name="Properties">
logback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener
logback.configurationFile=file:///D:/myapps/jboss-5.1.0.GA_BE/jboss-5.1.0.GA_BE/server/default/conf/logback.xml
</attribute>
It's reloading on the fly :) Is this the right approach?
Thanks
K Nair
-- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com. _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
-- Ceki 65% of statistics are made up on the spot
Yes, i checked ConfigurationWatchList and found the file object to be returned as null. Thanks K Nair. -- View this message in context: http://logback.10977.n7.nabble.com/JBoss-logback-scan-true-not-reloading-the... Sent from the Users mailing list archive at Nabble.com.
participants (2)
-
ceki -
KNair