[logback-dev] [JIRA] Created: (LBCORE-248) Logback Context is not thread safe, throws java.util.ConcurrentModificationException

[Svetla Arnaudova (JIRA)]

Logback Context  is not thread safe, throws java.util.ConcurrentModificationException
-------------------------------------------------------------------------------------

                 Key: LBCORE-248
                 URL: http://jira.qos.ch/browse/LBCORE-248
             Project: logback-core
          Issue Type: Bug
    Affects Versions: 1.0.0
         Environment: Windows 7 OS,  Java 1.6 build 1.6.0_27-b07, Tomcat 7
            Reporter: Svetla Arnaudova
            Assignee: Logback dev list


We see the following exception in Status messages for LoggerContext (see attached pic lbClassicStatus.jpg)

java.util.ConcurrentModificationException
        at java.util.Hashtable$Enumerator.next(Hashtable.java:1031)
        at ch.qos.logback.classic.LoggerContext.syncRemoteView(LoggerContext.java:93)
        at ch.qos.logback.classic.LoggerContext.putProperty(LoggerContext.java:101)
        at ch.qos.logback.core.util.ContextUtil.addHostNameAsProperty(ContextUtil.java:42)
        at ch.qos.logback.classic.joran.action.ConfigurationAction.begin(ConfigurationAction.java:48)
        at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:276)
        at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:148)
        at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:130)
        at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
        at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:147)
        at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:133)
        at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:96)
        at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:55)
        at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
        at com.excilys.ebi.utils.spring.log.logback.LogbackConfigurer.initLogging(LogbackConfigurer.java:90)
        at com.excilys.ebi.utils.spring.log.logback.web.LogbackWebConfigurer.initLogging(LogbackWebConfigurer.java:92)
        at com.excilys.ebi.utils.spring.log.logback.web.LogbackConfigListener.contextInitialized(LogbackConfigListener.java:43)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4723)
        at org.apache.catalina.core.StandardContext$1.call(StandardContext.java:5226)
        at org.apache.catalina.core.StandardContext$1.call(StandardContext.java:5221)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)


Our web application set default configuration logback.xml file in the class path so that logback will use it to configure itself during initialization. It is slightly different (only set info level) from the default basic configuration, used in case there is no such file (see attached logback.xml).

The real logback.xml configuration file is outside of the web application (attached as logback-conf.xml) and we reconfigure logapp to use it with spring integration lib 
https://github.com/excilys/spring-log

Not sure that the rest of the description will be helpful to troubleshoot the problem, but this is how we reproduce it:

This is the example code:

  <context-param>
    <param-name>logbackConfigLocation</param-name>
    <param-value>file:${basedir}/conf/logback.xml</param-value>
  </context-param>

  <listener>
    <listener-class>com.excilys.ebi.utils.spring.log.logback.web.LogbackConfigListener</listener-class>
  </listener>

After spring is loaded LogbackConfigListener class will initialize logback from the given location and reset the logger context. 

Code snip from LogbackConfigListener  init logging below: 

public static void initLogging(String location) throws FileNotFoundException, JoranException {
String resolvedLocation = SystemPropertyUtils.resolvePlaceholders(location);
URL url = ResourceUtils.getURL(resolvedLocation);
ContextSelector selector = ContextSelectorStaticBinder.getSingleton().getContextSelector();
LoggerContext loggerContext = selector.getLoggerContext();

// in the current version logback automatically configures at startup
// the context, so we have to reset it
loggerContext.reset();
ContextInitializer contextInitializer = new ContextInitializer(loggerContext);
contextInitializer.configureByResource(url);

// reset JUL
// don't forget to configure the LevelChangePropagator contextListener
// in the config file!!!
SLF4JBridgeHandler.install();

}
We sometimes receive concurrency modification exception from the logback core code.  We never observe this issue if we remove default logback file from the class path as initial configuration.
To prevent this exception we also delay logback configuration loading.

Thank you,
Svetla


-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira