SLF4J Dependencies and LocationAwareLogger.log Method Not Found Exception

I recently wrote a new module for incorporation into a couple of our web-applications. Everything seemed perfect - the hoards of unit tests passed, the integration tests succeeded and everything seemed hunky-dory. The module was added to the web-apps POM files and the source code amended to use the new functionality. The web-app was deployed and then disaster....

INFO: Deploying web application archive bm.war
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/RogerHughes/springsource/apache-tomcat-5.5.33-Sandbox/webapps/bm/WEB-INF/lib/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/RogerHughes/springsource/apache-tomcat-5.5.33-Sandbox/webapps/bm/WEB-INF/lib/slf4j-simple-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
Jan 11, 2012 4:57:18 PM org.apache.catalina.startup.HostConfig deployWAR
SEVERE: Error deploying web application archive bm.war
java.lang.NoSuchMethodError: org.slf4j.spi.LocationAwareLogger.log(Lorg/slf4j/Marker;Ljava/lang/String;ILjava/lang/String;Ljava/lang/Throwable;)V
 at org.apache.commons.logging.impl.SLF4JLocationAwareLog.debug(SLF4JLocationAwareLog.java:133)
 at org.apache.tomcat.util.digester.Digester.setDocumentLocator(Digester.java:1171)
 at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startDocument(AbstractSAXParser.java:282)
 at com.sun.org.apache.xerces.internal.impl.dtd.XMLDTDValidator.startDocument(XMLDTDValidator.java:663)
 at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.startEntity(XMLDocumentScannerImpl.java:588)
 at com.sun.org.apache.xerces.internal.impl.XMLVersionDetector.startDocumentParsing(XMLVersionDetector.java:172)
 at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:786)
 at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:737)
 at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:119)
 at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1205)
 at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:522)
 at org.apache.tomcat.util.digester.Digester.parse(Digester.java:1562)
 at org.apache.catalina.startup.ContextConfig.processDefaultWebConfig(ContextConfig.java:669)
 at org.apache.catalina.startup.ContextConfig.defaultWebConfig(ContextConfig.java:606)
 at org.apache.catalina.startup.ContextConfig.start(ContextConfig.java:1052)
 at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:261)
 at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:120)
 at org.apache.catalina.core.StandardContext.start(StandardContext.java:4184)
 at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:760)
 at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:740)
 at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:544)
 at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:884)
 at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:737)
 at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498)
 at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1271)
 at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:301)
 at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:120)
 at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1306)
 at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1570)
 at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1579)
 at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1559)
 at java.lang.Thread.run(Thread.java:680)

...and so, I like everyone else, panicked as this code HAS to go live.

Now, if you take a deep breath and pause for a minute, you’ll notice from the stack trace that the problem is a java.lang.NoSuchMethodError: org.slf4j.spi.LocationAwareLogger.log(...) exception, which was impossible as the JAR file containing the LocationAwareLogger class was in my module’s POM. The second thing to notice is that the stack trace has nothing to do with me... it’s all about xerces XML parsing classes that have been called from the org.apache.catalina.startup.ContextConfig.processDefaultWebConfig(...) method.

I now checked the WAR file to confirm that the JAR containing org.slf4j.spi.LocationAwareLogger was in the lib directory and it was, so it must be to do with versioning. and this is where eclipse’s (or STS’s) POM file editor comes in handly. If you look at the image below you’ll see that tiles-jsp JAR version 2.2 depends upon commons logging, and accesses commons logging using SLF4J’s jcl-over-slf4j version 1.5.8.

I’m using SLF4J version 1.6.1 and that’s the root cause of the problem: the SLF4J developers changed the signature of org.slf4j.spi.LocationAwareLogger.log(Lorg/slf4j/Marker;Ljava/lang/String;ILjava/lang/String;Ljava/lang/Throwable;) between versions 1.5 and 1.6 making my slf4j-api incompatible with the older jcl-over-slf4j JAR.

The fix, it turns out, is fairly trivial, all you need to do is to ensure that jcl-over-slf4j version 1.5.8 is excluded from your Maven dependency graph. This is done by adding the following to the offending org.apache.tiles dependency:

<dependency>
        <groupId>org.apache.tiles</groupId>
        <artifactId>tiles-jsp</artifactId>
        <version>2.2.2</version>
        <exclusions>
            <exclusion>
                <groupId>org.slf4j</groupId>
                <artifactId>slf4j-nop</artifactId>
            </exclusion>
            <exclusion>
                <groupId>org.slf4j</groupId>
                <artifactId>slf4j-api</artifactId>
             </exclusion>
             <exclusion>
                 <groupId>org.slf4j</groupId>
                 <artifactId>jcl-over-slf4j</artifactId>
             </exclusion>
        </exclusions>
    </dependency>

All of which tidies up the Maven dependencies very nicely...

And the moral of this tale? Don't change method signatures in public APIs. Instead, prefer overloading methods where you want to add new functionality. If you must deprecate an old method, leave it in and get it to throw an exception that explains the problem in simple English.