Bug 778802 (SOA-1252) - Erratic JMS messages delivered to wrong queues
Summary: Erratic JMS messages delivered to wrong queues
Keywords:
Status: CLOSED NOTABUG
Alias: SOA-1252
Product: JBoss Enterprise SOA Platform 4
Classification: JBoss
Component: JBossESB, JBoss Messaging
Version: 4.3 CP01
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: 4.3 CP01
Assignee: Default User
QA Contact:
URL: http://jira.jboss.org/jira/browse/SOA...
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-03-25 09:40 UTC by Martin Vecera
Modified: 2009-03-25 13:14 UTC (History)
0 users

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2009-03-25 13:14:44 UTC
Type: Bug


Attachments (Terms of Use)
server.log.bz2 (150.32 KB, application/x-bzip)
2009-03-25 09:41 UTC, Martin Vecera
no flags Details
server2.log.bz2 (346.33 KB, application/x-bzip)
2009-03-25 10:18 UTC, Martin Vecera
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker SOA-1252 0 None None None Never

Description Martin Vecera 2009-03-25 09:40:32 UTC
project_key: SOA

Sometimes it happens that the JMS message sent to a gateway queue is in fact delivered to a gateway queue of different service. This is similar to JBQA-1732

Comment 1 Martin Vecera 2009-03-25 09:40:55 UTC
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 ]


Comment 2 Martin Vecera 2009-03-25 09:41:49 UTC
Attachment: Added: server.log.bz2


Comment 3 Martin Vecera 2009-03-25 09:42:14 UTC
Link: Added: This issue is related to JBQA-1732


Comment 4 Martin Vecera 2009-03-25 09:43:10 UTC
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.

Comment 5 Martin Vecera 2009-03-25 10:18:36 UTC
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.

Comment 6 Martin Vecera 2009-03-25 10:18:36 UTC
Attachment: Added: server2.log.bz2


Comment 7 Martin Vecera 2009-03-25 13:14:34 UTC
The problem was between a keyboard and a seat.


Note You need to log in before you can comment on or make changes to this bug.