3 Replies Latest reply on Jun 10, 2014 10:33 AM by jbertram

    Weird transaction issue when publishing in-vm

    kellizer

      Hi,

       

      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

        • 1. Re: Weird transaction issue when publishing in-vm
          jbertram

          I don't see any direct evidence that this is related to HornetQ.  It appears to me that it is a problem between Hibernate and the transaction manager.  The InterruptedException looks strange to me.  You might investigate where that is coming from (e.g. using Byteman).

          • 2. Re: Weird transaction issue when publishing in-vm
            kellizer

            Thanks Justin - i agree that it doesn't seem to be related directly to hornet-q but it only ever happens when I use the MDB within arquillian (in-VM generating a message and publishing) - if i don't use the MDB and execute the code that the MDB executes directly  (i.e. call the code that the MDB does) then it works as expect so feels to me that the CMT isn't the same when going via arquillian and/or in-vm so that in turns makes hibernate fail

             

            in summary;

            • Direct call to MDB - pass
            • arquillian publishes message to MDB - fail
            • arquillian calls code directly - pass

             

            Any further thoughts and i will check out bytemann?

             

            Thanks,

             

            Ian.

            • 3. Re: Weird transaction issue when publishing in-vm
              jbertram

              Thanks Justin - i agree that it doesn't seem to be related directly to hornet-q but it only ever happens when I use the MDB within arquillian (in-VM generating a message and publishing) - if i don't use the MDB and execute the code that the MDB executes directly  (i.e. call the code that the MDB does) then it works as expect so feels to me that the CMT isn't the same when going via arquillian and/or in-vm so that in turns makes hibernate fail

              Unfortunately I can't help you with the behavior of Arquillian and/or the CMT semantics of the EJB container as I don't have expertise in those areas.  If you could come up with a simple reproducible test-case that specifically implicates HornetQ then I could help more.