ContextLoader static logger causes early log4j initialization [SPR-5977]

[spring-projects-issues]

Andrew Ebaugh opened SPR-5977 and commented

I am running into an issue using the Log4jConfigListener; in my web.xml, I have the listeners configured as follows:

<!-- context listeners -->
<listener>
<listener-class>org.springframework.web.util.Log4jConfigListener</listener-class>
</listener>

<listener>
    <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
</listener>

Prior to the Log4jConfigListener.contextInitialized(...) method being invoked, log4j errors are showing up in my console output:
log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: /../../logs/mark.log (No such file or directory)
at java.io.FileOutputStream.openAppend(Native Method)
at java.io.FileOutputStream.<init>(FileOutputStream.java:177)
at java.io.FileOutputStream.<init>(FileOutputStream.java:102)
at org.apache.log4j.FileAppender.setFile(FileAppender.java:289)
at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:163)
at org.apache.log4j.DailyRollingFileAppender.activateOptions(DailyRollingFileAppender.java:215)
at org.apache.log4j.config.PropertySetter.activate(PropertySetter.java:256)
at org.apache.log4j.xml.DOMConfigurator.parseAppender(DOMConfigurator.java:220)
at org.apache.log4j.xml.DOMConfigurator.findAppenderByName(DOMConfigurator.java:150)
at org.apache.log4j.xml.DOMConfigurator.findAppenderByReference(DOMConfigurator.java:163)
at org.apache.log4j.xml.DOMConfigurator.parseChildrenOfLoggerElement(DOMConfigurator.java:425)
at org.apache.log4j.xml.DOMConfigurator.parseRoot(DOMConfigurator.java:394)
at org.apache.log4j.xml.DOMConfigurator.parse(DOMConfigurator.java:829)
at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:712)
at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:618)
at org.apache.log4j.helpers.OptionConverter.selectAndConfigure(OptionConverter.java:470)
at org.apache.log4j.LogManager.<clinit>(LogManager.java:122)
at org.apache.log4j.Logger.getLogger(Logger.java:104)
at org.apache.commons.logging.impl.Log4JLogger.getLogger(Log4JLogger.java:289)
at org.apache.commons.logging.impl.Log4JLogger.<init>(Log4JLogger.java:109)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at org.apache.commons.logging.impl.LogFactoryImpl.createLogFromClass(LogFactoryImpl.java:1116)
at org.apache.commons.logging.impl.LogFactoryImpl.discoverLogImplementation(LogFactoryImpl.java:914)
at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:604)
at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:336)
at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:310)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:685)
at org.springframework.web.context.ContextLoader.<clinit>(ContextLoader.java:144)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
...
The log file path referenced in the error message above uses the webapp.root system property set by the Log4jWebConfigurer, so when log4j.xml is read prior to the log4j listener starting, the path is invalid.

I've tracked this back to where the ContextLoader declares its logger; it gets created when the ContextLoaderListener is instantiated:
private static final Log logger = LogFactory.getLog(ContextLoader.class);
This translates through to the default log4j.xml attempting to be loaded when it shouldn't. At least in Tomcat 6, the listeners all appear to be instantiated, then the contextInitialized(...) method is called on them in the order declared in the web.xml.

I also note that it appears this logger field changed to a static somewhere between the Spring 2.5 and 2.5.6 releases, although don't think this is related.

---

Affects: 3.0 M3

Referenced from: commits 6b824d9

[spring-projects-issues]

Juergen Hoeller commented

This might also be caused by ContextLoaderListener extending ContextLoader in Spring 3.0 now, versus just delegating to ContextLoader in previous Spring versions. I've changed the logger to an instance field, which should solve the issue in any case. Thanks for raising this!

Juergen

[spring-projects-issues]

Andrew Ebaugh commented

In your fix, is the ContextLoaderListener still extending the ContextLoader?

If so, even with changing the logger to an instance field, it would probably still happen. Tomcat appears to first run through the list of listeners and create instances of each, then run through the list again and call the contextInitialized(...) methods. Seems like the logger instance would still get initialized before the Log4jConfigListener had done its thing.

My workaround was to write a listener that waits until the contextInitialized(...) is invoked to create the ContextLoader instance, which sounds like how it used to work.

[spring-projects-issues]

Juergen Hoeller commented

Good point. I've revised ContextLoader's code to only obtain Log instances on the fly within the implementation methods, not holding it in any kind of field. That should not cause any issues at listener instantiation time then.

Juergen