Bug 778802 (SOA-1252)

I have a log when after several runs I was able to meet the issue from subject. I compared two runs (a right one and a wrong one) in the log that is attached. They are almost the same but the wrong one has some additional output:
=======================================================
2009-03-24 15:46:56,890 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Creating a JMS Connection for poolKey : {java.naming.provider.url=jnp://127.0.0.1:1099, java.naming.factory.url.pkgs=org.jnp.interfaces, java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, connection-factory=ConnectionFactory}

...

2009-03-24 15:46:56,896 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] JMS Security principal [null] using JMS Security : false

...

2009-03-24 15:46:56,897 DEBUG [org.jboss.remoting.Client] starting callback Connector: InvokerLocator [bisocket://127.0.1.1:1255975367/callback?serverSocketClass=org.jboss.jms.ser
ver.remoting.ServerSocketWrapper&isCallbackServer=true&callbackServerProtocol=bisocket&datatype=jms&guid=3j011-rgro8d-fsop5xdl-1-fsopa3r5-6z&callbackServerHost=127.0.1.1&callbackS
erverPort=1255975367&clientMaxPoolSize=1&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper]
2009-03-24 15:46:56,898 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] SocketServerInvoker[UNINITIALIZED] setting pingFrequency to 214748364
2009-03-24 15:46:56,898 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] SocketServerInvoker[UNINITIALIZED] setting pingWindowFactor to 10
2009-03-24 15:46:56,900 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] did not find server socket factory configuration as mbean service or classname.
 Creating default server socket factory.
2009-03-24 15:46:56,900 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] created server socket factory javax.net.DefaultServerSocketFactory@6293df2c
2009-03-24 15:46:56,900 DEBUG [org.jboss.remoting.transport.Connector] org.jboss.remoting.transport.Connector@87505bd started
2009-03-24 15:46:56,900 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) added client callback handler CallbackManager[778df39d] with se
ssion id of 3j011-rgro8d-fsop5xdl-1-fsopa3r5-6x+3j011-rgro8d-fsop5xdl-1-fsopa3r8-72 and callback handle object of null.
2009-03-24 15:46:56,900 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@1692012f from registry

...

2009-03-24 15:46:56,901 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] Session id for callback handler is 3j011-rgro8d-fsop5xdl-1-fsopa3r2-6u+3j011-rgro8d-fsop5x
dl-1-fsopa3r5-70
2009-03-24 15:46:56,901 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[3j011-rgro8d-fsop5xdl-1-fsopa3r2-6u+3j011-rgro8d-fsop5xdl-1-f
sopa3r5-70] using callbackTimeout value 10000
2009-03-24 15:46:56,901 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[127.
0.0.1:4457]
2009-03-24 15:46:56,901 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[SocketServerInvoker[127.0.0.1:4457]] setting callback handler t
o ServerInvokerCallbackHandler[3j011-rgro8d-fsop5xdl-1-fsopa3r2-6u+3j011-rgro8d-fsop5xdl-1-fsopa3r5-70]
=======================================================


Then there's something really strange. Correct run says:
2009-03-24 15:45:58,884 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Number of Sessions in the pool with acknowledgeMode: 1 is now 4

while the wrong one:
2009-03-24 15:46:56,940 DEBUG [org.jboss.jms.server.connectionfactory.ConnectionFactoryJNDIMapper] Server[0].ConnFactoryJNDIMapper received notification from node 0
2009-03-24 15:46:56,943 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] adding callback handler ServerInvokerCallbackHandler[3j011-rgro8d-fsop5xdl-1-fsopa3r2-6u+3j011-rgro8d-fsop5xdl-1-fsopa3r5-70]
2009-03-24 15:46:56,943 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] found calllback handler for remoting session ...-fsopa3r2-6u UID=3j011-rgro8d-fsop5xdl-1-fsopa3r2-6u
2009-03-24 15:46:56,943 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] registered connection ConnectionEndpoint[e7-fs3aposf-1-ldx5posf-d8orgr-110j3] as ...-fsopa3r2-6u
2009-03-24 15:46:56,946 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Number of Sessions in the pool with acknowledgeMode: 1 is now 1

Then everything is the same up to the point where the message gets delivered into the wrong service:
2009-03-24 15:46:58,471 INFO  [STDOUT] ======= Queue Notified pre:
2009-03-24 15:46:58,471 INFO  [STDOUT] [Queue notifier test - no JBM Message to notify].

The right run reads:
2009-03-24 15:46:00,325 INFO  [STDOUT] dump:
2009-03-24 15:46:00,326 INFO  [STDOUT] [ message: [ JBOSS_XML ]

Attachment: Added: server.log.bz2

Link: Added: This issue is related to JBQA-1732

Response from Kevin:

This is very interesting because it suggests that something is calling into the pool from an invalid classloader, i.e. one which is *not* associated with the esb deployment.
I'm not sure why this would cause any messages to be delivered to a different queue but it is worth pursuing further.
Can you change the logging so that it shows the thread information and rerun the test?  This may give me an idea of where to look.

Attached another log with org.jboss.jms and org.jboss.messaging set to TRACE. Thread IDs are also included (log4j pattern (%t:%x)).
A wrong run starts at 10:46:32,364. A good one at 10:46:05,234.

Attachment: Added: server2.log.bz2

The problem was between a keyboard and a seat.