HornetQ - Destroying connection that could not be successfully matched

[henry.short]

Under JBoss 7.1.1, I'm getting these warnings once I switched to using java:/JmsXA from ConnectionFactory. Any help would be greatly appreciated.

2012-08-16 17:44:58,585 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ajp-/192.168.4.206:8009-2) IJ000612: Destroying connection that could not be successfully matched: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@42e2ee9c[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@1f3067cf connection handles=0 lastUse=1345139063913 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@22ef5708 pool internal context=SemaphoreArrayListManagedConnectionPool@510f4e32[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@409f6612[xaResource=org.hornetq.ra.HornetQRAXAResource@f3ae023 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=null]

2012-08-16 17:44:58,632 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Thread-42 (HornetQ-client-global-threads-1100398953)) IJ000612: Destroying connection that could not be successfully matched: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7be316db[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@13d9fa48 connection handles=0 lastUse=1345139098616 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@22ef5708 pool internal context=SemaphoreArrayListManagedConnectionPool@510f4e32[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@79f1c367[xaResource=org.hornetq.ra.HornetQRAXAResource@4bbe9726 pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=null]

[jbertram]

Do you have a reproducer you can share or at the very least the code which is using JmsXA?

[jbertram]

Also, could you activate TRACE logging for "org.hornetq.ra", reproduce the problem, and attach the log?

[henry.short]

Here is an example of our client sending a message to a topic MDB. Let me know if you need anymore info.

TopicConnectionFactory factory = (TopicConnectionFactory)context.lookup("java:/JmsXA");
Topic topic = (Topic)context.lookup("topic/Status");
TopicConnection connection = factory.createTopicConnection();

TopicSession session = connection.createTopicSession(false, Session.AUTO_ACKNOWLEDGE);
TopicPublisher publisher = session.createPublisher(topic);
publisher.setDeliveryMode(DeliveryMode.NON_PERSISTENT);

MapMessage message = session.createMapMessage();
..
publisher.send(message);

standalone xml:

<jms-topic name="StatusService">
  <entry name="topic/Status"/>
  <entry name="java:jboss/exported/jms/topic/Status"/>
</jms-topic>

[jbertram]

Could you supply the logging I requested previously?

[jbertram]

Also, where is this code being executed (e.g. EJB, Servlet, etc.)?

[henry.short]

I will generate the log file now. The code is being executed inside an EJB.

[henry.short]

I have attached the trace file. Let me know if you need anything else. Thanks for your help.

[henry.short]

Did the trace file provide any insight Justin?

[jbertram]

It looks like the match is failing because the "type" of the connection doesn't match.  In other words, you are trying to use a Topic connection but the connection in the pool is a Queue connection (or vice versa).

Could you switch your code to use the generic javax.jms.Connection, javax.jms.Session, and javax.jms.MessageProducer?  If that doesn't help then please provide a test-case I can use to reproduce the issue and investigate further.

[henry.short]

Thanks for the suggestion. I will give that a try today.

[jbertram]

Any luck with my suggestion?

[nawazahamed]

Hi Justin,

     I am facing the same issue and I have already tried modifying our code to use generic javax.jms.Connection, javax.jms.Session, and javax.jms.MessageProducer but no luck. Iam getting the same warning messages . I have enabled debug on hornetq and attaching the log files.

2012.09.05 13:03:51,130 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (TrapHandler) IJ000612: Destroying connection that could not be successfully matched: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@2a5224[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@1953d98 connection handles=0 lastUse=1346830431007 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@fed240 pool internal context=SemaphoreArrayListManagedConnectionPool@52ba79[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@76e6b4[xaResource=org.hornetq.ra.HornetQRAXAResource@19d8c2a pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=null]

2012.09.05 13:03:51,130 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (TrapHandler) IJ000612: Destroying connection that could not be successfully matched: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@2a5224[state=NORMAL managed connection=org.hornetq.ra.HornetQRAManagedConnection@1953d98 connection handles=0 lastUse=1346830431007 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@fed240 pool internal context=SemaphoreArrayListManagedConnectionPool@52ba79[pool=HornetQConnectionDefinition] xaResource=XAResourceWrapperImpl@76e6b4[xaResource=org.hornetq.ra.HornetQRAXAResource@19d8c2a pad=false overrideRmValue=false productName=HornetQ productVersion=2.0 jndiName=java:/JmsXA] txSync=null]

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Calling close on session ClientSessionImpl [name=059025fe-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@96d618

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Calling close on session ClientSessionImpl [name=059025fe-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@96d618

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) calling cleanup on ClientSessionImpl [name=059025fe-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@96d618

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) calling cleanup on ClientSessionImpl [name=059025fe-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@96d618

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Calling close on session ClientSessionImpl [name=059025fd-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@7472f4

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Calling close on session ClientSessionImpl [name=059025fd-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@7472f4

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) calling cleanup on ClientSessionImpl [name=059025fd-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@7472f4

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) calling cleanup on ClientSessionImpl [name=059025fd-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@7472f4

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Calling close on session ClientSessionImpl [name=059025fc-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@4e7bdf

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Calling close on session ClientSessionImpl [name=059025fc-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@4e7bdf

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) calling cleanup on ClientSessionImpl [name=059025fc-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@4e7bdf

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) calling cleanup on ClientSessionImpl [name=059025fc-f72c-11e1-ad69-1d22de11aebb, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@4e7bdf

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Session was already closed, giving up now, this=ClientSessionImpl [name=059025fc-f72c-11e1-ad69-1d22de11aebb, username=null, closed=true, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@4e7bdf

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionImpl] (TrapHandler) Session was already closed, giving up now, this=ClientSessionImpl [name=059025fc-f72c-11e1-ad69-1d22de11aebb, username=null, closed=true, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], connectorConfig=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0, backupConfig=null], metaData=(jms-session=,)]@4e7bdf

2012.09.05 13:03:51,130 DEBUG [org.hornetq.ra.HornetQResourceAdapter] (TrapHandler) Creating Connection Factory on the resource adapter for transport=[Lorg.hornetq.api.core.TransportConfiguration;@363d9a with ha=false

2012.09.05 13:03:51,130 DEBUG [org.hornetq.ra.HornetQResourceAdapter] (TrapHandler) Creating Connection Factory on the resource adapter for transport=[Lorg.hornetq.api.core.TransportConfiguration;@363d9a with ha=false

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Trying reconnection attempt 0/1

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Trying reconnection attempt 0/1

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Trying to connect with connector = org.hornetq.core.remoting.impl.invm.InVMConnectorFactory@1ba3a45, parameters = {server-id=0} connector = org.hornetq.core.remoting.impl.invm.InVMConnector@147b815

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Trying to connect with connector = org.hornetq.core.remoting.impl.invm.InVMConnectorFactory@1ba3a45, parameters = {server-id=0} connector = org.hornetq.core.remoting.impl.invm.InVMConnector@147b815

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Trying to connect at the main server using connector :org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Trying to connect at the main server using connector :org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Reconnection successfull

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (TrapHandler) Reconnection successfull

2012.09.05 13:03:51,130 DEBUG [org.hornetq.core.client.impl.ClientSessionFactoryImpl] (Thread-7 (HornetQ-client-global-threads-21696366)) Node 0dee393e-f5e4-11e1-8b8a-23a17b961024 going up, connector = Pair[a=null, b=null], isLast=true csf created at

serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null]: java.lang.Exception

          at org.hornetq.core.client.impl.ClientSessionFactoryImpl.<init>(ClientSessionFactoryImpl.java:181) [hornetq-core-2.2.19.Mera-patch.jar:2.2.19.SNAPSHOT (HQ_2_2_19_SNAPSHOT, 122)]

          at org.hornetq.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:737) [hornetq-core-2.2.19.Mera-patch.jar:2.2.19.SNAPSHOT (HQ_2_2_19_SNAPSHOT, 122)]

          at org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:601) [hornetq-jms-2.2.19.Mera-patch.jar:2.2.19.SNAPSHOT (HQ_2_2_19_SNAPSHOT, 122)]

          at org.hornetq.jms.client.HornetQConnectionFactory.createXAConnection(HornetQConnectionFactory.java:155) [hornetq-jms-2.2.19.Mera-patch.jar:2.2.19.SNAPSHOT (HQ_2_2_19_SNAPSHOT, 122)]

          at org.hornetq.jms.client.HornetQConnectionFactory.createXAConnection(HornetQConnectionFactory.java:150) [hornetq-jms-2.2.19.Mera-patch.jar:2.2.19.SNAPSHOT (HQ_2_2_19_SNAPSHOT, 122)]

          at org.hornetq.ra.HornetQRAManagedConnection.setup(HornetQRAManagedConnection.java:824)

          at org.hornetq.ra.HornetQRAManagedConnection.<init>(HornetQRAManagedConnection.java:148)

          at org.hornetq.ra.HornetQRAManagedConnectionFactory.createManagedConnection(HornetQRAManagedConnectionFactory.java:172)

          at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.createConnectionEventListener(SemaphoreArrayListManagedConnectionPool.java:761)

          at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.getConnection(SemaphoreArrayListManagedConnectionPool.java:343)

          at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getSimpleConnection(AbstractPool.java:397)

          at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:365)

          at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:329)

          at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:368)

          at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:464)

          at org.hornetq.ra.HornetQRASessionFactoryImpl.allocateConnection(HornetQRASessionFactoryImpl.java:837)

          at org.hornetq.ra.HornetQRASessionFactoryImpl.createSession(HornetQRASessionFactoryImpl.java:470)

          at com.extremenetworks.epicenter.server.common.jms.JmsTopicPublisher.initTopicSession(JmsTopicPublisher.java:85)

          at com.extremenetworks.epicenter.server.common.jms.JmsTopicPublisher.setupTopicConnection(JmsTopicPublisher.java:78)

          at com.extremenetworks.epicenter.server.common.jms.JmsTopicPublisher.initialize(JmsTopicPublisher.java:67)

          at com.extremenetworks.epicenter.server.common.jms.JmsTopicPublisher.<init>(JmsTopicPublisher.java:61)

          at com.extremenetworks.epicenter.server.common.jms.JmsTopicPublisher.<init>(JmsTopicPublisher.java:52)

          at com.extremenetworks.everest.server.legacyinteraction.TrapForwarderToJMSThread.setupQueueConnection(TrapForwarderToJMSThread.java:121)

          at com.extremenetworks.everest.server.legacyinteraction.TrapForwarderToJMSThread.<init>(TrapForwarderToJMSThread.java:114)

          at com.extremenetworks.everest.server.dataServer.TrapManager.run(TrapManager.java:494)

          at com.extremenetworks.everest.server.transaction.TransactionThread.run(TransactionThread.java:122)

[hypheng]

Could anyone answer this problem?

I have the same issue.

[nawazahamed]

Hi,

Upgrade to https://github.com/hornetq/hornetq/archive/HornetQ_2_2_22_AS7_Final.zip, this has fixes for few major issues in messaging. I figured out that the

messages"Destroying connection that could not be successfully matched"  was a side effect for another bug in hornetq.