AmqpAppender webapp startup woes

[gnuphie]

I am having problems with configuration of AmqpAppender related to use in two web apps that run on the same tomcat 7.0.x instance. If I remove AmqpAppender and use the standard log4j appenders, there are no problems. They both work on my development instance as is because app A happens to start first. When app B starts first (as on our QA instances) I get the following:


Apr 16, 2012 10:11:41 AM org.apache.catalina.core.StandardContext listenerStart
SEVERE: Exception sending context initialized event to listener instance of class net.sf.navigator.menu.MenuContextListener
java.lang.NoClassDefFoundError: org/springframework/util/Assert
at org.springframework.amqp.rabbit.connection.Abstrac tConnectionFactory.<init>(AbstractConnectionFactor y.java:44)
at org.springframework.amqp.rabbit.connection.Caching ConnectionFactory.<init>(CachingConnectionFactory. java:77)
at org.springframework.amqp.rabbit.connection.Caching ConnectionFactory.<init>(CachingConnectionFactory. java:100)
at org.springframework.amqp.rabbit.connection.Caching ConnectionFactory.<init>(CachingConnectionFactory. java:68)
at org.springframework.amqp.rabbit.log4j.AmqpAppender .append(AmqpAppender.java:380)
at org.apache.log4j.AppenderSkeleton.doAppend(Appende rSkeleton.java:251)
at org.apache.log4j.helpers.AppenderAttachableImpl.ap pendLoopOnAppenders(AppenderAttachableImpl.java:66 )
at org.apache.log4j.Category.callAppenders(Category.j ava:206)
at org.apache.log4j.Category.forcedLog(Category.java: 391)
at org.apache.log4j.Category.log(Category.java:856)
at org.apache.commons.logging.impl.Log4JLogger.error( Log4JLogger.java:257)
at org.apache.commons.digester.Digester.endElement(Di gester.java:1132)
at com.sun.org.apache.xerces.internal.parsers.Abstrac tSAXParser.endElement(AbstractSAXParser.java:601)
at com.sun.org.apache.xerces.internal.parsers.Abstrac tXMLDocumentParser.emptyElement(AbstractXMLDocumen tParser.java:180)
at com.sun.org.apache.xerces.internal.impl.XMLDocumen tFragmentScannerImpl.scanStartElement(XMLDocumentF ragmentScannerImpl.java:1343)
at com.sun.org.apache.xerces.internal.impl.XMLDocumen tFragmentScannerImpl$FragmentContentDriver.next(XM LDocumentFragmentScannerImpl.java:2756)
at com.sun.org.apache.xerces.internal.impl.XMLDocumen tScannerImpl.next(XMLDocumentScannerImpl.java:648)
at com.sun.org.apache.xerces.internal.impl.XMLDocumen tFragmentScannerImpl.scanDocument(XMLDocumentFragm entScannerImpl.java:511)
at com.sun.org.apache.xerces.internal.parsers.XML11Co nfiguration.parse(XML11Configuration.java:808)
at com.sun.org.apache.xerces.internal.parsers.XML11Co nfiguration.parse(XML11Configuration.java:737)
at com.sun.org.apache.xerces.internal.parsers.XMLPars er.parse(XMLParser.java:119)
at com.sun.org.apache.xerces.internal.parsers.Abstrac tSAXParser.parse(AbstractSAXParser.java:1205)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserI mpl$JAXPSAXParser.parse(SAXParserImpl.java:522)
at org.apache.commons.digester.Digester.parse(Digeste r.java:1666)
at net.sf.navigator.menu.MenuRepository.load(MenuRepo sitory.java:202)
at net.sf.navigator.menu.MenuContextListener.contextI nitialized(MenuContextListener.java:62)
at org.apache.catalina.core.StandardContext.listenerS tart(StandardContext.java:4723)
at org.apache.catalina.core.StandardContext$1.call(St andardContext.java:5226)
at org.apache.catalina.core.StandardContext$1.call(St andardContext.java:5221)
at java.util.concurrent.FutureTask$Sync.innerRun(Futu reTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.jav a:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.run Task(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:680)

App A is a Spring 3.1 / Spring Integration 2.1.1 webapp

App B is a Spring 2.5.6 webapp (which I intend to convert eventually to the same framework as A, but will involve a fair amount of effort)

When App B attempts to start first, the above error occurs and App B ends in a stopped state. If I then click the 'start' button on the tomcat manager it works fine from that point. I can simulate this on my development setup by simply removing App A. App B attempts to start, the error occurs, I click the start button and it continues successfully.

I know from many posts there is not a supported way to enforce web app start order.

As far as I can tell it appears to be related to when the log4j initializes, if the required jars are not already loaded by the class loader, I get the error. Originally, the log4j.properties file was in the $CATALINA_HOME/lib directory, but because the differing spring version I don't want potentially conflicting jars at the tomcat level. So, I pulled the log4j configuration into the respective web apps. Now that the log4j configuration is in the web app, why do I still have the error if all the dependent jars are available? If I go back to a regular log4j appender configuration I do not have this problem, but I need to have the AmqpAppender as I am using the spring-integration web app (App A) for aggregating logs from App A, App B, and many other applications including Erlang applications, Grails applications, all of which are using RabbitMQ (App A is doing many other things as well). And everything is working great except this one glitch with the startup.

I have tried various incantations in App B of delaying the ThreadPoolTaskExecutor (because I am guessing that is where the log events are occurring during startup), but that doesn't seem that should be required as the AmqpAppender should have the necessary jars on hand in the WEB-INF/lib. And, my incantations are not working anyway. The frustrating part is once I manually force the start of App B, everything works wonderfully.

I am worried that part of the problem is maybe dependencies of AmqpAppender on Spring 3.1, but if that is the case why does it work at all even if I force the start, or even if App A is there and started first? Upgrading App B to Spring 3.1 / spring-integration 2.1.1 is not an option in the short term.

I have looked all around for more examples of how to use AmqpAppender properly, and have not found anything yet that helps me identify the errors of my ways.

Any constructive suggestions welcome.

[Gary Russell]

Caveat: This is guesswork because I don't know your environment, and I am making some guesses based on your description...

It sounds like you have spring-amqp and Spring 3.1 in the common classloader ($CATALINA_HOME/lib).

When app A starts first, the appender loads the dependent classes in that classloader so all is well. Assuming you have spring 2.5.6 in app B's war, when that one loads first, Spring is loaded in that classloader. In this case, the appender already has his deps and all is well.

When app B starts first, Spring is loaded in the war classloader; when you get to load the appender, it's not found in the war, so the classloader delegates to the common classloader, which finds the appender, but that classloader doesn't have access to the previously loaded Spring classes in the war classloader.

http://pragmaticjava.blogspot.com/20...s-loading.html

If you run the JVM with -verbose, you'll see exactly where every class is loaded from.

-Dlog4j.debug=true

helps too.

The bottom line, I think, is you can't do what you are trying to do.

A few ideas come to mind to work around this...

1. A custom appender (in the common classloader, with no Spring dependencies) that maintains a queue of log messages and add an <inbound-channel-adapter/> to app A that consumes messages from that queue.
2. Have app B use a RollingFileAppender with very small files and use a <file:inbound--channel-adapter/> to consume them in app A.
...

[gnuphie]

It sounds like you have spring-amqp and Spring 3.1 in the common classloader ($CATALINA_HOME/lib).

At various times in my troubleshooting I have done the above, but the reason I moved all the logging (I think) into the web apps is for exactly the reason that due to the different versions of spring I thought that could be the problem.

I have taken your advice on the -Dlog4j.debug=true, and am looking at your 2 suggestions. I will report back when I have made some progress (or when I am at my wit's end - which is a short trip). Thank you for your help.

[Gary Russell]

I have taken your advice on the -Dlog4j.debug=true

You'll probably find the other suggestion

-verbose

more fruitful because, with modern Sun JVMs, it tells you which jar a class is loaded from (although I will warn you that it provides copious amounts of output).

[gnuphie]

The bottom line, I think, is you can't do what you are trying to do.

I am reluctantly agreeing with your statement. I basically came up with another approach as well, but looking at what it would take to do (maybe three days work and testing), in conjunction with the limitations of the current Spring 2.5 implementation make it unpalatable:

The other approach was write a new AmqpAppender that does not depend on the Spring 3.x framework. This would be nice because there should be a way of dropping a simple amqp appender jar in the CATALINA_HOME/lib that either web app could use and not depend on the entire Spring Framework version getting in the way. We already have one here that does this - it uses slf4j and logback - which is great but my legacy App B Spring 2.5 app doesn't like this setup without a whole lot of work either. Most of the compatibility issues here arise because of the existing pre slf4j-1.6.x dependencies with the slf4j api changes made 1.6.x and after, as well as changes moving from log4j to the slf4j/logback. My App A Spring 3.1 web app already uses slf4j and so switching from log4j to logback or visa-versa is no big deal.

<sigh/>

All these can be worked around, but I would still be left with an aging application lacking the features of Spring 3.1, and in particular Spring Integration 2.1.x, so I will just bite the bullet and upgrade my app.

[gnuphie]

Hmmm. I get looking back at your original suggestions and I think the first is the same as my "other approach"; I guess I was thinking it was something else. It's been a long week and it's only Tuesday.

Same result; upgrade my 2.5.x app to 3.1 / SI 2.1.x