Weird transaction issue when publishing in-vm
kellizer Jun 9, 2014 10:12 AMHi,
I'm using arquillian to test an MDB but when it invokes via the unit test i get transaction errors (stacktrace below)- the MDB works as expected when I use another VM to invoke the MDB and only fails in the unit tests.
I'm using CMT, & the MDB is being called but when it hits hibernate it blows up.
Anyone have an idea on why this may happen?
Thanks,
Ian.
---
[0m [32m15:01:38,565 DEBUG [org.hornetq.core.server] (Thread-37 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=afc7bd6f-c0a0-11e3-83ed-39d38ca1f2d4-385907614-548654558)) Message ServerMessage[messageID=17179894805,userID=null,priority=0, bodySize=512,expiration=0, durable=true, address=hornetq.notifications,properties=TypedProperties[{_HQ_User=7dd1f104-e138-456f-9933-d6d268e98c09, _HQ_NotifTimestamp=1402322498565, _HQ_Distance=0, _HQ_SessionName=8ceb5d46-efde-11e3-ac00-b152002fa896, _HQ_NotifType=CONSUMER_CLOSED, _HQ_Address=jms.queue.brand-order-received, _HQ_ClusterName=jms.queue.brand-order-receivedafc7bd6f-c0a0-11e3-83ed-39d38ca1f2d4, _HQ_RoutingName=jms.queue.brand-order-received, _HQ_ConsumerCount=0, _HQ_RemoteAddress=invm:0, _HQ_FilterString=null}]]@1854380377 is not going anywhere as it didn't have a binding on address:hornetq.notifications
[0m [32m15:01:38,566 DEBUG [org.hornetq.core.client] (TearDown/HornetQActivation) Calling close on session ClientSessionImpl [name=8ceb5d46-efde-11e3-ac00-b152002fa896, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=25d20b68-efdd-11e3-ac00-b152002fa896, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=25d20b68-efdd-11e3-ac00-b152002fa896, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(resource-adapter=inbound,jms-session=,)]@5bac631f
[0m [32m15:01:38,566 DEBUG [org.hornetq.ra] (ServerService Thread Pool -- 174) Tearing down complete org.hornetq.ra.inflow.HornetQActivation(spec=org.hornetq.ra.inflow.HornetQActivationSpec mepf=org.jboss.as.ejb3.inflow.JBossMessageEndpointFactory active=false destination=java:/jboss/exported/stock-level-update transacted=false)
[0m [32m15:01:38,566 DEBUG [org.hornetq.core.client] (TearDown/HornetQActivation) calling cleanup on ClientSessionImpl [name=8ceb3631-efde-11e3-ac00-b152002fa896, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=25d20b68-efdd-11e3-ac00-b152002fa896, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=8ceae80c-efde-11e3-ac00-b152002fa896, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(resource-adapter=inbound,jms-session=,)]@28bddd65
[0m [32m15:01:38,566 DEBUG [org.hornetq.core.client] (TearDown/HornetQActivation) calling cleanup on ClientSessionImpl [name=8ceb5d46-efde-11e3-ac00-b152002fa896, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=25d20b68-efdd-11e3-ac00-b152002fa896, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=25d20b68-efdd-11e3-ac00-b152002fa896, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(resource-adapter=inbound,jms-session=,)]@5bac631f
[0m [32m15:01:38,566 DEBUG [org.hornetq.ra] (ServerService Thread Pool -- 179) Tearing down complete org.hornetq.ra.inflow.HornetQActivation(spec=org.hornetq.ra.inflow.HornetQActivationSpec mepf=org.jboss.as.ejb3.inflow.JBossMessageEndpointFactory active=false destination=java:/jboss/exported/brand-notification transacted=false)
[0m [32m15:01:38,567 DEBUG [org.hornetq.ra] (ServerService Thread Pool -- 184) Tearing down complete org.hornetq.ra.inflow.HornetQActivation(spec=org.hornetq.ra.inflow.HornetQActivationSpec mepf=org.jboss.as.ejb3.inflow.JBossMessageEndpointFactory active=false destination=java:/jboss/exported/brand-order-received transacted=false)
[0m [33m15:01:38,565 WARN [com.arjuna.ats.arjuna] (Thread-25 (HornetQ-client-global-threads-1693547151)) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff0a000dde:698cd374:5395bbd7:1d6, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@7b2f8bdd >: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Could not open connection
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1316) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.ejb.AbstractEntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(AbstractEntityManagerImpl.java:1510) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion(SynchronizationCallbackCoordinatorImpl.java:118) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:53) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:273)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:93)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:167)
&&&&&&
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Could not open connection
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1316) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.ejb.AbstractEntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(AbstractEntityManagerImpl.java:1510) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion(SynchronizationCallbackCoordinatorImpl.java:118) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:53) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:273)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:93)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
... 180 more
Caused by: org.hibernate.exception.GenericJDBCException: Could not open connection
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:221) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:157) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:56) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.doPrepare(StatementPreparerImpl.java:98) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:182) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareStatement(StatementPreparerImpl.java:91) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.buildBatchStatement(AbstractBatchImpl.java:138) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.getBatchStatement(AbstractBatchImpl.java:127) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3059) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3523) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:88) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:393) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:385) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:301) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:339) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:52) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1240) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:404) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion(SynchronizationCallbackCoordinatorImpl.java:113) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
... 186 more
Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@24e258ac[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@460de36f connection handles=0 lastUse=1402322498543 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@e4c3a7d pool internal context=SemaphoreArrayListManagedConnectionPool@315c0c9d[pool=jbpmDS] xaResource=LocalXAResourceImpl@2b2f67a3[connectionListener=24e258ac connectionManager=39ceb057 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a000dde:698cd374:5395bbd7:1d4, node_name=1, branch_uid=0:ffff0a000dde:698cd374:5395bbd7:1d9, subordinatenodename=null, eis_name=java:jboss/jbpmDS > productName=PostgreSQL productVersion=9.3.3 jndiName=java:jboss/jbpmDS] txSync=null]
at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:147)
at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:70) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:214) [hibernate-core-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
... 204 more
Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@24e258ac[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@460de36f connection handles=0 lastUse=1402322498543 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@e4c3a7d pool internal context=SemaphoreArrayListManagedConnectionPool@315c0c9d[pool=jbpmDS] xaResource=LocalXAResourceImpl@2b2f67a3[connectionListener=24e258ac connectionManager=39ceb057 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a000dde:698cd374:5395bbd7:1d4, node_name=1, branch_uid=0:ffff0a000dde:698cd374:5395bbd7:1d9, subordinatenodename=null, eis_name=java:jboss/jbpmDS > productName=PostgreSQL productVersion=9.3.3 jndiName=java:jboss/jbpmDS] txSync=null]
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:604)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)
at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139)
... 207 more
Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object
at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:474)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)
... 209 more
Caused by: java.lang.RuntimeException: Unable to get synchronization
at org.jboss.jca.core.connectionmanager.transaction.TransactionSynchronizer.lock(TransactionSynchronizer.java:284)
at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:227)
at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:467)
... 210 more
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1219) [rt.jar:1.7.0_45]
at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:340) [rt.jar:1.7.0_45]
at org.jboss.jca.core.connectionmanager.transaction.TransactionSynchronizer.lock(TransactionSynchronizer.java:280)
... 212 more