NPE - Synchronization.afterCompletion() call failed - Bitronix

Type: Bug
Status: Closed
Priority: 2 Major
Resolution: Fixed
Component/s: ehcache-core
Labels:

Assignee:
Reporter: foshea
Created: June 29, 2010
Votes: 0
Watchers: 1
Updated:
July 27, 2012
Resolved:
December 14, 2010

Description

Related to EHC-696 -or maybe the same issue

From Ludovic it seems to be a Hibernate issue it registered a Synchronization which is supposed to update some transactional caches after the transaction finished its execution.

This can never work and clearly is a problem in Hibernate itself.

@Brett: I’d advise to to try to narrow down the problem as much as possible so we can report the problem to the Hibernate team and push together to get it solved ASAP.

Comments

Fiona OShea 2010-06-29

Brett Wooldridge added a comment - 13/May/10 07:03 PM

Thanks Ludovic, I set this option.

Now I’m getting the following exception performing an update of some entities. Apologies for the long trace.

01:52:13,411 [JDBCContext ] [Jetty-1 ] DEBUG - successfully registered Synchronization 01:52:13,411 [SessionImpl ] [Jetty-1 ] DEBUG - opened session at timestamp: 5217492719247360 01:52:13,412 [QueryPlanCache ] [Jetty-1 ] TRACE - located HQL query plan in cache (UPDATE org.ziptie.credentials.DeviceToCredentialSetMapping SET stale = true WHERE fkCredentialSetId = 1) 01:52:13,413 [QueryPlanCache ] [Jetty-1 ] TRACE - located HQL query plan in cache (UPDATE org.ziptie.credentials.DeviceToCredentialSetMapping SET stale = true WHERE fkCredentialSetId = 1) 01:52:13,413 [HQLQueryPlan ] [Jetty-1 ] TRACE - executeUpdate: UPDATE org.ziptie.credentials.DeviceToCredentialSetMapping SET stale = true WHERE fkCredentialSetId = 1 01:52:13,415 [QueryParameters ] [Jetty-1 ] TRACE - named parameters: {} 01:52:13,416 [EhcacheXAResourceImpl ] [Jetty-1 ] DEBUG - xaResource.start called for Txn with flag: TMNOFLAGS and id: a Bitronix XID [6E65746C642D31000001289483025E00000131 : 6E65746C642D31000001289483026800000133] 01:52:13,416 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 01:52:13,417 [ConnectionManager ] [Jetty-1 ] DEBUG - opening JDBC connection 01:52:13,418 [SQL ] [Jetty-1 ] DEBUG - update device_to_cred_set_mappings set stale=1 where fkCredentialSetId=1 Hibernate: update device_to_cred_set_mappings set stale=1 where fkCredentialSetId=1 01:52:13,420 [AbstractBatcher ] [Jetty-1 ] TRACE - preparing statement 01:52:13,422 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 01:52:13,422 [AbstractBatcher ] [Jetty-1 ] TRACE - closing statement 01:52:13,422 [ConnectionManager ] [Jetty-1 ] DEBUG - aggressively releasing JDBC connection 01:52:13,422 [ConnectionManager ] [Jetty-1 ] DEBUG - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 01:52:13,423 [IdentifierValue ] [Jetty-1 ] TRACE - id unsaved-value: -1 01:52:13,423 [AbstractSaveEventListener] [Jetty-1 ] TRACE - detached instance of: org.ziptie.credentials.CredentialConfig 01:52:13,423 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,424 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.CredentialConfig#1 01:52:13,424 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.CredentialConfig#1 01:52:13,425 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.CredentialConfig#1 01:52:13,425 [LoadContexts ] [Jetty-1 ] TRACE - creating collection wrapper:org.ziptie.credentials.CredentialConfig.credentialSets#1 01:52:13,425 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,426 [tatefulPersistenceContext] [Jetty-1 ] DEBUG - initializing non-lazy collections 01:52:13,427 [zeCollectionEventListener] [Jetty-1 ] TRACE - initializing collection org.ziptie.credentials.CredentialConfig.credentialSets#1 01:52:13,427 [zeCollectionEventListener] [Jetty-1 ] TRACE - checking second-level cache 01:52:13,428 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.CredentialSet#1 01:52:13,428 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.CredentialSet#1 01:52:13,429 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.CredentialSet#1 01:52:13,429 [LoadContexts ] [Jetty-1 ] TRACE - creating collection wrapper:org.ziptie.credentials.CredentialSet.credentials#1 01:52:13,429 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,429 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.CredentialSet#1 01:52:13,429 [zeCollectionEventListener] [Jetty-1 ] TRACE - initializing collection org.ziptie.credentials.CredentialSet.credentials#1 01:52:13,429 [zeCollectionEventListener] [Jetty-1 ] TRACE - checking second-level cache 01:52:13,430 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#3 01:52:13,430 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#3 01:52:13,431 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#3 01:52:13,431 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,431 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#3 01:52:13,431 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#6 01:52:13,431 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#6 01:52:13,432 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#6 01:52:13,432 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,432 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#6 01:52:13,433 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#1 01:52:13,433 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#1 01:52:13,433 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#1 01:52:13,434 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,434 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#1 01:52:13,434 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#4 01:52:13,434 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#4 01:52:13,435 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#4 01:52:13,435 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,435 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#4 01:52:13,435 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#5 01:52:13,435 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#5 01:52:13,436 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#5 01:52:13,436 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,436 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#5 01:52:13,436 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#2 01:52:13,436 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#2 01:52:13,437 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#2 01:52:13,437 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,437 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#2 01:52:13,437 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#7 01:52:13,437 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#7 01:52:13,438 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#7 01:52:13,438 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,438 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#7 01:52:13,438 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#8 01:52:13,438 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#8 01:52:13,439 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#8 01:52:13,439 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,439 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#8 01:52:13,440 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#9 01:52:13,440 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#9 01:52:13,440 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - assembling entity from second-level cache: org.ziptie.credentials.Credential#9 01:52:13,441 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - Cached Version: null 01:52:13,441 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.Credential#9 01:52:13,441 [zeCollectionEventListener] [Jetty-1 ] TRACE - collection initialized from cache 01:52:13,441 [zeCollectionEventListener] [Jetty-1 ] TRACE - collection initialized from cache 01:52:13,441 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in second-level cache: org.ziptie.credentials.CredentialConfig#1 01:52:13,441 [Cascade ] [Jetty-1 ] TRACE - processing cascade ACTION_MERGE for: org.ziptie.credentials.CredentialConfig 01:52:13,441 [Cascade ] [Jetty-1 ] TRACE - cascade ACTION_MERGE for collection: org.ziptie.credentials.CredentialConfig.credentialSets 01:52:13,441 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.CredentialSet 01:52:13,441 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.CredentialSet#1 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.CredentialSet#1 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.CredentialSet#1 01:52:13,442 [Cascade ] [Jetty-1 ] TRACE - processing cascade ACTION_MERGE for: org.ziptie.credentials.CredentialSet 01:52:13,442 [Cascade ] [Jetty-1 ] TRACE - cascade ACTION_MERGE for collection: org.ziptie.credentials.CredentialSet.credentials 01:52:13,442 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,442 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#3 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#3 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#3 01:52:13,442 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,442 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,442 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#6 01:52:13,443 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#6 01:52:13,443 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#6 01:52:13,443 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,443 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,443 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#1 01:52:13,443 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#1 01:52:13,443 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#1 01:52:13,444 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,444 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,444 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#4 01:52:13,444 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#4 01:52:13,444 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#4 01:52:13,444 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,444 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,444 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#2 01:52:13,445 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#2 01:52:13,445 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#2 01:52:13,445 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,445 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,445 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#5 01:52:13,445 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#5 01:52:13,445 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#5 01:52:13,445 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,445 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,446 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#7 01:52:13,446 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#7 01:52:13,446 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#7 01:52:13,446 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,446 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,446 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#8 01:52:13,446 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#8 01:52:13,446 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#8 01:52:13,446 [CascadingAction ] [Jetty-1 ] TRACE - cascading to merge: org.ziptie.credentials.Credential 01:52:13,447 [DefaultMergeEventListener] [Jetty-1 ] TRACE - merging detached instance 01:52:13,447 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - loading entity: org.ziptie.credentials.Credential#9 01:52:13,447 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - attempting to resolve: org.ziptie.credentials.Credential#9 01:52:13,447 [DefaultLoadEventListener ] [Jetty-1 ] TRACE - resolved object in session cache: org.ziptie.credentials.Credential#9 01:52:13,447 [Cascade ] [Jetty-1 ] TRACE - done cascade ACTION_MERGE for collection: org.ziptie.credentials.CredentialSet.credentials 01:52:13,447 [Cascade ] [Jetty-1 ] TRACE - done processing cascade ACTION_MERGE for: org.ziptie.credentials.CredentialSet 01:52:13,447 [Cascade ] [Jetty-1 ] TRACE - done cascade ACTION_MERGE for collection: org.ziptie.credentials.CredentialConfig.credentialSets 01:52:13,447 [Cascade ] [Jetty-1 ] TRACE - done processing cascade ACTION_MERGE for: org.ziptie.credentials.CredentialConfig 01:52:13,447 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.CredentialConfig 01:52:13,448 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,448 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.CredentialConfig#1 01:52:13,449 [CacheSynchronization ] [Jetty-1 ] TRACE - transaction before completion callback 01:52:13,449 [CacheSynchronization ] [Jetty-1 ] TRACE - automatically flushing session 01:52:13,449 [SessionImpl ] [Jetty-1 ] TRACE - automatically flushing session 01:52:13,449 [ractFlushingEventListener] [Jetty-1 ] TRACE - flushing session 01:52:13,450 [ractFlushingEventListener] [Jetty-1 ] DEBUG - processing flush-time cascades 01:52:13,450 [Cascade ] [Jetty-1 ] TRACE - processing cascade ACTION_SAVE_UPDATE for: org.ziptie.credentials.CredentialConfig 01:52:13,450 [Cascade ] [Jetty-1 ] TRACE - cascade ACTION_SAVE_UPDATE for collection: org.ziptie.credentials.CredentialConfig.credentialSets 01:52:13,450 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.CredentialSet 01:52:13,450 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.CredentialSet 01:52:13,450 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,450 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.CredentialSet#1 01:52:13,450 [Cascade ] [Jetty-1 ] TRACE - done cascade ACTION_SAVE_UPDATE for collection: org.ziptie.credentials.CredentialConfig.credentialSets 01:52:13,450 [Cascade ] [Jetty-1 ] TRACE - deleting orphans for collection: org.ziptie.credentials.CredentialConfig.credentialSets 01:52:13,451 [Cascade ] [Jetty-1 ] TRACE - done deleting orphans for collection: org.ziptie.credentials.CredentialConfig.credentialSets 01:52:13,451 [Cascade ] [Jetty-1 ] TRACE - done processing cascade ACTION_SAVE_UPDATE for: org.ziptie.credentials.CredentialConfig 01:52:13,451 [Cascade ] [Jetty-1 ] TRACE - processing cascade ACTION_SAVE_UPDATE for: org.ziptie.credentials.CredentialSet 01:52:13,451 [Cascade ] [Jetty-1 ] TRACE - cascade ACTION_SAVE_UPDATE for collection: org.ziptie.credentials.CredentialSet.credentials 01:52:13,451 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,451 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,451 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,451 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#3 01:52:13,451 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,451 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,451 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,452 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#6 01:52:13,452 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,452 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,452 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,452 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#1 01:52:13,452 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,452 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,452 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,452 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#4 01:52:13,452 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,453 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,453 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,453 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#2 01:52:13,453 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,453 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,453 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,453 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#5 01:52:13,453 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,453 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,453 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,454 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#7 01:52:13,454 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,454 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,454 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,454 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#8 01:52:13,454 [CascadingAction ] [Jetty-1 ] TRACE - cascading to saveOrUpdate: org.ziptie.credentials.Credential 01:52:13,454 [AbstractSaveEventListener] [Jetty-1 ] TRACE - persistent instance of: org.ziptie.credentials.Credential 01:52:13,454 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - ignoring persistent instance 01:52:13,454 [SaveOrUpdateEventListener] [Jetty-1 ] TRACE - object already associated with session: org.ziptie.credentials.Credential#9 01:52:13,454 [Cascade ] [Jetty-1 ] TRACE - done cascade ACTION_SAVE_UPDATE for collection: org.ziptie.credentials.CredentialSet.credentials 01:52:13,455 [Cascade ] [Jetty-1 ] TRACE - deleting orphans for collection: org.ziptie.credentials.CredentialSet.credentials 01:52:13,455 [Cascade ] [Jetty-1 ] TRACE - done deleting orphans for collection: org.ziptie.credentials.CredentialSet.credentials 01:52:13,455 [Cascade ] [Jetty-1 ] TRACE - done processing cascade ACTION_SAVE_UPDATE for: org.ziptie.credentials.CredentialSet 01:52:13,455 [ractFlushingEventListener] [Jetty-1 ] DEBUG - dirty checking collections 01:52:13,455 [CollectionEntry ] [Jetty-1 ] DEBUG - Collection dirty: org.ziptie.credentials.CredentialConfig.credentialSets#1 01:52:13,455 [CollectionEntry ] [Jetty-1 ] DEBUG - Collection dirty: org.ziptie.credentials.CredentialSet.credentials#1 01:52:13,455 [ractFlushingEventListener] [Jetty-1 ] TRACE - Flushing entities and processing referenced collections 01:52:13,456 [Collections ] [Jetty-1 ] DEBUG - Collection found: org.ziptie.credentials.CredentialConfig.credentialSets#1, was: org.ziptie.credentials.CredentialConfig.credentialSets#1 (initialized) 01:52:13,456 [Collections ] [Jetty-1 ] DEBUG - Collection found: org.ziptie.credentials.CredentialSet.credentials#1, was: org.ziptie.credentials.CredentialSet.credentials#1 (initialized) 01:52:13,456 [AbstractEntityPersister ] [Jetty-1 ] TRACE - org.ziptie.credentials.Credential.value is dirty 01:52:13,456 [tFlushEntityEventListener] [Jetty-1 ] TRACE - Updating entity: org.ziptie.credentials.Credential#5 01:52:13,456 [ractFlushingEventListener] [Jetty-1 ] TRACE - Processing unreferenced collections 01:52:13,457 [ractFlushingEventListener] [Jetty-1 ] TRACE - Scheduling collection removes/(re)creates/updates 01:52:13,457 [ractFlushingEventListener] [Jetty-1 ] DEBUG - Flushed: 0 insertions, 1 updates, 0 deletions to 11 objects 01:52:13,457 [ractFlushingEventListener] [Jetty-1 ] DEBUG - Flushed: 0 (re)creations, 2 updates, 0 removals to 2 collections 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - listing entities: 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=7, name=username, value=} 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=8, name=snmpPrivPassword, value=} 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=5, name=password, value=dar} 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=6, name=enablePassword, value=dar} 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=3, name=snmpUsername, value=} 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=4, name=snmpAuthPassword, value=} 01:52:13,457 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=1, name=roCommunityString, value=public} 01:52:13,458 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=2, name=rwCommunityString, value=private} 01:52:13,458 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.CredentialConfig{id=1, priority=-1, managedNetwork=Default, name=Default, credentialSets=[org.ziptie.credentials.CredentialSet#1], addresses=} 01:52:13,458 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.Credential{id=9, name=enableUsername, value=} 01:52:13,458 [Printer ] [Jetty-1 ] DEBUG - org.ziptie.credentials.CredentialSet{id=1, priority=1, name=default set, credentials=[org.ziptie.credentials.Credential#3, org.ziptie.credentials.Credential#6, org.ziptie.credentials.Credential#1, org.ziptie.credentials.Credential#4, org.ziptie.credentials.Credential#2, org.ziptie.credentials.Credential#5, org.ziptie.credentials.Credential#7, org.ziptie.credentials.Credential#8, org.ziptie.credentials.Credential#9]} 01:52:13,458 [ractFlushingEventListener] [Jetty-1 ] TRACE - executing flush 01:52:13,458 [ConnectionManager ] [Jetty-1 ] TRACE - registering flush begin 01:52:13,458 [AbstractEntityPersister ] [Jetty-1 ] TRACE - Updating entity: org.ziptie.credentials.Credential#5 01:52:13,458 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 01:52:13,458 [ConnectionManager ] [Jetty-1 ] DEBUG - opening JDBC connection 01:52:13,459 [SQL ] [Jetty-1 ] DEBUG - update creds set credentialName=?, credentialValue=? where id=? Hibernate: update creds set credentialName=?, credentialValue=? where id=? 01:52:13,459 [AbstractBatcher ] [Jetty-1 ] TRACE - preparing statement 01:52:13,459 [AbstractEntityPersister ] [Jetty-1 ] TRACE - Dehydrating entity: org.ziptie.credentials.Credential#5 01:52:13,460 [AbstractBatcher ] [Jetty-1 ] DEBUG - Executing batch size: 1 01:52:13,462 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 01:52:13,463 [AbstractBatcher ] [Jetty-1 ] TRACE - closing statement 01:52:13,463 [ConnectionManager ] [Jetty-1 ] DEBUG - skipping aggressive-release due to flush cycle 01:52:13,463 [stractCollectionPersister] [Jetty-1 ] DEBUG - Inserting rows of collection: org.ziptie.credentials.CredentialConfig.credentialSets#1 01:52:13,463 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 01:52:13,464 [SQL ] [Jetty-1 ] DEBUG - update cred_set set fkCredentialConfigId=? where id=? Hibernate: update cred_set set fkCredentialConfigId=? where id=? 01:52:13,464 [AbstractBatcher ] [Jetty-1 ] TRACE - preparing statement 01:52:13,464 [stractCollectionPersister] [Jetty-1 ] DEBUG - done inserting rows: 1 inserted 01:52:13,465 [stractCollectionPersister] [Jetty-1 ] DEBUG - Inserting rows of collection: org.ziptie.credentials.CredentialSet.credentials#1 01:52:13,466 [AbstractBatcher ] [Jetty-1 ] DEBUG - Executing batch size: 1 01:52:13,468 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 01:52:13,468 [AbstractBatcher ] [Jetty-1 ] TRACE - closing statement 01:52:13,468 [ConnectionManager ] [Jetty-1 ] DEBUG - skipping aggressive-release due to flush cycle 01:52:13,468 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 01:52:13,468 [SQL ] [Jetty-1 ] DEBUG - update creds set fkCredentialSetId=? where id=? Hibernate: update creds set fkCredentialSetId=? where id=? 01:52:13,468 [AbstractBatcher ] [Jetty-1 ] TRACE - preparing statement 01:52:13,469 [stractCollectionPersister] [Jetty-1 ] DEBUG - done inserting rows: 1 inserted 01:52:13,470 [AbstractBatcher ] [Jetty-1 ] DEBUG - Executing batch size: 1 01:52:13,471 [AbstractBatcher ] [Jetty-1 ] DEBUG - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 01:52:13,472 [AbstractBatcher ] [Jetty-1 ] TRACE - closing statement 01:52:13,472 [ConnectionManager ] [Jetty-1 ] DEBUG - skipping aggressive-release due to flush cycle 01:52:13,472 [ConnectionManager ] [Jetty-1 ] TRACE - registering flush end 01:52:13,472 [ConnectionManager ] [Jetty-1 ] DEBUG - aggressively releasing JDBC connection 01:52:13,472 [ConnectionManager ] [Jetty-1 ] DEBUG - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 01:52:13,472 [ractFlushingEventListener] [Jetty-1 ] TRACE - post flush 01:52:13,472 [JDBCContext ] [Jetty-1 ] TRACE - before transaction completion 01:52:13,472 [SessionImpl ] [Jetty-1 ] TRACE - before transaction completion 01:52:13,472 [EhcacheXAResourceImpl ] [Jetty-1 ] DEBUG - xaResource.end called for Txn with flag: TMSUCCESS and id: a Bitronix XID [6E65746C642D31000001289483025E00000131 : 6E65746C642D31000001289483026800000133] 01:52:13,475 [EhcacheXAResourceImpl ] [XA-Request processor Thread Xid [ a Bitronix XID [6E65746C642D31000001289483025E00000131 : 6E65746C642D31000001289483026800000133] ]] DEBUG - xaResource.prepare called for Txn with id: a Bitronix XID [6E65746C642D31000001289483025E00000131 : 6E65746C642D31000001289483026800000133] 01:52:13,483 [EhcacheXAResourceImpl ] [XA-Request processor Thread Xid [ a Bitronix XID [6E65746C642D31000001289483025E00000131 : 6E65746C642D31000001289483026800000133] ]] DEBUG - xaResource.commit called for Txn with phase: twoPhase and id: a Bitronix XID [6E65746C642D31000001289483025E00000131 : 6E65746C642D31000001289483026800000133] 01:52:13,486 [CacheSynchronization ] [Jetty-1 ] TRACE - transaction after completion callback, status: 3 01:52:13,486 [JDBCContext ] [Jetty-1 ] TRACE - after transaction completion 01:52:13,486 [SessionImpl ] [Jetty-1 ] TRACE - after transaction completion 01:52:13,486 [ActionQueue ] [Jetty-1 ] ERROR - could not release a cache lock org.hibernate.cache.CacheException: java.lang.IllegalStateException: transaction started or finished 2PC, cannot enlist any more resource at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.clear(EhcacheTransactionalDataRegion.java:138) at net.sf.ehcache.hibernate.strategy.AbstractEhcacheAccessStrategy.unlockRegion(AbstractEhcacheAccessStrategy.java:89) at org.hibernate.action.BulkOperationCleanupAction$EntityCleanup.release(BulkOperationCleanupAction.java:214) at org.hibernate.action.BulkOperationCleanupAction$EntityCleanup.access$300(BulkOperationCleanupAction.java:203) at org.hibernate.action.BulkOperationCleanupAction$1.doAfterTransactionCompletion(BulkOperationCleanupAction.java:183) at org.hibernate.engine.ActionQueue$AfterTransactionCompletionProcessQueue.afterTransactionCompletion(ActionQueue.java:577) at org.hibernate.engine.ActionQueue.afterTransactionCompletion(ActionQueue.java:204) at org.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:594) at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:252) at org.hibernate.transaction.CacheSynchronization.afterCompletion(CacheSynchronization.java:117) at bitronix.tm.BitronixTransaction.fireAfterCompletionEvent(BitronixTransaction.java:417) at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:191) at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:103) at org.ziptie.zap.jta.TransactionElf.commit(TransactionElf.java:53) at org.ziptie.server.web.ZTransactionFilter.doFilter(ZTransactionFilter.java:71) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at org.ziptie.server.security.ZSecurityFilter.doFilter(ZSecurityFilter.java:62) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at org.ziptie.zap.metro.ZThreadContextFilter.doFilter(ZThreadContextFilter.java:34) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388) at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) at org.ziptie.zap.web.internal.ZContext.handle(ZContext.java:133) at org.ziptie.zap.web.ZSessionHandler.handle(ZSessionHandler.java:99) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230) at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:326) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:938) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:755) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451) Caused by: java.lang.IllegalStateException: transaction started or finished 2PC, cannot enlist any more resource at bitronix.tm.BitronixTransaction.enlistResource(BitronixTransaction.java:62) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.createTransactionContext(EhcacheXAResourceImpl.java:529) at net.sf.ehcache.store.XATransactionalStore.getOrCreateTransactionContext(XATransactionalStore.java:514) at net.sf.ehcache.store.XATransactionalStore.removeAll(XATransactionalStore.java:204) at net.sf.ehcache.Cache.removeAll(Cache.java:1961) at net.sf.ehcache.Cache.removeAll(Cache.java:1946) at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.clear(EhcacheTransactionalDataRegion.java:136) … 36 more 01:52:13,488 [JDBCContext ] [Jetty-1 ] TRACE - TransactionFactory reported no active transaction; Synchronization not registered 01:52:13,488 [JDBCContext ] [Jetty-1 ] TRACE - TransactionFactory reported no active transaction; Synchronization not registered 01:52:13,488 [JDBCContext ] [Jetty-1 ] TRACE - TransactionFactory reported no active transaction; Synchronization not registered 01:52:13,488 [CacheSynchronization ] [Jetty-1 ] TRACE - automatically closing session 01:52:13,488 [SessionImpl ] [Jetty-1 ] TRACE - automatically closing session 01:52:13,488 [SessionImpl ] [Jetty-1 ] TRACE - closing session 01:52:13,488 [ConnectionManager ] [Jetty-1 ] TRACE - connection already null in cleanup : no action

Ludovic Orban 2010-12-14

This error is due to Hibernate’s way of updating its org.hibernate.cache.UpdateTimestampsCache cache: this cache cannot participate in XA transactions and should not be marked with transactionalMode=”xa”.

The doc should probably be more explicit about this.

ilevy 2010-12-14

fixed in 3.4.0 source.