1 2 Previous Next 23 Replies Latest reply on Aug 29, 2016 2:00 PM by christopher.j.willems Go to original post
      • 15. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
        smarlow

        So you have the traces you want from Wildfly ?

        I'm not really sure which JTA transaction to look at in the server.log.  I looked at the first few after the first server start and don't see any answers.

         

        Would it be possible to update the relationship setter method to check for null and call Thread.dumpStack() to show what code is clearing the relationship?

         

        For later reference, below is the first JTA transaction after the app server starts that seems to have JPA activity, not that I see anything directly related to the problem.

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::Begin() for action-id 0:ffffc0a80165:2e8fcbdc:57bd81ef:11

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::actionInitialise() for action-id 0:ffffc0a80165:2e8fcbdc:57bd81ef:11

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) ActionHierarchy::ActionHierarchy(1)

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) ActionHierarchy::add(0:ffffc0a80165:2e8fcbdc:57bd81ef:11, 1)

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::addChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 adding Thread[default task-2,5,main]

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::addChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 adding Thread[default task-2,5,main] result = true

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) TransactionReaper::insert ( BasicAction: 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 status: ActionStatus.RUNNING, 600 )

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) ReaperElement::ReaperElement ( BasicAction: 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 status: ActionStatus.RUNNING, 600 )

        2016-08-24 13:16:28,990 DEBUG [org.jboss.as.jpa] (default task-2) created new TransactionScopedEntityManager for unit name=veri95app.ear#VERI95

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.jta] (default task-2) BaseTransaction.commit

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.commitAndDisassociate

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::End() for action-id 0:ffffc0a80165:2e8fcbdc:57bd81ef:11

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::End() result for action-id (0:ffffc0a80165:2e8fcbdc:57bd81ef:11) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::removeChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 removing TSThread:1

        2016-08-24 13:16:28,990 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::removeChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 removing TSThread:1 result = true

        2016-08-24 13:16:28,991 TRACE [com.arjuna.ats.arjuna] (default task-2) TransactionReaper::remove ( BasicAction: 0:ffffc0a80165:2e8fcbdc:57bd81ef:11 status: ActionStatus.COMMITTED )

        2016-08-24 13:16:28,991 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImpleManager.resume

        2016-08-24 13:16:28,991 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::addChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:10 adding Thread[default task-2,5,main]

        2016-08-24 13:16:28,991 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::addChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:10 adding Thread[default task-2,5,main] result = true

        2016-08-24 13:16:28,992 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:28,992 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getResource

        2016-08-24 13:16:28,992 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,001 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.registerSynchronization - Class: class org.eclipse.persistence.internal.jpa.transaction.JTATransactionWrapper$1 HashCode: 1712490575 toString: org.eclipse.persistence.internal.jpa.transaction.JTATransactionWrapper$1@6612884f

        2016-08-24 13:16:29,002 DEBUG [org.jboss.as.jpa] (default task-2) default task-2:transaction scoped EntityManager [veri95app.ear#VERI95]: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a80165:2e8fcbdc:57bd81ef:10 status: ActionStatus.RUNNING >

        2016-08-24 13:16:29,002 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.registerInterposedSynchronization - Class: class org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList HashCode: 2083870043 toString: org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList@7c35555b

        2016-08-24 13:16:29,002 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,002 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,003 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.equals

        2016-08-24 13:16:29,003 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.putResource

        2016-08-24 13:16:29,003 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,009 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,009 TRACE [org.jboss.as.jpa] (default task-2) createNamedQuery name 'GeneralCustomizing.getCustomizingValueByGeneralCustomizingId' took 18ms

        2016-08-24 13:16:29,011 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.011--ServerSession(266485903)--Thread(Thread[default task-2,5,main])--client acquired: 532150083 

        2016-08-24 13:16:29,017 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,017 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.017--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--TX binding to tx mgr, status=STATUS_ACTIVE 

        2016-08-24 13:16:29,017 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.registerSynchronization - Class: class org.eclipse.persistence.transaction.JTASynchronizationListener HashCode: 1783378643 toString: org.eclipse.persistence.transaction.JTASynchronizationListener@6a4c32d3

        2016-08-24 13:16:29,017 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.017--ClientSession(532150083)--Thread(Thread[default task-2,5,main])--acquire unit of work: 1256093239 

        2016-08-24 13:16:29,018 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.018--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--begin unit of work flush 

        2016-08-24 13:16:29,018 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.018--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--end unit of work flush 

        2016-08-24 13:16:29,018 INFO  [stdout] (default task-2) [EL Finest]: 2016-08-24 13:16:29.018--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--Execute query ReportQuery(name="GeneralCustomizing.getCustomizingValueByGeneralCustomizingId" referenceClass=GeneralCustomizing sql="SELECT VAL FROM V95_CUST_GNRL WHERE (CODE = ?)") 

        2016-08-24 13:16:29,020 INFO  [stdout] (default task-2) [EL Finest]: 2016-08-24 13:16:29.02--ServerSession(266485903)--Connection(1567378445)--Thread(Thread[default task-2,5,main])--Connection acquired from connection pool [read]. 

        2016-08-24 13:16:29,020 INFO  [stdout] (default task-2) [EL Finest]: 2016-08-24 13:16:29.02--ServerSession(266485903)--Thread(Thread[default task-2,5,main])--reconnecting to external connection pool 

        2016-08-24 13:16:29,020 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,020 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getTransactionKey

        2016-08-24 13:16:29,020 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getTransactionKey

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getTransactionKey

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.putResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getTransactionKey

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.getResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionSynchronizationRegistryImple.putResource

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,021 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,022 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,023 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.enlistResource ( LocalXAResourceImpl@6f7677c7[connectionListener=9cb2669 connectionManager=58f621d4 warned=false currentXid=null productName=Microsoft SQL Server productVersion=11.00.3513 jndiName=java:/veri95] )

        2016-08-24 13:16:29,023 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) InputObjectState::InputObjectState()

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

        InputObjectState Type  : null

        InputObjectState Size  : 0

        InputObjectState Buffer: , -1)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) OutputObjectState::OutputObjectState()

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.read_committed(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) ShadowingStore.read_state(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, StateType.OS_ORIGINAL)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) ShadowingStore.genPathName(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, StateType.OS_SHADOW)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.genPathName(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, 10)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) ShadowingStore.genPathName(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, StateType.OS_ORIGINAL)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.genPathName(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, 11)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) ShadowingStore.currentState(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME) - returning StateStatus.OS_COMMITTED

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) ShadowingStore.genPathName(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, StateType.OS_ORIGINAL)

        2016-08-24 13:16:29,024 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.genPathName(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME, 11)

        2016-08-24 13:16:29,025 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.openAndLock(C:\wildfly\wildfly-10.0.0.Final\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a80165_12b43ed_57965544_c0, FileLock.F_RDLCK, false)

        2016-08-24 13:16:29,025 TRACE [com.arjuna.ats.arjuna] (default task-2) InputObjectState::InputObjectState(0:ffffc0a80165:12b43ed:57965544:c0, EISNAME)

        2016-08-24 13:16:29,026 TRACE [com.arjuna.ats.arjuna] (default task-2) FileSystemStore.closeAndUnlock(C:\wildfly\wildfly-10.0.0.Final\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a80165_12b43ed_57965544_c0, java.io.FileInputStream@5495f254, null)

        2016-08-24 13:16:29,028 TRACE [com.arjuna.ats.arjuna] (default task-2) StateManager::StateManager( 0:0:0:0:1 )

        2016-08-24 13:16:29,028 TRACE [com.arjuna.ats.arjuna] (default task-2) AbstractRecord::AbstractRecord (0:0:0:0:1)

        2016-08-24 13:16:29,028 TRACE [com.arjuna.ats.arjuna] (default task-2) LastResourceRecord()

        2016-08-24 13:16:29,029 TRACE [com.arjuna.ats.arjuna] (default task-2) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/LastResourceRecord for 0:0:0:0:1

        2016-08-24 13:16:29,030 INFO  [stdout] (default task-2) [EL Fine]: 2016-08-24 13:16:29.03--ServerSession(266485903)--Connection(652230437)--Thread(Thread[default task-2,5,main])--SELECT VAL FROM V95_CUST_GNRL WHERE (CODE = ?) 

        2016-08-24 13:16:29,030 INFO  [stdout] (default task-2)     bind => [XML_PROCESSING_ATTEMPTS] 

        2016-08-24 13:16:29,030 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,034 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,037 INFO  [stdout] (default task-2) [EL Finest]: 2016-08-24 13:16:29.037--ServerSession(266485903)--Connection(1567378445)--Thread(Thread[default task-2,5,main])--Connection released to connection pool [read]. 

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) BaseTransaction.commit

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.commitAndDisassociate

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) SynchronizationImple.beforeCompletion - Class: class org.eclipse.persistence.internal.jpa.transaction.JTATransactionWrapper$1 HashCode: 1712490575 toString: org.eclipse.persistence.internal.jpa.transaction.JTATransactionWrapper$1@6612884f

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) SynchronizationImple.beforeCompletion - Class: class org.eclipse.persistence.transaction.JTASynchronizationListener HashCode: 1783378643 toString: org.eclipse.persistence.transaction.JTASynchronizationListener@6a4c32d3

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,037 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.037--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--TX beforeCompletion callback, status=STATUS_ACTIVE 

        2016-08-24 13:16:29,037 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.037--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--begin unit of work commit 

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) SynchronizationImple.beforeCompletion - Class: class org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList HashCode: 2083870043 toString: org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList@7c35555b

        2016-08-24 13:16:29,037 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.delistResource ( LocalXAResourceImpl@6f7677c7[connectionListener=9cb2669 connectionManager=58f621d4 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80165:2e8fcbdc:57bd81ef:10, node_name=1, branch_uid=0:ffffc0a80165:2e8fcbdc:57bd81ef:16, subordinatenodename=null, eis_name=java:/veri95 > productName=Microsoft SQL Server productVersion=11.00.3513 jndiName=java:/veri95], 67108864 )

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::End() for action-id 0:ffffc0a80165:2e8fcbdc:57bd81ef:10

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::onePhaseCommit() for action-id 0:ffffc0a80165:2e8fcbdc:57bd81ef:10

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.arjuna] (default task-2) LastResourceRecord::topLevelPrepare() for 0:0:0:0:1

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.arjuna] (default task-2) LastResourceRecord::topLevelCommit() for 0:0:0:0:1

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::End() result for action-id (0:ffffc0a80165:2e8fcbdc:57bd81ef:10) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.jta] (default task-2) SynchronizationImple.afterCompletion - Class: class org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList HashCode: 2083870043 toString: org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList@7c35555b

        2016-08-24 13:16:29,038 DEBUG [org.jboss.as.jpa] (default task-2) default task-2:transaction scoped EntityManager [veri95app.ear#VERI95]: closing entity managersession

        2016-08-24 13:16:29,038 TRACE [com.arjuna.ats.jta] (default task-2) SynchronizationImple.afterCompletion - Class: class org.eclipse.persistence.transaction.JTASynchronizationListener HashCode: 1783378643 toString: org.eclipse.persistence.transaction.JTASynchronizationListener@6a4c32d3

        2016-08-24 13:16:29,039 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.038--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--TX afterCompletion callback, status=COMMITTED 

        2016-08-24 13:16:29,039 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.039--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--end unit of work commit 

        2016-08-24 13:16:29,039 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.039--UnitOfWork(1256093239)--Thread(Thread[default task-2,5,main])--release unit of work 

        2016-08-24 13:16:29,039 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-24 13:16:29.039--ClientSession(532150083)--Thread(Thread[default task-2,5,main])--client released 

        2016-08-24 13:16:29,039 TRACE [com.arjuna.ats.jta] (default task-2) SynchronizationImple.afterCompletion - Class: class org.eclipse.persistence.internal.jpa.transaction.JTATransactionWrapper$1 HashCode: 1712490575 toString: org.eclipse.persistence.internal.jpa.transaction.JTATransactionWrapper$1@6612884f

        2016-08-24 13:16:29,039 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::removeChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:10 removing TSThread:1

        2016-08-24 13:16:29,039 TRACE [com.arjuna.ats.arjuna] (default task-2) BasicAction::removeChildThread () action 0:ffffc0a80165:2e8fcbdc:57bd81ef:10 removing TSThread:1 result = true

        2016-08-24 13:16:29,039 TRACE [com.arjuna.ats.arjuna] (default task-2) TransactionReaper::remove ( BasicAction: 0:ffffc0a80165:2e8fcbdc:57bd81ef:10 status: ActionStatus.COMMITTED )

         

        • 16. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
          christopher.j.willems

          hi ,

          i added the logs to jira but may be this is important :

           

          the transaction is started in a bean with

          @Stateless

          @TransactionManagement(TransactionManagementType.BEAN)

           

          but I perform the actions in a container managed bean

          @TransactionManagement(TransactionManagementType.CONTAINER)

          @TransactionAttribute(value = REQUIRED)

          • 17. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
            smarlow

            I updated the first dumpStack() output in the log to not include the various EJB related calls for easier reading:

             

            2016-08-25 17:09:29,681 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2016-08-25 17:09:29,681 DEBUG [org.jboss.as.jpa] (default task-2) default task-2:transaction scoped EntityManager [veri95app.ear#VERI95]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a80165:19bdbd09:57bf09ec:17 status: ActionStatus.RUNNING >

            2016-08-25 17:09:29,682 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2016-08-25 17:09:29,682 TRACE [org.jboss.as.jpa] (default task-2) createNamedQuery name 'PersonnelClass.getPersonnelClassByPersonnelClassID' took 2ms

            2016-08-25 17:09:29,682 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-25 17:09:29.682--UnitOfWork(1942582596)--Thread(Thread[default task-2,5,main])--begin unit of work flush 

            2016-08-25 17:09:29,683 INFO  [stdout] (default task-2) [EL Finer]: 2016-08-25 17:09:29.683--UnitOfWork(1942582596)--Thread(Thread[default task-2,5,main])--end unit of work flush 

            2016-08-25 17:09:29,683 INFO  [stdout] (default task-2) [EL Finest]: 2016-08-25 17:09:29.683--UnitOfWork(1942582596)--Thread(Thread[default task-2,5,main])--Execute query ReadAllQuery(name="PersonnelClass.getPersonnelClassByPersonnelClassID" referenceClass=PersonnelClass sql="SELECT UIID, CHANGEDBY, CHANGEDON, CREATEDBY, CREATEDON, CUST_TYPE, ID, PERS_LEVEL, HIER_SCOPE FROM V95_PECL WHERE (ID = ?)") 

            2016-08-25 17:09:29,683 INFO  [stdout] (default task-2) [EL Fine]: 2016-08-25 17:09:29.683--ClientSession(1639754146)--Connection(334773752)--Thread(Thread[default task-2,5,main])--SELECT UIID, CHANGEDBY, CHANGEDON, CREATEDBY, CREATEDON, CUST_TYPE, ID, PERS_LEVEL, HIER_SCOPE FROM V95_PECL WHERE (ID = ?) 

            2016-08-25 17:09:29,683 INFO  [stdout] (default task-2)     bind => [Operators] 

            2016-08-25 17:09:29,684 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2016-08-25 17:09:29,684 TRACE [com.arjuna.ats.jta] (default task-2) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2016-08-25 17:09:29,685 ERROR [stderr] (default task-2) java.lang.Exception: Stack trace 

            2016-08-25 17:09:29,685 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.personnel.person.PersonServicesCore.addPersonnelClassDefinedBy(PersonServicesCore.java:3602) 

            2016-08-25 17:09:29,688 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:254) 

            2016-08-25 17:09:29,688 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:329) 

            2016-08-25 17:09:29,688 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) 

            2016-08-25 17:09:29,690 ERROR [stderr] (default task-2)     at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73) 

            2016-08-25 17:09:29,690 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.personnel.person.PersonServicesCoreLocal$$$view156.addPersonnelClassDefinedBy(Unknown Source) 

            2016-08-25 17:09:29,691 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.personnel.person.PersonXMLServiceCore.updateRelationships(PersonXMLServiceCore.java:696) 

            2016-08-25 17:09:29,691 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.personnel.person.PersonXMLServiceCore.updatePerson(PersonXMLServiceCore.java:363) 

            2016-08-25 17:09:29,691 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.personnel.person.PersonXMLServiceCore.processXml(PersonXMLServiceCore.java:206) 

            2016-08-25 17:09:29,692 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.EjbBMTInterceptor.handleInvocation(EjbBMTInterceptor.java:103) 

            2016-08-25 17:09:29,692 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.BMTInterceptor.processInvocation(BMTInterceptor.java:58) 

            2016-08-25 17:09:29,695 ERROR [stderr] (default task-2)     at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73) 

            2016-08-25 17:09:29,695 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.personnel.person.PersonXMLServiceCoreLocal$$$view145.processXml(Unknown Source) 

            2016-08-25 17:09:29,695 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.rs.v2.model.util.XmlServicesRest.processXml(XmlServicesRest.java:108) 

            2016-08-25 17:09:29,697 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:275) 

            2016-08-25 17:09:29,697 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:327) 

            2016-08-25 17:09:29,697 ERROR [stderr] (default task-2)     at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at inxites.be.veri95.ejb.service.rs.v2.model.util.XmlServicesRest$$$view7.processXml(Unknown Source) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at java.lang.reflect.Method.invoke(Method.java:498) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:395) 

            2016-08-25 17:09:29,699 ERROR [stderr] (default task-2)     at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:202) 

            2016-08-25 17:09:29,700 ERROR [stderr] (default task-2)     at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221) 

            2016-08-25 17:09:29,700 ERROR [stderr] (default task-2)     at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) 

            2016-08-25 17:09:29,700 ERROR [stderr] (default task-2)     at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) 

            2016-08-25 17:09:29,700 ERROR [stderr] (default task-2)     at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) 

             

             

            I see no reason why starting a JTA transaction via (BMT) UserTransaction should be a problem for the call to the container managed transaction bean, however, from the above call stack, it looks like XmlServicesRest.processXml() may already have started a JTA transaction before the BMT code is invoked.  Is PersonXMLServiceCore.processXml() suspending the callers JTA transaction somehow? 

             

            One thing that I noticed from the trace output, is that we are reusing the EntityManager (via VERI95 persistence unit) that is already associated with the JTA transaction, which should be expected.  Perhaps you could look at the above mentioned lines of code in your application and explain if you expect the "PersonXMLServiceCore.updatePerson(PersonXMLServiceCore.java:363)" to be reached and to be setting the (dropped) relationship to null.  Basically, we are looking for conditions in your code that might be sensitive to this (currently) unknown difference between WildFly + GlassFish running your app.

            • 18. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
              christopher.j.willems

              hi ,

               

              sorry for the late reply but I have been debugging and seems that the issue is not weaving , if I remove the annotation @XmlElementWrapper(name = "personnelClasses") from the entity it is ok... I thought probably the name of the wrapper should be different than the entity member but this has no effect ..

               

              @XmlElementWrapper(name = "personnelClasses")

                  @XmlElement(name = "personnelClass")

                  public List<LinkPersonnelClassPersonDefinedBy> getPersonnelClasses() {

                      if (this.personnelClasses.isEmpty()) {

                            return null;

                      }

               

                   return this.personnelClasses;

                  }

               

              so what you think , this is possible ?

              • 19. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
                christopher.j.willems

                sorry my mistake the XmlElementWrapper has nothing to do with it ...

                • 20. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
                  smarlow

                  Is the getPersonnelClasses() code above showing how null is coming into the application, after the application server restart and first JTA transaction commits?  Is setPersonnelClasses(null) called perhaps when the transaction commits?

                  • 21. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
                    christopher.j.willems

                    hi ,

                     

                    i found what triggers this strange behavior .

                     

                    in my stateless bean annotated with @TransactionManagement(TransactionManagementType.BEAN) i inject stateless beans annotated with

                    @TransactionManagement(TransactionManagementType.CONTAINER)

                    @TransactionAttribute(value = REQUIRED)

                     

                     

                    @EJB

                    private PersonServicesCoreLocal psc;

                     

                    @EJB

                    private PersonnelClassServicesCoreLocal pcsc;

                     

                    @EJB

                    private CustomizingLocal customizing;

                     

                     

                     

                    private void updatePerson(Person peIncoming, String transactionID) throws Exception {

                    Person peOriginal = psc.findPersonByPersonId(peIncoming.getId(), transactionID);

                     

                    peOriginal.setHierarchyScopePath(peIncoming.getHierarchyScopePath());

                    peOriginal.setCustomizingDataType(peIncoming.getCustomizingDataType());

                    peOriginal.setPersonName(peIncoming.getPersonName());

                     

                    psc.changePerson(peOriginal, transactionID);

                     

                    if (customizing.checkXMLReplaceRelationshipsActive()) {

                    removeRelationships(peOriginal, transactionID);

                    }

                    updateRelationships(peOriginal, peIncoming, transactionID);

                    processPersonDescriptionsAndProperties(peOriginal, peIncoming, transactionID);

                     

                    }

                     

                     

                    this situation will give the error . If I use @TransactionAttribute(value = NOT_SUPPORTED) in the customizing bean the error is not occurring .

                     

                    i know this is not the complete story yet but it's a step ahead ..

                     

                    another thing I noticed is that the combination of @TransactionManagement(TransactionManagementType.BEAN) with a @TransactionAttribute is not giving an error on deploy although not supported

                    • 22. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
                      smarlow

                      Interesting, I wonder if GlassFish is always treating the combination of @TransactionManagement(TransactionManagementType.BEAN) + any TransactionAttribute, as if TransactionAttribute(value = NOT_SUPPORTED) is specified.

                      • 23. Re: problem with lazy relationship and eclipselink 2.5.2 on wildfly 10 final
                        christopher.j.willems

                        no idea , but there is a difference because glassfish will give a deploy error if you put the annotation .

                         

                        i am stripping my coding to isolate this issue but it will need some time ...

                        1 2 Previous Next