1 Reply Latest reply on Oct 14, 2009 11:51 AM by Srini c

    bulkUpdate -  could not release cache lock

    Srini c Newbie

      Hi,
      We are using Hibernate-3.3.2 and JBossCache-3.1.0. We are running into issues on bulk update, the operation runs longer time trying, to acquire locks on the nodes. The issue happens only in Websphere 6.1 and now issues with the bulk update in JBoss.

      1. The hibernate session is flushed on the transaction synchronization
      ( Flushing Hibernate Session on transaction synchronization)
      2. Acquiring write locks on all nodes (commit is issued, prepare phase is entered which locks all the nodes in the workspace and validates that all changes can be applied to the cache itself).
      3. Acquired write locks on nodes. Validating nodes completed (example: Validating 74 nodes).
      4. If nodes are validated then a commit is invoked - this applies the changes and unlocks all the locks acquired in the prepare. (I guess this is where we are running into issues, the locks are not freed up on successful validation. )
      5. RemoveNodeCommand is Issued. (This happens in a separate transaction; created new GTX: GlobalTransaction:<10.10.21.72:33898>:6849)
      6. Acquiring lock failure from item 5 above with below message
      (failure acquiring lock: fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY
      caller=GlobalTransaction:<10.10.21.72:33898>:6849, lock=write owner=GlobalTransaction:<10.10.21.72:33898>:6847)
      8. There are several tries to acquire locks on several nodes above on the RemoveNodeCommad for at least, 10 minutes
      9. Original transaction started is commited
      (calling aftercompletion for GlobalTransaction:<10.10.21.72:33898>:6847
      Running commit phase. One phase? False
      Running commit for GlobalTransaction:<10.10.21.72:33898>:6847
      Commiting successfully validated changes for GlobalTransaction GlobalTransaction:<10.10.21.72:33898>:6847
      10.The write locks are released (after the transaction complete) finally.


      Below are the logs.

      DEBUG 1179976 [WebContainer : 2] (org.hibernate.SQL) 2009-10-08 09:52:29,775 - delete from BILL_OF_WORK where BILL_OF_WORK_ID=?
      DEBUG 1180035 [WebContainer : 2] (org.springframework.orm.hibernate3.HibernateTemplate) 2009-10-08 09:52:29,834 - Not closing pre-bound Hibernate Session after HibernateTemplate
      DEBUG 1180038 [WebContainer : 2] (org.springframework.orm.hibernate3.SessionFactoryUtils) 2009-10-08 09:52:29,837 - Flushing Hibernate Session on transaction synchronization
      TRACE 1180044 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,843 - Running beforeCompletion on gtx GlobalTransaction:<10.10.21.72:33898>:6847


      DEBUG 1180045 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticLockingInterceptor) 2009-10-08 09:52:29,844 - Locking nodes in transaction workspace for GlobalTransaction GlobalTransaction:<10.10.21.72:33898>:6847


      (org.jboss.cache.lock.IdentityLock) 2009-10-08 09:52:29,853 - acquiring WL: fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, caller=GlobalTransaction:<10.10.21.72:33898>:6847, lock=
      TRACE 1180054 [WebContainer : 2] (org.jboss.cache.lock.IdentityLock) 2009-10-08 09:52:29,853 - acquired WL: fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, caller=GlobalTransaction:<10.10.21.72:33898>:6847, lock=write owner=GlobalTransaction:<10.10.21.72:33898>:6847
      TRACE 1180054 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticLockingInterceptor) 2009-10-08 09:52:29,853 - Acquired lock on node /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY
      TRACE 1180053 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticLockingInterceptor) 2009-10-08 09:52:29,852 - Acquired lock on node /

      DEBUG 1180064 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 09:52:29,863 - Validating 74 nodes.
      (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 09:52:29,864 - Node [/fleetcycle/domain/billing/invoicing/InvoiceStatus] doesn't need validating as it isn't dirty
      TRACE 1180067 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 09:52:29,866 - Validating version for node [/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY]
      TRACE 1180067 [WebContainer : 2] (org.jboss.cache.DataContainerImpl) 2009-10-08 09:52:29,866 - peek /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, includeDeletedNodes:true, includeInvalidNodes:true

      DEBUG 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 09:52:29,867 - Successfully validated nodes

      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.CallInterceptor) 2009-10-08 09:52:29,867 - Suppressing invocation of method handleOptimisticPrepareCommand.
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Setting up transactional context.
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Setting tx as null and gtx as null
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Running beforeCompletion on gtx GlobalTransaction:<10.10.21.72:33898>:6848
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Setting up transactional context.
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Setting tx as com.ibm.ws.Transaction.JTA.TransactionImpl@45bb45bb#tid=7417 and gtx as GlobalTransaction:<10.10.21.72:33898>:6848
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.factories.ComponentRegistry) 2009-10-08 09:52:29,867 - Testing if invocations are allowed.
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Setting up transactional context.
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - Setting tx as com.ibm.ws.Transaction.JTA.TransactionImpl@45bb45bb#tid=7417 and gtx as GlobalTransaction:<10.10.21.72:33898>:6848
      TRACE 1180068 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,867 - No modifications in this tx. Skipping beforeCompletion()
      TRACE 1180070 [WebContainer : 2] (org.jboss.cache.factories.ComponentRegistry) 2009-10-08 09:52:29,869 - Testing if invocations are allowed.
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.InvocationContextInterceptor) 2009-10-08 09:52:29,870 - Invoked with command RemoveNodeCommand{fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=org.hibernate.cache.jbc2.util.NonLockingDataVersion@230b230b, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=true, bypassUnmarshalling=false}]
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.InvocationContextInterceptor) 2009-10-08 09:52:29,870 - Setting up transactional context.
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.InvocationContextInterceptor) 2009-10-08 09:52:29,870 - Setting tx as null and gtx as null
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,870 - Creating transaction for thread Thread[WebContainer : 2,5,main]
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,870 - local transaction exists - registering global tx if not present for Thread[WebContainer : 2,5,main]
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,870 - Associated gtx in txTable is null
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.transaction.TransactionTable) 2009-10-08 09:52:29,870 - created new GTX: GlobalTransaction:<10.10.21.72:33898>:6849, local TX=com.ibm.ws.Transaction.JTA.TransactionImpl@617e617e#tid=7418
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,870 - Registering sync handler for tx com.ibm.ws.Transaction.JTA.TransactionImpl@617e617e#tid=7418, gtx GlobalTransaction:<10.10.21.72:33898>:6849
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:29,870 - registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<10.10.21.72:33898>:6849, tx=com.ibm.ws.Transaction.JTA.TransactionImpl@1635672446))
      TRACE 1180071 [WebContainer : 2] (org.jboss.cache.DataContainerImpl) 2009-10-08 09:52:29,870 - peek /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, includeDeletedNodes:true, includeInvalidNodes:true
      TRACE 1180072 [WebContainer : 2] (org.jboss.cache.lock.IdentityLock) 2009-10-08 09:52:29,871 - acquiring RL: fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, caller=GlobalTransaction:<10.10.21.72:33898>:6849, lock=write owner=GlobalTransaction:<10.10.21.72:33898>:6847

      TRACE 1195074 [WebContainer : 2] (org.jboss.cache.lock.IdentityLock) 2009-10-08 09:52:44,873 - read lock for /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY could not be acquired by GlobalTransaction:<10.10.21.72:33898>:6849 after 15000 ms. Locks: Read lock owners: []
      Write lock owner: GlobalTransaction:<10.10.21.72:33898>:6847
      , lock info: write owner=GlobalTransaction:<10.10.21.72:33898>:6847 (activeReaders=0, activeWriter=Thread[WebContainer : 2,5,main], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
      TRACE 1195075 [WebContainer : 2] (org.jboss.cache.lock.IdentityLock) 2009-10-08 09:52:44,874 - failure acquiring lock: fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, caller=GlobalTransaction:<10.10.21.72:33898>:6849, lock=write owner=GlobalTransaction:<10.10.21.72:33898>:6847 (activeReaders=0, activeWriter=Thread[WebContainer : 2,5,main], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
      WARN 1195075 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 09:52:44,874 - Rolling back, exception encountered
      org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY, caller=GlobalTransaction:<10.10.21.72:33898>:6849, lock=write owner=GlobalTransaction:<10.10.21.72:33898>:6847 (activeReaders=0, activeWriter=Thread[WebContainer : 2,5,main], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
      at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:534)
      at org.jboss.cache.lock.NodeBasedLockManager.acquireLock(NodeBasedLockManager.java:87)
      at org.jboss.cache.lock.NodeBasedLockManager.lock(NodeBasedLockManager.java:117)
      at org.jboss.cache.interceptors.OptimisticInterceptor.lockAndCreateWorkspaceNode(OptimisticInterceptor.java:134)
      at org.jboss.cache.interceptors.OptimisticNodeInterceptor.fetchWorkspaceNode(OptimisticNodeInterceptor.java:583)
      at org.jboss.cache.interceptors.OptimisticNodeInterceptor.visitRemoveNodeCommand(OptimisticNodeInterceptor.java:103)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.EvictionInterceptor.visitRemoveNodeCommand(EvictionInterceptor.java:223)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
      at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
      at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
      at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.InvalidationInterceptor.handleWriteMethod(InvalidationInterceptor.java:241)
      at org.jboss.cache.interceptors.InvalidationInterceptor.visitRemoveNodeCommand(InvalidationInterceptor.java:125)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
      at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.TxInterceptor.attachGtxAndPassUpChain(TxInterceptor.java:301)
      at org.jboss.cache.interceptors.OptimisticTxInterceptor.handleDefault(OptimisticTxInterceptor.java:83)
      at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
      at org.jboss.cache.commands.AbstractVisitor.visitRemoveNodeCommand(AbstractVisitor.java:75)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
      at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
      at org.jboss.cache.interceptors.InvocationContextInterceptor.visitRemoveNodeCommand(InvocationContextInterceptor.java:88)
      at org.jboss.cache.commands.write.RemoveNodeCommand.acceptVisitor(RemoveNodeCommand.java:125)
      at org.jboss.cache.interceptors.InterceptorChain.invoke(InterceptorChain.java:287)
      at org.jboss.cache.invocation.CacheInvocationDelegate.removeNode(CacheInvocationDelegate.java:478)
      at org.hibernate.cache.jbc2.util.CacheHelper.removeAll(CacheHelper.java:378)
      at org.hibernate.cache.jbc2.access.OptimisticTransactionalAccessDelegate.evictOrRemoveAll(OptimisticTransactionalAccessDelegate.java:172)
      at org.hibernate.cache.jbc2.access.OptimisticTransactionalAccessDelegate.evictAll(OptimisticTransactionalAccessDelegate.java:80)
      at org.hibernate.cache.jbc2.entity.TransactionalAccess.evictAll(TransactionalAccess.java:102)
      at org.hibernate.impl.SessionFactoryImpl.evictEntity(SessionFactoryImpl.java:918)
      at org.hibernate.action.BulkOperationCleanupAction.evictEntityRegions(BulkOperationCleanupAction.java:153)
      at org.hibernate.action.BulkOperationCleanupAction.afterTransactionCompletion(BulkOperationCleanupAction.java:132)
      at org.hibernate.engine.ActionQueue.afterTransactionCompletion(ActionQueue.java:198)
      at org.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:452)
      at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:252)
      at org.hibernate.transaction.CacheSynchronization.afterCompletion(CacheSynchronization.java:117)
      at com.ibm.ws.Transaction.JTA.RegisteredSyncs.distributeAfter(RegisteredSyncs.java:424)
      at com.ibm.ws.Transaction.JTA.TransactionImpl.distributeAfter(TransactionImpl.java:3885)
      at com.ibm.ws.Transaction.JTA.TransactionImpl.postCompletion(TransactionImpl.java:3864)
      at com.ibm.ws.Transaction.JTA.TransactionImpl.commitXAResources(TransactionImpl.java:2521)
      at com.ibm.ws.Transaction.JTA.TransactionImpl.stage1CommitProcessing(TransactionImpl.java:1647)
      at com.ibm.ws.Transaction.JTA.TransactionImpl.processCommit(TransactionImpl.java:1607)
      at com.ibm.ws.Transaction.JTA.TransactionImpl.commit(TransactionImpl.java:1542)
      at com.ibm.ws.Transaction.JTA.TranManagerImpl.commit(TranManagerImpl.java:240)
      at com.ibm.ws.Transaction.JTA.TranManagerSet.commit(TranManagerSet.java:164)
      at com.ibm.ws.Transaction.JTA.UserTransactionImpl.commit(UserTransactionImpl.java:292)
      at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:842)
      at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:662)
      at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:632)
      at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:139)
      at fleetcycle.services.framework.execution.interceptors.TransactionInterceptor.doInTransactionTemplate(TransactionInterceptor.java:114)
      at fleetcycle.services.framework.execution.interceptors.TransactionInterceptor.invoke(TransactionInterceptor.java:86)
      at sun.reflect.GeneratedMethodAccessor1147.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:618)
      at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:172)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:139)
      at fleetcycle.model.framework.persistence.TransactionRetryInterceptor.invoke(TransactionRetryInterceptor.java:95)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
      at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      at $Proxy191.invoke(Unknown Source)
      at fleetcycle.services.framework.execution.interceptors.SecurityInterceptor.invoke(SecurityInterceptor.java:29)
      at fleetcycle.services.framework.execution.ExecutionEntryTask.doTask(ExecutionEntryTask.java:98)
      at fleetcycle.services.framework.execution.ExecutionEntry.executeWorkflow(ExecutionEntry.java:105)
      at fleetcycle.services.framework.execution.ExecutionEntryWorkflowImpl.invokeWorkflow(ExecutionEntryWorkflowImpl.java:89)
      at sun.reflect.GeneratedMethodAccessor1146.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:618)
      at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:172)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:139)
      at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:104)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
      at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      at $Proxy192.invokeWorkflow(Unknown Source)
      at fleetcycle.services.framework.execution.ServiceExecutor$2.doInCacheBlock(ServiceExecutor.java:225)
      at fleetcycle.services.framework.execution.cache.CacheTemplate.invoke(CacheTemplate.java:93)
      at fleetcycle.services.framework.execution.ServiceExecutor.process(ServiceExecutor.java:230)
      at fleetcycle.services.framework.execution.ServiceExecutor.access$000(ServiceExecutor.java:33)
      at fleetcycle.services.framework.execution.ServiceExecutor$1.doInWorkflowContext(ServiceExecutor.java:102)
      at fleetcycle.services.framework.execution.WorkflowContextTemplate.execute(WorkflowContextTemplate.java:26)
      at fleetcycle.services.framework.execution.ServiceExecutor.execute(ServiceExecutor.java:99)
      at sun.reflect.GeneratedMethodAccessor1281.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:618)
      at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:172)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:139)
      at fleetcycle.services.framework.audit.intercept.ApplicationExceptionAuditingInterceptor.invoke(ApplicationExceptionAuditingInterceptor.java:34)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
      at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      at $Proxy193.execute(Unknown Source)
      at fleetcycle.ui.framework.actions.AbstractFleetCycleAction.callExecutionEntry(AbstractFleetCycleAction.java:245)
      at fleetcycle.ui.framework.actions.ServiceExecutorAction.execute(ServiceExecutorAction.java:169)
      at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
      at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
      at fleetcycle.ui.framework.actions.FleetCycleRequestProcessor.process(FleetCycleRequestProcessor.java:109)
      at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
      at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:507)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:743)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
      at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1068)
      at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1009)
      at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:145)
      at fleetcycle.util.common.UserDetailsFilter.doFilterInternal(UserDetailsFilter.java:44)
      at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:75)
      at org.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:98)
      at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:190)
      at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:130)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:265)
      at org.acegisecurity.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:107)
      at org.acegisecurity.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:72)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
      at org.acegisecurity.ui.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:110)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
      at fleetcycle.ui.framework.security.AbstractAuthenticationFilter.doFilterInternal(AbstractAuthenticationFilter.java:144)
      at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:75)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
      at org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:229)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
      at org.acegisecurity.ui.logout.LogoutFilter.doFilter(LogoutFilter.java:106)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
      at org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:286)
      at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
      at org.acegisecurity.util.FilterChainProxy.doFilter(FilterChainProxy.java:149)
      at org.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:98)
      at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:190)
      at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:130)
      at fleetcycle.ui.framework.actions.SessionFilter$1.doInWorkflowContext(SessionFilter.java:106)
      at fleetcycle.services.framework.execution.WorkflowContextTemplate.execute(WorkflowContextTemplate.java:26)
      at fleetcycle.ui.framework.actions.SessionFilter.doFilterInternal(SessionFilter.java:111)
      at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:75)
      at org.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:98)
      at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:190)
      at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:130)
      at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:198)
      at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:75)
      at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:190)
      at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:130)
      at com.ibm.ws.webcontainer.filter.WebAppFilterChain._doFilter(WebAppFilterChain.java:87)
      at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:771)
      at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:679)
      at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:539)
      at com.ibm.ws.wswebcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:478)
      at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:3357)
      at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:267)
      at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:811)
      at com.ibm.ws.wswebcontainer.WebContainer.handleRequest(WebContainer.java:1455)
      at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:115)
      at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:454)
      at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewInformation(HttpInboundLink.java:383)
      at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.ready(HttpInboundLink.java:263)
      at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:214)
      at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:113)
      at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)
      at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
      at com.ibm.io.async.AsyncChannelFuture$1.run(AsyncChannelFuture.java:205)
      at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1473)
      Caused by:
      org.jboss.cache.lock.TimeoutException: read lock for /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY could not be acquired by GlobalTransaction:<10.10.21.72:33898>:6849 after 15000 ms. Locks: Read lock owners: []
      Write lock owner: GlobalTransaction:<10.10.21.72:33898>:6847
      , lock info: write owner=GlobalTransaction:<10.10.21.72:33898>:6847 (activeReaders=0, activeWriter=Thread[WebContainer : 2,5,main], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
      at org.jboss.cache.lock.IdentityLock.acquireReadLock0(IdentityLock.java:332)
      at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:276)
      at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:499)
      ... 178 more



      TRACE 1782515 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,314 - Setting up transactional context.
      TRACE 1782515 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,314 - Setting tx as com.ibm.ws.Transaction.JTA.TransactionImpl@45bb45bb#tid=7417 and gtx as GlobalTransaction:<10.10.21.72:33898>:6847
      TRACE 1782515 [WebContainer : 2] (org.jboss.cache.factories.ComponentRegistry) 2009-10-08 10:02:32,314 - Testing if invocations are allowed.
      TRACE 1782515 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,314 - calling aftercompletion for GlobalTransaction:<10.10.21.72:33898>:6847
      TRACE 1782515 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,314 - Running commit phase. One phase? false
      TRACE 1782516 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,315 - Running commit for GlobalTransaction:<10.10.21.72:33898>:6847
      DEBUG 1782516 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 10:02:32,315 - Commiting successfully validated changes for GlobalTransaction GlobalTransaction:<10.10.21.72:33898>:6847

      TRACE 1782528 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 10:02:32,327 - Applying children deltas to parent node /fleetcycle/domain/billing/invoicing/InvoiceStatus
      TRACE 1782528 [WebContainer : 2] (org.jboss.cache.VersionedNode) 2009-10-08 10:02:32,327 - Marking node /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY as invalid

      TRACE 1782534 [WebContainer : 2] (org.jboss.cache.VersionedNode) 2009-10-08 10:02:32,333 - Marking node /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY as invalid
      TRACE 1782534 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 10:02:32,333 - Versioning is explicit; not attempting an increment.
      TRACE 1782534 [WebContainer : 2] (org.jboss.cache.interceptors.OptimisticValidatorInterceptor) 2009-10-08 10:02:32,333 - Setting version of node /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY from org.hibernate.cache.jbc2.util.NonLockingDataVersion@230b230b to org.hibernate.cache.jbc2.util.NonLockingDataVersion@230b230b

      TRACE 1782536 [WebContainer : 2] (org.jboss.cache.lock.NodeBasedLockManager) 2009-10-08 10:02:32,335 - releasing lock for /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY (write owner=GlobalTransaction:<10.10.21.72:33898>:6847), owner GlobalTransaction:<10.10.21.72:33898>:6847
      TRACE 1782540 [WebContainer : 2] (org.jboss.cache.lock.NodeBasedLockManager) 2009-10-08 10:02:32,339 - releasing lock for /fleetcycle/domain/billing/invoicing/InvoiceStatus (read owners=[GlobalTransaction:<10.10.21.72:33898>:6847]), owner GlobalTransaction:<10.10.21.72:33898>:6847


      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,503 - Setting up transactional context.
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.interceptors.OptimisticTxInterceptor) 2009-10-08 10:02:32,503 - Setting tx as null and gtx as null
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.interceptors.InvocationContextInterceptor) 2009-10-08 10:02:32,503 - Resetting invocation-scope options
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.commands.legacy.write.VersionedInvalidateCommand) 2009-10-08 10:02:32,503 - Invalidating fqn:/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.VersionedNode) 2009-10-08 10:02:32,503 - Marking node /fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY as invalid
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.interceptors.InvocationContextInterceptor) 2009-10-08 10:02:32,503 - Resetting invocation-scope options
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.marshall.CommandAwareRpcDispatcher) 2009-10-08 10:02:32,503 - Command : ReplicateCommand{cmds=OptimisticInvalidateCommand{dataVersion=org.hibernate.cache.jbc2.util.NonLockingDataVersion@42014201 ,fqn=/fleetcycle/domain/billing/invoicing/InvoiceStatus/ENTITY}} executed, result is: null
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.marshall.CacheMarshaller300) 2009-10-08 10:02:32,503 - Marshalling object null
      TRACE 1782704 [Multiplexer-1] (org.jboss.cache.marshall.CacheMarshaller300) 2009-10-08 10:02:32,503 - Done serializing object: null
      TRACE 1782705 [OOB-1,udp-legacy-fleetcycle,10.10.21.72:33898] (org.jboss.cache.marshall.CacheMarshaller300) 2009-10-08 10:02:32,504 - Unmarshalled object null
      TRACE 1782705 [WebContainer : 2] (org.jboss.cache.marshall.CommandAwareRpcDispatcher) 2009-10-08 10:02:32,504 - responses: [sender=10.10.21.72:33896, retval=null, received=true, suspected=false]