1 2 Previous Next 24 Replies Latest reply on Sep 3, 2015 11:29 AM by Sreenath Reddy

    Transaction issue while migrating Jboss 5.1 to WildFly 8.2

    Sreenath Reddy Novice

      Hi All,

       

      I am mygrating my application from Jboss 5.1.0 to Wild Fly 8.2. While starting the server we are fetching the data from data base and storing in application scope. This was working fine in Jboss 5.1.0 and not working on WildFly 8.2. It is showing the below warnings.

       

      15:04:38,152 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0ab6a4f7:3057cd0:55c9c01b:8 in state  RUN

      15:04:38,156 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff0ab6a4f7:3057cd0:55c9c01b:8 invoked while multiple threads active within it.

      15:04:38,157 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff0ab6a4f7:3057cd0:55c9c01b:8 aborting with 1 threads active!

      15:04:38,158 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff0ab6a4f7:3057cd0:55c9c01b:8

       

      I have double checked that my data source configuration is correct.

      As part of migration I have upgraded Seam 2.2.0 to 2.3.1 and EJB 3.0 to EJB 3.1. I am suspecting that there might be an issue with upgrading Seam and EJB.

       

      I am understanding why I am getting the above transaction, please help me if any one has solution for the above issue.

       

      Thanks,

      Sreenath

        • 1. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
          Amos Feng Apprentice

          I think it could be useful to set the TRACE level of "com.arjuna" in the configuration xml you used.

          <logger category="com.arjuna">
              <level name="TRACE">
          </logger>
          

           

          also if you can attach the configuration xml and the trace log file, it would be helpful to analyze this issue.

           

          Thanks,

          Amos

          • 2. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
            Frank Langelage Master

            How long does it take to fetch the data?

            The exception looks like a transaction timeout. The default timeout is set to 300 seconds.

            • 3. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
              Sreenath Reddy Novice

              Hi Amos,

               

              I tried to set the TRACE level for com.arjuna on WildFly 8.2, still it is showing the WARN level, i will look in this issue. The below is my components.xml file

               

              <?xml version="1.0" encoding="UTF-8"?>

              <components xmlns="http://jboss.org/schema/seam/components"

                xmlns:core="http://jboss.org/schema/seam/core"

                xmlns:drools="http://jboss.org/schema/seam/drools"

                xmlns:mail="http://jboss.org/schema/seam/mail"

                xmlns:bpm="http://jboss.org/schema/seam/bpm"

                xmlns:persistence="http://jboss.org/schema/seam/persistence"

                xmlns:transaction="http://jboss.org/schema/seam/transaction"

                xmlns:pdf="http://jboss.org/schema/seam/pdf"

                xmlns:security="http://jboss.org/schema/seam/security"

                xmlns:framework="http://jboss.org/schema/seam/framework"

                xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

               

                xsi:schemaLocation="http://jboss.org/schema/seam/core http://jboss.org/schema/seam/core-2.3.xsd                

                     http://jboss.org/schema/seam/persistence http://jboss.org/schema/seam/persistence-2.3.xsd                 

                     http://jboss.org/schema/seam/drools http://jboss.org/schema/seam/drools-2.3.xsd                       

                     http://jboss.org/schema/seam/bpm http://jboss.org/schema/seam/bpm-2.3.xsd                 

                     http://jboss.org/schema/seam/security http://jboss.org/schema/seam/security-2.3.xsd 

                     http://jboss.org/schema/seam/mail http://jboss.org/schema/seam/mail-2.3.xsd                 

                     http://jboss.org/schema/seam/transaction http://jboss.org/schema/seam/transaction-2.3.xsd

                     http://jboss.org/schema/seam/pdf http://jboss.org/schema/seam/pdf-2.3.xsd

                     http://jboss.org/schema/seam/components http://jboss.org/schema/seam/components-2.3.xsd

                     http://jboss.org/schema/seam/transaction http://jboss.org/schema/seam/transaction-2.3.xsd

                     http://jboss.org/schema/seam/framework http://jboss.org/schema/seam/framework-2.3.xsd">

              <core:init debug="true" jndi-pattern="@jndiPattern@" />

              <!-- <context-param> -->

              <!--     <param-name>org.jboss.seam.core.init.jndiPattern</param-name> -->

              <!--     <param-value>project/#{project-ejb}/local</param-value> -->

              <!-- </context-param> -->

                <!--  <core:init debug="true" jndi-pattern="project-ear/#{ejbName}/local" />-->

                <core:manager concurrent-request-timeout="10000"

                conversation-id-parameter="cid" conversation-timeout="3600000"

                parent-conversation-id-parameter="pid" />

              <transaction:ejb-transaction/>

                  <pdf:document-store use-extensions="true" />

                 

                  <core:resource-loader>

                      <core:bundle-names>

                <value>messages</value>

                          </core:bundle-names>

                  </core:resource-loader>

                 <persistence:managed-persistence-context auto-create="true"

                name="entityManager"

                persistence-unit-jndi-name="java:/projectEntityManagerFactory" />

                <security:identity

                authenticate-method="#{project_authenticator.authenticate}"

                remember-me="true" />

                 <mail:mail-session session-jndi-name="java:/Mail" />

                 <bpm:jbpm>

                <bpm:process-definitions>

                <value>userEntry/processdefinition.xml</value>

                <value>projectEntry/processdefinition.xml</value>

                <value>bookingEntry/processdefinition.xml</value>

                </bpm:process-definitions>

                <!--

                <bpm:pageflow-definitions></bpm:pageflow-definitions>

                -->

                </bpm:jbpm>

                  <factory name="cachedTaskInstanceListForType" value="#{taskInstanceListForType}"/>

                  <factory name="messagesFromCourier" value="#{cachedTaskInstanceListForType['receive']}"/>

                <!-- This is required for JBoss AS7 due these EJB components are bound to jboss-seam module  -->

              <component class="org.jboss.seam.transaction.EjbSynchronizations" jndi-name="java:app/jboss-seam/EjbSynchronizations"/>

              <!--     <component class="org.jboss.seam.async.TimerServiceDispatcher" jndi-name="java:app/jboss-seam/TimerServiceDispatcher"/> -->

                <component class="org.jboss.seam.web.MultipartFilter">

                <property name="createTempFiles">true</property>

                </component>

              </components>

               

              This application was successfully running on Jboss 5.1, Seam 2.2 and EJB 3.0, after migrating the application to WildFly 8.2, Seam 2.3.1 and EJB 3.1, we are facing this issue.

              • 4. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                Sreenath Reddy Novice

                Yes Frank, It is waiting for 300 seconds and after that it is showing the above warning. I think my application should not take 300 seconds as I have simple queries which can be executed in 60-120 seconds. I was refering your answer for the post How to change Transaction timeout in WildFly 8.2.0, but it seems we need to do this for each component.I will try to increase the time, is there any way to change the timeout in wildfly 8.2

                • 5. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                  Sreenath Reddy Novice

                  Hi Frank,

                   

                  I increased the time out and waited for 15 min. Still the issue was not resolved

                  • 7. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                    Sreenath Reddy Novice

                    The below is my complete log trace.

                     

                    2015-08-11 22:29:57,408 INFO  [com.project.action.AppData] (MSC service thread 1-1) loadLanguageAllList

                    2015-08-11 22:29:57,426 TRACE [com.arjuna.ats.jta] (MSC service thread 1-1) BaseTransaction.begin

                    2015-08-11 22:29:57,427 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) StateManager::StateManager( 2, 0 )

                    2015-08-11 22:29:57,427 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) BasicAction::BasicAction()

                    2015-08-11 22:29:57,427 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) BasicAction::Begin() for action-id 0:ffffac183738:-3bc2b42a:55ca29a0:9

                    2015-08-11 22:29:57,427 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) BasicAction::actionInitialise() for action-id 0:ffffac183738:-3bc2b42a:55ca29a0:9

                    2015-08-11 22:29:57,428 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) ActionHierarchy::ActionHierarchy(1)

                    2015-08-11 22:29:57,429 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) ActionHierarchy::add(0:ffffac183738:-3bc2b42a:55ca29a0:9, 1)

                    2015-08-11 22:29:57,430 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) BasicAction::addChildThread () action 0:ffffac183738:-3bc2b42a:55ca29a0:9 adding Thread[MSC service thread 1-1,5,main]

                    2015-08-11 22:29:57,430 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) BasicAction::addChildThread () action 0:ffffac183738:-3bc2b42a:55ca29a0:9 adding Thread[MSC service thread 1-1,5,main] result = true

                    2015-08-11 22:29:57,431 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) TransactionReaper::insert ( BasicAction: 0:ffffac183738:-3bc2b42a:55ca29a0:9 status: ActionStatus.RUNNING, 7200 )

                    2015-08-11 22:29:57,431 TRACE [com.arjuna.ats.arjuna] (MSC service thread 1-1) ReaperElement::ReaperElement ( BasicAction: 0:ffffac183738:-3bc2b42a:55ca29a0:9 status: ActionStatus.RUNNING, 7200 )

                    2015-08-11 22:29:57,432 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()

                    2015-08-11 22:29:57,432 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()

                    2015-08-11 22:29:57,432 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1439319597431

                    2015-08-11 22:29:57,432 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 7199999

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:30:19

                    2015-08-11 22:30:19,402 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:30:19,402 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:30:19,402 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:30:19,402 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:30:19,402 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:30:19,402 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:30:19,402 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:b

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:30:19,403 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:30:19,403 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:30:19,403 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:30:19,405 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:30:19,406 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:30:19,406 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:30:19,407 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:30:19,412 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:30:19,413 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:30:29

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:30:29,413 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:30:29,414 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:30:29,414 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:30:29,414 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:30:29,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:30:29,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:30:29,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:32:29,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:32:29,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:32:29,420 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:32:29

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:32:29,420 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:32:29,420 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:32:29,420 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:32:29,420 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:32:29,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:f

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:32:29,421 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:32:29,421 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:32:29,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:32:29,421 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:32:29,421 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:32:29,422 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:32:39,429 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:32:39

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:32:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:34:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:34:39,431 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:34:39,431 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:34:39

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:34:39,431 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:34:39,431 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:34:39,431 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:34:39,431 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:34:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:13

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:34:39,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:34:39,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:34:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:34:39,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:34:39,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:34:39,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:34:49

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:34:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:34:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:36:49

                    2015-08-11 22:36:49,414 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:36:49,414 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:36:49,414 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:36:49,414 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:36:49,414 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:36:49,414 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:36:49,415 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:36:49,415 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:17

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:36:49,415 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:36:49,415 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:36:49,415 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:36:49,417 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:36:49,417 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:36:49,417 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:36:49,417 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:36:49,418 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:36:49,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:36:49,419 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:36:49,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:36:49,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:36:49,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:36:49,419 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:36:49,420 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:36:49,420 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:36:59

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:36:59,418 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:36:59,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:38:59

                    2015-08-11 22:38:59,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:38:59,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:38:59,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:38:59,395 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:38:59,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:38:59,395 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:1b

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:38:59,396 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:38:59,397 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:38:59,397 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:38:59,397 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:38:59,397 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:38:59,397 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:38:59,397 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:38:59,397 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:38:59,397 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:38:59,397 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:39:09

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:39:09,395 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:41:09

                    2015-08-11 22:41:09,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:41:09,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:41:09,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:41:09,419 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:41:09,419 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:41:09,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:41:09,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:41:09,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:1f

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:41:09,420 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:41:09,421 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:41:09,421 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:41:09,421 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:41:09,421 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:41:09,421 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:41:09,421 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:41:19,423 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:41:19

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:41:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:43:19

                    2015-08-11 22:43:19,424 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:43:19,424 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:43:19,424 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:43:19,424 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:43:19,424 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:43:19,424 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:43:19,424 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:23

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:43:19,425 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:43:19,425 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:43:19,425 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:43:19,425 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:43:19,425 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:43:19,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:43:29

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:43:29,426 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:45:29,427 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:45:29,428 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:45:29,428 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:45:29

                    2015-08-11 22:45:29,428 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:45:29,428 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:45:29,428 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:45:29,428 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:45:29,428 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:45:29,428 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:45:29,428 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:45:29,428 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:45:29,428 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:45:29,428 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:27

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:45:29,429 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:45:29,429 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:45:29,429 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:45:29,429 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:45:29,429 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:45:29,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:45:39

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:45:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:47:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:47:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:47:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:47:39

                    2015-08-11 22:47:39,430 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:47:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:47:39,430 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:47:39,430 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:47:39,430 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:47:39,431 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:47:39,431 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:2b

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:47:39,431 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:47:39,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:47:39,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:47:39,432 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:47:39,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:47:39,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:47:39,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:47:49

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:47:49,432 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:47:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:49:49

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:49:49,433 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:49:49,433 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:2f

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:49:49,434 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:49:49,435 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:49:49,435 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:49:49,435 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:49:49,435 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:49:49,435 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:49:49,435 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:49:59

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:49:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:51:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:51:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:51:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:51:59

                    2015-08-11 22:51:59,436 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:51:59,436 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:51:59,436 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:51:59,436 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:51:59,437 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:51:59,437 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:51:59,437 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:33

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:51:59,437 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:51:59,438 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:51:59,438 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:51:59,438 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:51:59,438 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:51:59,438 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:51:59,438 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:52:09

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:52:09,439 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:52:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Tue, 11 Aug 2015 22:54:09

                    2015-08-11 22:54:09,440 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass

                    2015-08-11 22:54:09,440 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:54:09,440 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:54:09,440 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass

                    2015-08-11 22:54:09,440 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:54:09,440 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: )

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffffac183738:-3bc2b42a:55ca29a0:37

                    OutputObjectState Type  : null

                    OutputObjectState Size  : 20

                    OutputObjectState Buffer: , EISNAME)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , 2)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_SHADOW)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 10)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, StateType.OS_ORIGINAL)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME, 11)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffffac183738:47790f3d:55c9e8e1:d, EISNAME) - returning StateStatus.OS_COMMITTED

                    2015-08-11 22:54:09,441 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:54:09,441 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    2015-08-11 22:54:09,441 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()

                    2015-08-11 22:54:09,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:54:09,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Found 0 xids in doubt

                    2015-08-11 22:54:09,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Tue, 11 Aug 2015 22:54:19

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery second pass of RecoveryOnlyEJBXAResource{receiverContext=EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@3e049197, receiver=org.jboss.as.ejb3.remote.LocalEjbReceiver@5e3e1352}, transactionOriginNodeIdentifier='1'}

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Have 0 Xids to recover on this pass.

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE

                    2015-08-11 22:54:19,442 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

                    • 8. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                      Scott Marlow Master

                      Try enabling TRACE logging for org.jboss.as.jpa also, that might give you an idea of what is taking too long (if you are using container managed persistence contexts).  The org.jboss.as.jpa TRACE logging should show how long each EntityManager invocation took.

                      • 9. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                        Amos Feng Apprentice

                        I agree that the issue looks like related to timeout.

                        • 10. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                          Sreenath Reddy Novice

                          But I changed the timeout to 7200 i.e 2 hours, I got the above warnings after 2 hours. My application was running successfully on JBoss 5.1.0 and it will not take more than 180 sec to fetch the data.

                          • 11. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                            Scott Marlow Master

                            In AS 5.1, were you loading the initial application data within a JTA transaction?  How long did it take in AS 5.1 to load the initial application state? 

                            • 12. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                              Sreenath Reddy Novice

                              Yes scott, we are loading the initial app data with in a JTA transaction and it was taking 15-20 sec in AS 5.1. I am suspecting that we need to do some code changes as part of migrating from Seam 2.2.0 to 2.3.1.

                              • 13. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                                Sreenath Reddy Novice

                                Hi Scott,

                                 

                                Because of this issue I am blocked with my migration from 5.1.0 to wildfly 8.2.0. Do we need to give the transaction details explicitly in components.xml or persistence.xml.

                                • 14. Re: Transaction issue while migrating Jboss 5.1 to WildFly 8.2
                                  Scott Marlow Master

                                  Hi Sreenath,

                                   

                                  Typically, you need to do the work of figuring out why the application (data loading) initialization is not taking 20 seconds on WildFly 8.2.0.  You need to understand your application code that is related to the area that is "very slow" or "getting stuck".  I would enable the org.jboss.as.jpa trace logging that I mentioned before, that should give you a hint as to where the application is slowing down or getting stuck.

                                   

                                  You could also look into a purchasing a support contract as well.  I'm not going to say any more about that path here but wanted to mention it as well.

                                   

                                  Scott

                                  1 2 Previous Next