8 Replies Latest reply on Jun 16, 2014 2:14 PM by Scott Marlow

    createStoredProcedureQuery - Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7

    Maycon Oliveira Newbie

      Hi there!

       

      I´m using Wildfly 8.1 Final and i´m having the following Exception when I call a StoredProcedure on a second EJB after do anything with EntityManager on the first EJB:

       

       

      IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: IJ000152: Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@68c39106

        at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.unregisterConnection(CachedConnectionManagerImpl.java:385)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.connectionClosed(TxConnectionListener.java:591)

        at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:581)

        at org.jboss.jca.adapters.jdbc.WrappedConnection.close(WrappedConnection.java:265)

        at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.closeConnection(DatasourceConnectionProviderImpl.java:144) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

        at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.releaseConnection(AbstractSessionImpl.java:391) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:255) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.close(LogicalConnectionImpl.java:182) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

        at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close(JdbcCoordinatorImpl.java:205) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

       

       

      Source code:

       

      EJB1Session

       

      @PersistenceContext

      protected EntityManager em;

       

      @EJB

      protected EJB2Session session;

       

      public void aa(){

          // do ANYTHING with EntityManager

          Query q = this.em.createQuery("select e from Anything e");

          session.callStoredProcedureX();

      }

      --------------------------------

      EJB2Session


      @PersistenceContext

      protected EntityManager em;

       

      public void callStoredProcedureX() {

        StoredProcedureQuery storedProcedure = this.em.createStoredProcedureQuery("PROCEDURE_XXX");

        storedProcedure.execute();

      }

       

       

      Anybody knows if this is a bug? 

       

      If i copy the method from the second EJB e put inside the first , everything runs ok. Or, if I mark the second one with REQUIRES_NEW also runs ok.

        • 2. Re: createStoredProcedureQuery - Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7
          Maycon Oliveira Newbie

          I dont know if this can help, but here it comes (procedure call and the exception are in bold):

           

          2014-06-04 21:53:39,266 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] prepareStatement(/* load com.test.ejb.entity.extend.PerfisManut */ select perfismanu0_.CODIGO as CODIGO1_36_0_, perfismanu0_.DESCRICAO as DESCRICAO2_36_0_ from PERFIS perfismanu0_ where perfismanu0_.CODIGO=?)

          2014-06-04 21:53:39,266 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [PreparedStatement] setInt(1, 100)

          2014-06-04 21:53:39,266 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [PreparedStatement] executeQuery()

          2014-06-04 21:53:39,269 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [ResultSet] next()

          2014-06-04 21:53:39,269 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [ResultSet] getString(DESCRICAO2_36_0_)

          2014-06-04 21:53:39,269 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [ResultSet] wasNull()

          2014-06-04 21:53:39,269 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [ResultSet] next()

          2014-06-04 21:53:39,269 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [ResultSet] close()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getWarnings()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] clearWarnings()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getMaxRows()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getQueryTimeout()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] close()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] isClosed()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] getWarnings()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] clearWarnings()

          2014-06-04 21:53:39,270 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] close()

          2014-06-04 21:53:39,272 TRACE [org.jboss.as.jpa.messages] (default task-103) merge entityClass 'com.test.ejb.entity.extend.PerfisManut' took 10ms

          2014-06-04 21:53:39,272 DEBUG [org.jboss.as.jpa] (default task-103) default task-103:[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffff7f000101:-41818f42:538fbf52:243 status: ActionStatus.RUNNING >

          2014-06-04 21:53:39,272 TRACE [org.jboss.as.jpa.messages] (default task-103) flush took 0ms

          2014-06-04 21:53:39,272 DEBUG [org.jboss.as.jpa] (default task-103) default task-103:[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffff7f000101:-41818f42:538fbf52:243 status: ActionStatus.RUNNING >

          2014-06-04 21:53:39,273 TRACE [org.jboss.as.jpa.messages] (default task-103) flush took 1ms

          2014-06-04 21:53:39,273 DEBUG [org.jboss.as.jpa] (default task-103) created new TransactionScopedEntityManager for unit name=mysys.ear/mysysejb.jar#persistence

          2014-06-04 21:53:39,274 DEBUG [org.jboss.as.jpa] (default task-103) default task-103:[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffff7f000101:-41818f42:538fbf52:243 status: ActionStatus.RUNNING >

          2014-06-04 21:53:39,280 TRACE [org.jboss.as.jpa.messages] (default task-103) createStoredProcedureQuery PRC_REFAZ_MV took 6ms

          2014-06-04 21:53:39,282 INFO  [stdout] (default task-103) Hibernate: {call PRC_REFAZ_MV()}

          2014-06-04 21:53:39,282 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [DataSource] getConnection()

          2014-06-04 21:53:39,282 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] prepareCall({call PRC_REFAZ_MV()})

          2014-06-04 21:53:39,303 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [PreparedStatement] execute()

          2014-06-04 21:53:39,305 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getUpdateCount()

          2014-06-04 21:53:39,351 DEBUG [org.jboss.as.jpa] (default task-103) default task-103:[transaction scoped EntityManager]: closing entity managersession

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getWarnings()

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] clearWarnings()

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getMaxRows()

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] getQueryTimeout()

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Statement] close()

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] isClosed()

          2014-06-04 21:53:39,352 DEBUG [jboss.jdbc.spy] (default task-103) java:/jdbc/MyDS [Connection] close()

          2014-06-04 21:53:39,353 INFO  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (default task-103) IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: IJ000152: Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@7f63fffc

           

          Any Ideas?

           

          Really thanks for the interest!

          • 3. Re: createStoredProcedureQuery - Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7
            Scott Marlow Master

            How many different persistence unit definitions do you have in your persistence.xml?  In the trace output, I see that the stored procedure is using the "persistence" persistence unit but there is also another persistence unit previously accessed on the same JTA transaction (0:ffff7f000101:-41818f42:538fbf52:243).

             

            You may as well also enable TRACE logging for com.arjuna, which will show when JTA transactions start and end (it will be noisy but that might help).

             

            Can you also show us more of the "previous" (to the error) log output.

            • 4. Re: createStoredProcedureQuery - Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7
              Maycon Oliveira Newbie

              Sure. More information:

               

              persistence.xml ( Just one persistence unit)

               

              <?xml version="1.0" encoding="UTF-8"?>
              <persistence version="2.0"
                xmlns="http://java.sun.com/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
                xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd">
                <persistence-unit name="persistence">
                <jta-data-source>java:/jdbc/MyDS</jta-data-source>
                <properties>
                <property name="hibernate.dialect" value="org.hibernate.dialect.Oracle10gDialect" />
                <property name="hibernate.show_sql" value="true" />
                <property name="hibernate.format_sql" value="false" />
                <property name="hibernate.use_sql_comments" value="true" />
                <property name="hibernate.id.new_generator_mappings" value="false" />
                </properties>
                </persistence-unit>
              </persistence>
              

               

               

              LOG (Cutted the line start )

               

               

              [com.arjuna.ats.jta] (default task-5) TransactionImple.enlistResource ( LocalXAResourceImpl@363fe85[connectionListener=2fc50780 connectionManager=19dacf80 warned=false currentXid=null productName=Oracle productVersion=Oracle Database 11g Express Edition Release 11.2.0.2.0 - Production jndiName=java:/jdbc/MyDS] )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 0:0:0:0:1 )

              [com.arjuna.ats.arjuna] (default task-5) AbstractRecord::AbstractRecord (0:0:0:0:1)

              [com.arjuna.ats.arjuna] (default task-5) LastResourceRecord()

              [com.arjuna.ats.arjuna] (default task-5) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:0:1

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] prepareStatement(/* select e from Rotinas as e where e.componente = :desUrl  */ select rotinas0_.ROTINA as ROTINA1_40_, rotinas0_.COD_OBJETO as COD_OBJETO2_40_, rotinas0_.COMPONENTE as COMPONENTE3_40_, rotinas0_.DESCRICAO as DESCRICAO4_40_, rotinas0_.HELP as HELP5_40_, rotinas0_.ICONE as ICONE6_40_ from ROTINAS rotinas0_ where rotinas0_.COMPONENTE=?)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [PreparedStatement] setString(1, PerfisForm.xhtml)

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [PreparedStatement] executeQuery()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] next()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getInt(ROTINA1_40_)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] wasNull()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getString(COD_OBJETO2_40_)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getString(COMPONENTE3_40_)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] wasNull()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getString(DESCRICAO4_40_)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] wasNull()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getInt(HELP5_40_)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] wasNull()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getString(ICONE6_40_)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] next()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] close()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] clearWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getMaxRows()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getQueryTimeout()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] close()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] isClosed()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] getWarnings()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] clearWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] close()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.suspend

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:17d removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:17d removing TSThread:5 result = true

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.begin

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 2, 0 )

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::BasicAction()

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::Begin() for action-id 0:ffff7f000101:-706476dc:5390f480:185

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::actionInitialise() for action-id 0:ffff7f000101:-706476dc:5390f480:185

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::ActionHierarchy(1)

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::add(0:ffff7f000101:-706476dc:5390f480:185, 1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:185 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:185 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::insert ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:185 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.arjuna] (default task-5) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:185 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:185

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:185) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:185 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:185 removing TSThread:5 result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:185 status: ActionStatus.COMMITTED )

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.resume

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:17d adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:17d adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.beforeCompletion

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.beforeCompletion

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.beforeCompletion

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.delistResource ( LocalXAResourceImpl@363fe85[connectionListener=2fc50780 connectionManager=19dacf80 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-706476dc:5390f480:17d, node_name=1, branch_uid=0:ffff7f000101:-706476dc:5390f480:184, subordinatenodename=null, eis_name=java:/jdbc/MyDS > productName=Oracle productVersion=Oracle Database 11g Express Edition Release 11.2.0.2.0 - Production jndiName=java:/jdbc/MyDS], 67108864 )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:17d

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::onePhaseCommit() for action-id 0:ffff7f000101:-706476dc:5390f480:17d

              [com.arjuna.ats.arjuna] (default task-5) LastResourceRecord::topLevelPrepare() for 0:0:0:0:1

              [com.arjuna.ats.arjuna] (default task-5) LastResourceRecord::topLevelCommit() for 0:0:0:0:1

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:17d) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.afterCompletion

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.afterCompletion

              [org.jboss.as.jpa] (default task-5) default task-5:[transaction scoped EntityManager]: closing entity managersession

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_COMMITTED

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.afterCompletion

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:17d removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:17d removing TSThread:5 result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:17d status: ActionStatus.COMMITTED )

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.begin

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 2, 0 )

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::BasicAction()

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::Begin() for action-id 0:ffff7f000101:-706476dc:5390f480:186

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::actionInitialise() for action-id 0:ffff7f000101:-706476dc:5390f480:186

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::ActionHierarchy(1)

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::add(0:ffff7f000101:-706476dc:5390f480:186, 1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::insert ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:186 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.arjuna] (default task-5) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:186 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.suspend

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5 result = true

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.begin

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 2, 0 )

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::BasicAction()

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::Begin() for action-id 0:ffff7f000101:-706476dc:5390f480:187

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::actionInitialise() for action-id 0:ffff7f000101:-706476dc:5390f480:187

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::ActionHierarchy(1)

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::add(0:ffff7f000101:-706476dc:5390f480:187, 1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:187 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:187 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::insert ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:187 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.arjuna] (default task-5) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:187 status: ActionStatus.RUNNING, 300 )

              [org.jboss.as.jpa] (default task-5) created new TransactionScopedEntityManager for unit name=rhsys.ear/rhsysejb.jar#persistence

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:187

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:187) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:187 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:187 removing TSThread:5 result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:187 status: ActionStatus.COMMITTED )

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.resume

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getRollbackOnly

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.registerInterposedSynchronization

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [org.jboss.as.jpa] (default task-5) default task-5:[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffff7f000101:-706476dc:5390f480:186 status: ActionStatus.RUNNING >

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.registerInterposedSynchronization

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.putResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [org.jboss.as.jpa.messages] (default task-5) createNativeQuery took 3ms

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [stdout] (default task-5) Hibernate: /* dynamic native SQL query */ select 1 from dual

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [DataSource] getConnection()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.putResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.putResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.registerInterposedSynchronization

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.enlistResource ( LocalXAResourceImpl@363fe85[connectionListener=2fc50780 connectionManager=19dacf80 warned=false currentXid=null productName=Oracle productVersion=Oracle Database 11g Express Edition Release 11.2.0.2.0 - Production jndiName=java:/jdbc/MyDS] )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 0:0:0:0:1 )

              [com.arjuna.ats.arjuna] (default task-5) AbstractRecord::AbstractRecord (0:0:0:0:1)

              [com.arjuna.ats.arjuna] (default task-5) LastResourceRecord()

              [com.arjuna.ats.arjuna] (default task-5) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:0:1

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] prepareStatement(/* dynamic native SQL query */ select 1 from dual)

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [PreparedStatement] executeQuery()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getMetaData()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] next()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] getBigDecimal(1)

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] wasNull()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] next()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [ResultSet] close()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] clearWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getMaxRows()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getQueryTimeout()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] close()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] isClosed()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] getWarnings()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] clearWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] close()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionImple.enlistResource ( ResourceImpl{transactionKey=0:ffff7f000101:-706476dc:5390f480:186, ejbClientContext=org.jboss.ejb.client.EJBClientContext@7543698c, nodeName='fuinha-lpc', state=null} )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 1, 0 )

              [com.arjuna.ats.arjuna] (default task-5) AbstractRecord::AbstractRecord (0:ffff7f000101:-706476dc:5390f480:18d, 1)

              [com.arjuna.ats.jta] (default task-5) XAResourceRecord.XAResourceRecord ( < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-706476dc:5390f480:186, node_name=1, branch_uid=0:ffff7f000101:-706476dc:5390f480:18c, subordinatenodename=null, eis_name=unknown eis name >, ResourceImpl{transactionKey=0:ffff7f000101:-706476dc:5390f480:186, ejbClientContext=org.jboss.ejb.client.EJBClientContext@7543698c, nodeName='fuinha-lpc', state=null} ), record id=0:ffff7f000101:-706476dc:5390f480:18d

              [com.arjuna.ats.arjuna] (default task-5) RecordList::insert(RecordList: 0:0:0:0:1) : inserting /StateManager/AbstractRecord/XAResourceRecord for 0:ffff7f000101:-706476dc:5390f480:18d before /StateManager/AbstractRecord/LastResourceRecord

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.suspend

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5 result = true

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.begin

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 2, 0 )

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::BasicAction()

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::Begin() for action-id 0:ffff7f000101:-706476dc:5390f480:18f

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::actionInitialise() for action-id 0:ffff7f000101:-706476dc:5390f480:18f

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::ActionHierarchy(1)

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::add(0:ffff7f000101:-706476dc:5390f480:18f, 1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:18f adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:18f adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::insert ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:18f status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.arjuna] (default task-5) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:18f status: ActionStatus.RUNNING, 300 )

              [org.jboss.as.jpa] (default task-5) created new TransactionScopedEntityManager for unit name=rhsys.ear/rhsysejb.jar#persistence

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:18f

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:18f) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:18f removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:18f removing TSThread:5 result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:18f status: ActionStatus.COMMITTED )

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.resume

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [org.jboss.as.jpa] (default task-5) default task-5:[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffff7f000101:-706476dc:5390f480:186 status: ActionStatus.RUNNING >

              [org.jboss.as.jpa.messages] (default task-5) createStoredProcedureQuery PRC_REFAZ_MV took 6ms

              [stdout] (default task-5) Hibernate: {call PRC_REFAZ_MV()}

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [DataSource] getConnection()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getTransactionKey

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.equals

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] prepareCall({call PRC_REFAZ_MV()})

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [PreparedStatement] execute()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getUpdateCount()

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.suspend

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5 result = true

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.begin

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 2, 0 )

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::BasicAction()

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::Begin() for action-id 0:ffff7f000101:-706476dc:5390f480:190

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::actionInitialise() for action-id 0:ffff7f000101:-706476dc:5390f480:190

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::ActionHierarchy(1)

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::add(0:ffff7f000101:-706476dc:5390f480:190, 1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:190 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:190 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::insert ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:190 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.arjuna] (default task-5) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:190 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:190

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:190) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:190 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:190 removing TSThread:5 result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:190 status: ActionStatus.COMMITTED )

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.resume

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.suspend

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 removing TSThread:5 result = true

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.begin

              [com.arjuna.ats.arjuna] (default task-5) StateManager::StateManager( 2, 0 )

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::BasicAction()

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::Begin() for action-id 0:ffff7f000101:-706476dc:5390f480:191

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::actionInitialise() for action-id 0:ffff7f000101:-706476dc:5390f480:191

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::ActionHierarchy(1)

              [com.arjuna.ats.arjuna] (default task-5) ActionHierarchy::add(0:ffff7f000101:-706476dc:5390f480:191, 1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:191 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:191 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::insert ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:191 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.arjuna] (default task-5) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:191 status: ActionStatus.RUNNING, 300 )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:191

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:191) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:191 removing TSThread:5

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::removeChildThread () action 0:ffff7f000101:-706476dc:5390f480:191 removing TSThread:5 result = true

              [com.arjuna.ats.arjuna] (default task-5) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-706476dc:5390f480:191 status: ActionStatus.COMMITTED )

              [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.resume

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main]

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000101:-706476dc:5390f480:186 adding Thread[default task-5,5,main] result = true

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) BaseTransaction.commit

              [com.arjuna.ats.jta] (default task-5) TransactionImple.commitAndDisassociate

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.beforeCompletion

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.beforeCompletion

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.beforeCompletion

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.jta] (default task-5) TransactionImple.delistResource ( LocalXAResourceImpl@363fe85[connectionListener=2fc50780 connectionManager=19dacf80 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-706476dc:5390f480:186, node_name=1, branch_uid=0:ffff7f000101:-706476dc:5390f480:18b, subordinatenodename=null, eis_name=java:/jdbc/MyDS > productName=Oracle productVersion=Oracle Database 11g Express Edition Release 11.2.0.2.0 - Production jndiName=java:/jdbc/MyDS], 67108864 )

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() for action-id 0:ffff7f000101:-706476dc:5390f480:186

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::prepare () for action-id 0:ffff7f000101:-706476dc:5390f480:186

              [com.arjuna.ats.jta] (default task-5) XAResourceRecord.topLevelPrepare for XAResourceRecord < resource:ResourceImpl{transactionKey=0:ffff7f000101:-706476dc:5390f480:186, ejbClientContext=org.jboss.ejb.client.EJBClientContext@7543698c, nodeName='fuinha-lpc', state=State{transactionID=org.jboss.ejb.client.XidTransactionID@a564067a, suspended=false, participantCnt=0}}, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-706476dc:5390f480:186, node_name=1, branch_uid=0:ffff7f000101:-706476dc:5390f480:18c, subordinatenodename=null, eis_name=unknown eis name >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@46b7b4f >, record id=0:ffff7f000101:-706476dc:5390f480:18d

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::doPrepare() result for action-id (0:ffff7f000101:-706476dc:5390f480:186) on record id: (0:ffff7f000101:-706476dc:5390f480:18d) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffff7f000101:-706476dc:5390f480:18d

              [com.arjuna.ats.arjuna] (default task-5) LastResourceRecord::topLevelPrepare() for 0:0:0:0:1

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::doPrepare() result for action-id (0:ffff7f000101:-706476dc:5390f480:186) on record id: (0:0:0:0:1) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) RecordList::insert(RecordList: 0:ffff7f000101:-706476dc:5390f480:18d) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:0:1

              [com.arjuna.ats.arjuna] (default task-5) OutputObjectState::OutputObjectState(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::save_state ()

              [com.arjuna.ats.arjuna] (default task-5) StateManager.packHeader for object-id 0:ffff7f000101:-706476dc:5390f480:186 birth-date 1402008756985

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true

              [com.arjuna.ats.arjuna] (default task-5) Packing a 171 record

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::save_state - next record to pack is a 2147483647 record /StateManager/AbstractRecord/LastResourceRecord should save it? = false

              [com.arjuna.ats.arjuna] (default task-5) Packing a NONE_RECORD

              [com.arjuna.ats.arjuna] (default task-5) Packing action status of ActionStatus.COMMITTING

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.write_committed(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.write_state(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.openAndLock(/servers/wildfly-8.1.0.Final/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff7f000101_-706476dc_5390f480_186, FileLock.F_WRLCK, true)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.closeAndUnlock(/servers/wildfly-8.1.0.Final/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff7f000101_-706476dc_5390f480_186, null, java.io.FileOutputStream@69a5dc0b)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::phase2Commit() for action-id 0:ffff7f000101:-706476dc:5390f480:186

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::doCommit (XAResourceRecord < resource:ResourceImpl{transactionKey=0:ffff7f000101:-706476dc:5390f480:186, ejbClientContext=org.jboss.ejb.client.EJBClientContext@7543698c, nodeName='fuinha-lpc', state=null}, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-706476dc:5390f480:186, node_name=1, branch_uid=0:ffff7f000101:-706476dc:5390f480:18c, subordinatenodename=null, eis_name=unknown eis name >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@46b7b4f >)

              [com.arjuna.ats.jta] (default task-5) XAResourceRecord.topLevelCommit for XAResourceRecord < resource:ResourceImpl{transactionKey=0:ffff7f000101:-706476dc:5390f480:186, ejbClientContext=org.jboss.ejb.client.EJBClientContext@7543698c, nodeName='fuinha-lpc', state=null}, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-706476dc:5390f480:186, node_name=1, branch_uid=0:ffff7f000101:-706476dc:5390f480:18c, subordinatenodename=null, eis_name=unknown eis name >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@46b7b4f >, record id=0:ffff7f000101:-706476dc:5390f480:18d

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::doCommit() result for action-id (0:ffff7f000101:-706476dc:5390f480:186) on record id: (0:ffff7f000101:-706476dc:5390f480:18d) is (TwoPhaseOutcome.FINISH_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::doCommit (LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@363fe85[connectionListener=2fc50780 connectionManager=19dacf80 warned=false currentXid=null productName=Oracle productVersion=Oracle Database 11g Express Edition Release 11.2.0.2.0 - Production jndiName=java:/jdbc/MyDS])))

              [com.arjuna.ats.arjuna] (default task-5) LastResourceRecord::topLevelCommit() for 0:0:0:0:1

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::doCommit() result for action-id (0:ffff7f000101:-706476dc:5390f480:186) on record id: (0:0:0:0:1) is (TwoPhaseOutcome.FINISH_OK) node id: (1)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::updateState() for action-id 0:ffff7f000101:-706476dc:5390f480:186

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.remove_committed(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.remove_state(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_SHADOW)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 10)

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.currentState(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning StateStatus.OS_COMMITTED

              [com.arjuna.ats.arjuna] (default task-5) ShadowingStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, StateType.OS_ORIGINAL)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.genPathName(0:ffff7f000101:-706476dc:5390f480:186, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, 11)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.openAndLock(/servers/wildfly-8.1.0.Final/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff7f000101_-706476dc_5390f480_186, FileLock.F_WRLCK, false)

              [com.arjuna.ats.arjuna] (default task-5) FileSystemStore.closeAndUnlock(/servers/wildfly-8.1.0.Final/standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/0_ffff7f000101_-706476dc_5390f480_186, null, null)

              [com.arjuna.ats.arjuna] (default task-5) BasicAction::End() result for action-id (0:ffff7f000101:-706476dc:5390f480:186) is (TwoPhaseOutcome.FINISH_OK) node id: (1)

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.afterCompletion

              [com.arjuna.ats.jta] (default task-5) SynchronizationImple.afterCompletion

              [org.jboss.as.jpa] (default task-5) default task-5:[transaction scoped EntityManager]: closing entity managersession

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_COMMITTED

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] clearWarnings()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getMaxRows()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] getQueryTimeout()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Statement] close()

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] isClosed()

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_COMMITTED

              [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_COMMITTED

              [jboss.jdbc.spy] (default task-5) java:/jdbc/MyDS [Connection] close()

              [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (default task-5) IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: IJ000152: Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@6e6426be

               

               

               

              What do you think?

              • 5. Re: Re: createStoredProcedureQuery - Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7
                Scott Marlow Master

                I suspect that the IronJacamar JCA layer is closing the connection first and then Hibernate also closes it and the connection has already been returned to the pool. 

                 

                Can we also see the entire exception call stack as well for the "IJ000152: Trying to return an unknown connection".  It might be easier for us to read the log if you attach the server.log (or part of it).  Feel free to zip it for compression (see file attach link on bottom of page after clicking "use advanced editor"). 

                • 8. Re: Re: createStoredProcedureQuery - Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7
                  Scott Marlow Master

                  It is just an informational message that is wrong for your application:

                  2014-06-08 09:29:16,616 DEBUG [jboss.jdbc.spy] (default task-18) java:/jdbc/MyDS [Connection] close()

                  2014-06-08 09:29:16,616 INFO  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (default task-18) IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: IJ000152: Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@38c9d6b2

                          at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.unregisterConnection(CachedConnectionManagerImpl.java:385)

                          at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.connectionClosed(TxConnectionListener.java:591)

                          at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:581)

                          at org.jboss.jca.adapters.jdbc.WrappedConnection.close(WrappedConnection.java:265)

                          at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.closeConnection(DatasourceConnectionProviderImpl.java:144) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.releaseConnection(AbstractSessionImpl.java:391) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:255) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.close(LogicalConnectionImpl.java:182) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close(JdbcCoordinatorImpl.java:205) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl.close(TransactionCoordinatorImpl.java:297) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.internal.SessionImpl.close(SessionImpl.java:369) [hibernate-core-4.3.5.Final.jar:4.3.5.Final]

                          at org.hibernate.jpa.internal.EntityManagerImpl.close(EntityManagerImpl.java:153) [hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

                          at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:154) [wildfly-jpa-8.1.0.Final.jar:8.1.0.Final]

                          at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)

                   

                  You could change logging configuration to make it go away.  There are probably some application errors that could be found by the info level message but this isn't one of them.

                   

                  In standalone.xml (or whichever WildFly config you are using), update the urn:jboss:domain:logging section config to also contain:

                  <logger category="org.jboss.jca.core.connectionmanager.listener.TxConnectionListener">

                                  <level name="WARN"/>

                  </logger>

                   

                   

                   

                  There are some cases where the informational message could mean that there is a problem but this isn't one of those.