NPE when using Ehcache with XA (bitronix)

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

Assignee: lorban
Reporter: brettw
Created: April 26, 2010
Votes: 0
Watchers: 0
Updated:
July 27, 2012
Resolved:
May 03, 2010

Description

Recently configured Ehcache to be used with Hibernate in a standalone deployment with Bitronix JTA manager. I received this exception doing seeming normal operations.

NPE is a possible cascade failure from here:

Caused by: net.sf.ehcache.transaction.xa.EhcacheXAException: could not lock all required entries in oldVersionStore at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.tryLockingKeysRequiredForPrepare(EhcacheXAResourceImpl.java:231)

Full stack trace follows:

16:55:53,264 [Committer ] [Running-6 (10.0.0.203@Default)] WARN - resource ‘credentials@__DEFAULT__.cacheManager’ reported XAER_RMERR when asked to commit transaction branch. Transaction is prepared and will commit via recovery service when resource availability allows. net.sf.ehcache.transaction.xa.EhcacheXAException: java.lang.NullPointerException at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor.process(TransactionXARequestProcessor.java:74) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.commit(EhcacheXAResourceImpl.java:323) at bitronix.tm.twopc.Committer$CommitJob.commitResource(Committer.java:175) at bitronix.tm.twopc.Committer$CommitJob.run(Committer.java:164) at bitronix.tm.twopc.executor.SyncExecutor.submit(SyncExecutor.java:12) at bitronix.tm.twopc.AbstractPhaseEngine.runJobsForPosition(AbstractPhaseEngine.java:109) at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:71) at bitronix.tm.twopc.Committer.commit(Committer.java:63) at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:186) at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:103) at org.ziptie.zap.jta.TransactionElf.commit(TransactionElf.java:53) at org.ziptie.server.job.AbstractAdapterTask.execute(AbstractAdapterTask.java:106) at org.ziptie.server.dispatcher.Operation.execute(Operation.java:100) at org.ziptie.server.dispatcher.OperationExecutor$JobThread.runJob(OperationExecutor.java:684) at org.ziptie.server.dispatcher.OperationExecutor$JobThread.run(OperationExecutor.java:561) Caused by: java.util.concurrent.ExecutionException: java.lang.NullPointerException at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222) at java.util.concurrent.FutureTask.get(FutureTask.java:83) at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor.process(TransactionXARequestProcessor.java:68) … 14 more Caused by: java.lang.NullPointerException at net.sf.ehcache.transaction.xa.EhcacheXAStoreImpl$Version.checkinWrite(EhcacheXAStoreImpl.java:296) at net.sf.ehcache.transaction.xa.EhcacheXAStoreImpl$VersionTable.checkin(EhcacheXAStoreImpl.java:218) at net.sf.ehcache.transaction.xa.EhcacheXAStoreImpl.checkin(EhcacheXAStoreImpl.java:86) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.potentiallyCheckin(EhcacheXAResourceImpl.java:386) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.commitInternal(EhcacheXAResourceImpl.java:355) at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor$XARequestCallable.call(TransactionXARequestProcessor.java:188) at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor$XARequestCallable.call(TransactionXARequestProcessor.java:152) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:637) 16:56:12,609 [AbstractPhaseEngine ] [Running-6 (10.0.0.203@Default)] ERROR - resource credentials@__DEFAULT__.cacheManager failed on a Bitronix XID [6E65746C642D3100000128391D7C33000004FD : 6E65746C642D3100000128391D8D140000052B] net.sf.ehcache.transaction.xa.EhcacheXAException: XA request on [a Bitronix XID [6E65746C642D3100000128391D7C33000004FD : 6E65746C642D3100000128391D8D140000052B]] failed at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor.process(TransactionXARequestProcessor.java:78) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.prepare(EhcacheXAResourceImpl.java:170) at bitronix.tm.twopc.Preparer$PrepareJob.run(Preparer.java:134) at bitronix.tm.twopc.executor.SyncExecutor.submit(SyncExecutor.java:12) at bitronix.tm.twopc.AbstractPhaseEngine.runJobsForPosition(AbstractPhaseEngine.java:109) at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:71) at bitronix.tm.twopc.Preparer.prepare(Preparer.java:68) at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:172) at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:103) at org.ziptie.zap.jta.TransactionElf.commit(TransactionElf.java:53) at org.ziptie.server.job.backup.BackupTask.performTask(BackupTask.java:133) at org.ziptie.server.job.AbstractAdapterTask.execute(AbstractAdapterTask.java:132) at org.ziptie.server.dispatcher.Operation.execute(Operation.java:100) at org.ziptie.server.dispatcher.OperationExecutor$JobThread.runJob(OperationExecutor.java:684) at org.ziptie.server.dispatcher.OperationExecutor$JobThread.run(OperationExecutor.java:561) Caused by: net.sf.ehcache.transaction.xa.EhcacheXAException: could not lock all required entries in oldVersionStore at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.tryLockingKeysRequiredForPrepare(EhcacheXAResourceImpl.java:231) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.prepareInternal(EhcacheXAResourceImpl.java:190) at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor$XARequestCallable.call(TransactionXARequestProcessor.java:180) at net.sf.ehcache.transaction.xa.TransactionXARequestProcessor$XARequestCallable.call(TransactionXARequestProcessor.java:152) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:637) Caused by: net.sf.ehcache.concurrent.LocksAcquisitionException: could not acquire all locks in 15000 ms at net.sf.ehcache.store.compound.CompoundStore$LockProvider.getAndWriteLockAllSyncForKeys(CompoundStore.java:577) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.tryLockingKeysRequiredForPrepare(EhcacheXAResourceImpl.java:229) … 8 more 16:56:12,655 [TransactionElf ] [Running-6 (10.0.0.203@Default)] WARN - Transaction commit failed. bitronix.tm.internal.BitronixRollbackException: transaction failed to prepare: a Bitronix Transaction with GTRID [6E65746C642D3100000128391D7C33000004FD], status=ROLLEDBACK, 2 resource(s) enlisted (started Mon Apr 26 07:55:53 GMT+00:00 2010) at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:180) at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:103) at org.ziptie.zap.jta.TransactionElf.commit(TransactionElf.java:53) at org.ziptie.server.job.backup.BackupTask.performTask(BackupTask.java:133) at org.ziptie.server.job.AbstractAdapterTask.execute(AbstractAdapterTask.java:132) at org.ziptie.server.dispatcher.Operation.execute(Operation.java:100) at org.ziptie.server.dispatcher.OperationExecutor$JobThread.runJob(OperationExecutor.java:684) at org.ziptie.server.dispatcher.OperationExecutor$JobThread.run(OperationExecutor.java:561) Caused by: bitronix.tm.internal.BitronixRollbackException: transaction failed during prepare of a Bitronix Transaction with GTRID [6E65746C642D3100000128391D7C33000004FD], status=PREPARING, 2 resource(s) enlisted (started Mon Apr 26 07:55:53 GMT+00:00 2010): resource(s) [credentials@__DEFAULT__.cacheManager] threw unexpected exception at bitronix.tm.twopc.Preparer.throwException(Preparer.java:110) at bitronix.tm.twopc.Preparer.prepare(Preparer.java:71) at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:172) … 7 more Caused by: bitronix.tm.twopc.PhaseException: collected 1 exception(s): [credentials@__DEFAULT__.cacheManager - net.sf.ehcache.transaction.xa.EhcacheXAException(XA_RBDEADLOCK) - XA request on [a Bitronix XID [6E65746C642D3100000128391D7C33000004FD : 6E65746C642D3100000128391D8D140000052B]] failed] at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:90) at bitronix.tm.twopc.Preparer.prepare(Preparer.java:68) … 8 more

Comments

Brett Wooldridge 2010-04-26

I would note that this set of transactions normally (without Ehcache) takes only several milliseconds to complete … so I can only surmise that the timeout, if that is the cause, is some sort of deadlock/lock-acquisition issue.

Brett Wooldridge 2010-04-26

LOL, Ludovic I had no idea this would get assigned to you! You’re a busy guy.

Alexander Snaps 2010-04-26

I fixed that NPE in the head of trunk last week already… The real problem here remains though :(

Ludovic Orban 2010-04-26

Alex: if by the ‘real problem’ you mean the XAException(XA_RBDEADLOCK) I think it happens because the NPE bypassed the unlockWriteLockForAllKeys() method call so the locks stay locked forever. Fixing the NPE solves that too.

Ludovic Orban 2010-05-03

Should be fixed.

Brett Wooldridge 2010-05-13

I don’t know if it’s the same bug, but I’m getting the following NPE using the latest nightly (terracotta-trunk-nightly-rev15210):

16:37:14,294 [BitronixTransaction ] [Jetty-1 ] WARN - Synchronization.afterCompletion() call failed for net.sf.ehcache.hibernate.tm.TransactionSynchronization@2714c598 java.lang.RuntimeException: java.lang.NullPointerException at net.sf.ehcache.hibernate.tm.TransactionSynchronization.afterCompletion(TransactionSynchronization.java:52) 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.NullPointerException at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.potentiallyCheckin(EhcacheXAResourceImpl.java:639) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.onePhaseCommit(EhcacheXAResourceImpl.java:622) at net.sf.ehcache.transaction.xa.EhcacheXAResourceImpl.commit(EhcacheXAResourceImpl.java:371) at net.sf.ehcache.hibernate.tm.SyncTransaction.commit(SyncTransaction.java:70) at net.sf.ehcache.hibernate.tm.TransactionSynchronization.afterCompletion(TransactionSynchronization.java:50) … 27 more

If it’s the same bug, pls re-open. I can’t find an option to re-open a bug.

Ludovic Orban 2010-05-13

It’s a new bug, introduced by H2LC 1PC optimization.

As a workaround the optimization can be disabled by setting this property in your Hibernate config: net.sf.ehcache.xa.useOnePhaseSynchronization=false

Brett Wooldridge 2010-05-13

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

Nitin Rana 2010-06-29

Ludovic, can you comment one the latest finding of Brett?

Ludovic Orban 2010-06-29

Hibernate seems to do something very silly here: 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.

Fiona OShea 2010-06-29

I’ve created a new Jira EHC-745 to track this.