Uploaded image for project: 'JBoss Enterprise Application Platform 4 and 5'
  1. JBoss Enterprise Application Platform 4 and 5
  2. JBPAPP-9712 Regression in EAP 5.2 testsuite
  3. JBPAPP-9713

TimerCleanUpUnitTestCase fails randomly

    XMLWordPrintable

Details

    • Sub-task
    • Resolution: Done
    • Major
    • EAP_EWP 5.2.0 ER2
    • EAP_EWP 5.1.2
    • None
    • None
    • Not Required
    • NEW

    Description

      There are two test failures, probably those will deserve separate issues, but ATM it seems that there may be a single reason for both of them failing.

      testEntityBeanSingleTimerHasTimerServiceAfterExpirationInstPerTx:

      Error Message

EJBException:; nested exception is:   javax.ejb.EJBException: Timer is already set
Stacktrace

java.rmi.ServerException: EJBException:; nested exception is: 
	javax.ejb.EJBException: Timer is already set
	at org.jboss.ejb.plugins.LogInterceptor.handleException(LogInterceptor.java:365)
	at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:209)
	at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
	at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:533)
	at org.jboss.ejb.Container.invoke(Container.java:1092)
	at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
	at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
	at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
	at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
	at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
	at org.jboss.invocation.unified.server.UnifiedInvoker.invoke(UnifiedInvoker.java:232)
	at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:967)
	at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:791)
	at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:744)
	at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586)
	at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)
Caused by: javax.ejb.EJBException: Timer is already set
	at org.jboss.test.timer.ejb.TimerEntityBean.startSingleTimer(TimerEntityBean.java:89)
	at org.jboss.invocation.Invocation.performCall(Invocation.java:386)
	at org.jboss.ejb.EntityContainer$ContainerInterceptor.invoke(EntityContainer.java:1205)
	at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:284)
	at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:156)
	at org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:123)
	at org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:279)
	at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:104)
	at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:76)
	at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
	at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
	at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
	at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
	at org.jboss.ejb.plugins.SecurityInterceptor.process(SecurityInterceptor.java:281)
	at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:211)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.process(PreSecurityInterceptor.java:167)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.invoke(PreSecurityInterceptor.java:84)
	at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
	at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
	at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:533)
	at org.jboss.ejb.Container.invoke(Container.java:1092)
	at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
	at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
	at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
	at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
	at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
	at org.jboss.invocation.unified.server.UnifiedInvoker.invoke(UnifiedInvoker.java:232)
	at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:967)
	at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:791)
	at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:744)
	at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586)
	at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)
	at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:218)
	at org.jboss.remoting.Client.invoke(Client.java:2084)
	at org.jboss.remoting.Client.invoke(Client.java:879)
	at org.jboss.invocation.unified.interfaces.UnifiedInvokerProxy.invoke(UnifiedInvokerProxy.java:184)
	at org.jboss.invocation.InvokerInterceptor.invokeInvoker(InvokerInterceptor.java:416)
	at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:248)
	at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:61)
	at org.jboss.proxy.ejb.SecurityContextInterceptor.invoke(SecurityContextInterceptor.java:64)
	at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:68)
	at org.jboss.proxy.ejb.EntityInterceptor.invoke(EntityInterceptor.java:112)
	at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:101)
	at $Proxy3.startSingleTimer(Unknown Source)
	at org.jboss.test.timer.test.TimerCleanUpUnitTestCase.testEntityBeanSingleTimerHasTimerServiceAfterExpirationInstPerTx(TimerCleanUpUnitTestCase.java:127)
	at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
	at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
	at junit.extensions.TestSetup.run(TestSetup.java:25)

      testEntityBeanTimerHasTimerServiceAfterCancellationInstPerTx:

      Error Message

EJBException:; nested exception is:   javax.ejb.EJBException: Timer is not available
Stacktrace

java.rmi.ServerException: EJBException:; nested exception is: 
	javax.ejb.EJBException: Timer is not available
	at org.jboss.ejb.plugins.LogInterceptor.handleException(LogInterceptor.java:365)
	at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:209)
	at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
	at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:533)
	at org.jboss.ejb.Container.invoke(Container.java:1092)
	at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
	at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
	at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
	at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
	at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
	at org.jboss.invocation.unified.server.UnifiedInvoker.invoke(UnifiedInvoker.java:232)
	at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:967)
	at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:791)
	at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:744)
	at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586)
	at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)
Caused by: javax.ejb.EJBException: Timer is not available
	at org.jboss.test.timer.ejb.TimerEntityBean.stopTimer(TimerEntityBean.java:130)
	at org.jboss.invocation.Invocation.performCall(Invocation.java:386)
	at org.jboss.ejb.EntityContainer$ContainerInterceptor.invoke(EntityContainer.java:1205)
	at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:284)
	at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:156)
	at org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:123)
	at org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:279)
	at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:104)
	at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:76)
	at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
	at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
	at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
	at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
	at org.jboss.ejb.plugins.SecurityInterceptor.process(SecurityInterceptor.java:281)
	at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:211)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.process(PreSecurityInterceptor.java:167)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.invoke(PreSecurityInterceptor.java:84)
	at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
	at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
	at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:533)
	at org.jboss.ejb.Container.invoke(Container.java:1092)
	at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
	at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
	at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
	at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
	at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
	at org.jboss.invocation.unified.server.UnifiedInvoker.invoke(UnifiedInvoker.java:232)
	at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:967)
	at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:791)
	at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:744)
	at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586)
	at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)
	at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:218)
	at org.jboss.remoting.Client.invoke(Client.java:2084)
	at org.jboss.remoting.Client.invoke(Client.java:879)
	at org.jboss.invocation.unified.interfaces.UnifiedInvokerProxy.invoke(UnifiedInvokerProxy.java:184)
	at org.jboss.invocation.InvokerInterceptor.invokeInvoker(InvokerInterceptor.java:416)
	at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:248)
	at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:61)
	at org.jboss.proxy.ejb.SecurityContextInterceptor.invoke(SecurityContextInterceptor.java:64)
	at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:68)
	at org.jboss.proxy.ejb.EntityInterceptor.invoke(EntityInterceptor.java:112)
	at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:101)
	at $Proxy3.stopTimer(Unknown Source)
	at org.jboss.test.timer.test.TimerCleanUpUnitTestCase.testEntityBeanTimerHasTimerServiceAfterCancellationInstPerTx(TimerCleanUpUnitTestCase.java:107)
	at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
	at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
	at junit.extensions.TestSetup.run(TestSetup.java:25)

      Relevant log part:

      2012-08-16 04:04:19,761 DEBUG [org.jboss.deployers.plugins.deployers.DeployersImpl] (RMI TCP Connection(652)-127.0.0.1) Fully Deployed vfszip:/var/lib/jenkins/jobs/EAP-5.x-JDK7-latest/workspace/JBPAPP_5_1/testsuite/output/lib/ejb-timer.ear/
2012-08-16 04:04:20,037 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7c88 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) setEntityContext
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbCreate(555)
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbPostCreate(555)
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbStore
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbPassivate
2012-08-16 04:04:20,037 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7c88 status: ActionStatus.COMMITTED )
2012-08-16 04:04:20,037 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7c8b status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbActivate
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbLoad
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) TimerEntityBean.startTimer(), try to get a Timer Service from the Entity Context
2012-08-16 04:04:20,037 DEBUG [org.jboss.ejb.txtimer.EJBTimerServiceImpl] (WorkerThread#26[127.0.0.1:51343]) createTimerService: org.jboss.ejb.txtimer.TimerServiceImpl@1ea5daf
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) TimerEntityBean.startTimer(), create a timer if not already done
2012-08-16 04:04:20,037 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (WorkerThread#26[127.0.0.1:51343]) setTimerState: created
2012-08-16 04:04:20,037 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (WorkerThread#26[127.0.0.1:51343]) setTimerState: started_in_tx
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbStore
2012-08-16 04:04:20,037 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (WorkerThread#26[127.0.0.1:51343]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=1000,periode=1000,started_in_tx]
2012-08-16 04:04:20,037 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (WorkerThread#26[127.0.0.1:51343]) setTimerState: active
2012-08-16 04:04:20,037 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbPassivate
2012-08-16 04:04:20,037 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7c8b status: ActionStatus.COMMITTED )
2012-08-16 04:04:21,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:21,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:22 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:21,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:21,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7c91 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:21,182 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:21,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:21,183 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:21,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:21,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:21,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:21,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:21,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7c91 status: ActionStatus.COMMITTED )
2012-08-16 04:04:22,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:22,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:23 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:22,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:22,180 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7c95 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:22,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:22,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:22,181 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=856,periode=1000,in_timeout]
2012-08-16 04:04:22,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:22,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:22,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=856,periode=1000,in_timeout]
2012-08-16 04:04:22,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:22,181 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7c95 status: ActionStatus.COMMITTED )
2012-08-16 04:04:23,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:23,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:24 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:23,182 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:23,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7c99 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:23,182 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:23,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:23,183 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:23,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:23,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:23,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:23,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:23,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7c99 status: ActionStatus.COMMITTED )
2012-08-16 04:04:24,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:24,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:25 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:24,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:24,179 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7c9d status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:24,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:24,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:24,180 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=857,periode=1000,in_timeout]
2012-08-16 04:04:24,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:24,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:24,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=856,periode=1000,in_timeout]
2012-08-16 04:04:24,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:24,181 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7c9d status: ActionStatus.COMMITTED )
2012-08-16 04:04:25,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:25,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:26 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:25,182 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:25,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7ca1 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:25,182 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:25,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:25,183 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:25,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:25,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:25,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:25,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:25,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7ca1 status: ActionStatus.COMMITTED )
2012-08-16 04:04:26,174 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-137,periode=1000,active]
2012-08-16 04:04:26,174 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:27 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:26,175 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:26,175 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7ca5 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:26,176 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:26,176 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:26,176 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=861,periode=1000,in_timeout]
2012-08-16 04:04:26,176 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:26,177 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:26,177 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=860,periode=1000,in_timeout]
2012-08-16 04:04:26,177 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:26,177 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7ca5 status: ActionStatus.COMMITTED )
2012-08-16 04:04:27,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:27,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:28 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:27,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:27,182 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7ca9 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:27,182 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:27,182 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:27,182 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=855,periode=1000,in_timeout]
2012-08-16 04:04:27,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:27,183 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:27,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=854,periode=1000,in_timeout]
2012-08-16 04:04:27,183 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:27,183 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-4 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7ca9 status: ActionStatus.COMMITTED )
2012-08-16 04:04:28,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:28,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:29 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:28,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:28,180 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cad status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:28,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:28,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:28,180 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=857,periode=1000,in_timeout]
2012-08-16 04:04:28,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:28,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:28,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=856,periode=1000,in_timeout]
2012-08-16 04:04:28,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:28,181 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-1 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cad status: ActionStatus.COMMITTED )
2012-08-16 04:04:29,174 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-137,periode=1000,active]
2012-08-16 04:04:29,174 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:30 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:29,177 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:29,178 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cb1 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:29,178 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:29,178 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:29,178 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=859,periode=1000,in_timeout]
2012-08-16 04:04:29,179 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:29,179 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:29,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=858,periode=1000,in_timeout]
2012-08-16 04:04:29,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:29,179 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-5 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cb1 status: ActionStatus.COMMITTED )
2012-08-16 04:04:29,658 INFO  [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Attempting to reconnect org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueC destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,658 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Setting up org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueC destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,658 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Retrieving the jms provider adapter java:DefaultJMSProvider for org.jboss.resource.adapter.jms.inflow.JmsActivation@643eeb7e(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2 mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@5ed6d09c active=true transacted=true)
2012-08-16 04:04:29,659 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Using jms provider adapter org.jboss.jms.jndi.JNDIProviderAdapter@1a238839 for org.jboss.resource.adapter.jms.inflow.JmsActivation@643eeb7e(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2 mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@5ed6d09c active=true transacted=true)
2012-08-16 04:04:29,659 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Using context {java.naming.factory.initial=org.jboss.iiop.naming.ORBInitialContextFactory, java.naming.corba.orb=org.jacorb.orb.ORB@e08dcf5, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces:org.jboss.naming:org.jnp.interfaces} for org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueC destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,659 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-39) Attempting to lookup dlq connection factory java:/XAConnectionFactory
2012-08-16 04:04:29,659 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-39) Got dlq connection factory JBossConnectionFactory->ConnectionFactoryDelegate[jboss.messaging.connectionfactory:service=ConnectionFactory, SID=0] from java:/XAConnectionFactory
2012-08-16 04:04:29,659 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-39) Attempting to create queue connection with user null
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[411678894:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn].connect(ConsolidatedListener(UNINITIALIZED))
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[411678894:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] connected to InvokerLocator [bisocket://localhost:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&enableTcpNoDelay=true&failureDisconnectTimeout=0&marshaller=org.jboss.jms.wireformat.JMSWireFormat&socket.check_connection=false&stopLeaseOnFailure=true&timeout=30000&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat&useClientConnectionIdentity=true&validatorPingPeriod=10000&validatorPingTimeout=5000&writeTimeout=30000]
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[411678894:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] is connected
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[2042344471:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxo].connect(null)
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[2042344471:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxo] connected to InvokerLocator [bisocket://localhost:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&enableTcpNoDelay=true&failureDisconnectTimeout=0&marshaller=org.jboss.jms.wireformat.JMSWireFormat&socket.check_connection=false&stopLeaseOnFailure=true&timeout=30000&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat&useClientConnectionIdentity=true&validatorPingPeriod=10000&validatorPingTimeout=5000&writeTimeout=30000]
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[2042344471:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxo] is connected
2012-08-16 04:04:29,660 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) starting callback Connector: InvokerLocator [local://10.16.43.69:380890674/callback?callbackServerHost=10.16.43.69&callbackServerPort=380890674&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxp&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,661 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) org.jboss.remoting.transport.local.LocalServerInvoker@587914f did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
2012-08-16 04:04:29,661 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) org.jboss.remoting.transport.local.LocalServerInvoker@587914f created server socket factory javax.net.DefaultServerSocketFactory@658db648
2012-08-16 04:04:29,661 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) org.jboss.remoting.transport.local.LocalServerInvoker@587914f started for locator InvokerLocator [local://10.16.43.69:380890674/callback?callbackServerHost=10.16.43.69&callbackServerPort=380890674&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxp&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,661 DEBUG [org.jboss.remoting.transport.Connector] (WorkManager(2)-39) org.jboss.remoting.transport.Connector@2bbef409 started
2012-08-16 04:04:29,661 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[123001951:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn].connect(null)
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[123001951:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] connected to InvokerLocator [local://10.16.43.69:380890674/callback?callbackServerHost=10.16.43.69&callbackServerPort=380890674&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxp&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[123001951:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] is connected
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) ServerInvoker (org.jboss.remoting.transport.local.LocalServerInvoker@587914f) added client callback handler CallbackManager[122c9071] with session id of ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr and callback handle object of null.
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-39) removed org.jboss.remoting.transport.local.LocalClientInvoker@544fe4bb from registry
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[123001951:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] is disconnected
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] (WorkManager(2)-39) Session id for callback handler is ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] (WorkManager(2)-39) ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr] using callbackTimeout value 10000
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] (WorkManager(2)-39) DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[localhost:4457]
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] (WorkManager(2)-39) DefaultCallbackErrorHandler[SocketServerInvoker[localhost:4457]] setting callback handler to ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr]
2012-08-16 04:04:29,662 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1228004411:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr].connect(null)
2012-08-16 04:04:29,663 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1228004411:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr] connected to InvokerLocator [local://10.16.43.69:380890674/callback?callbackServerHost=10.16.43.69&callbackServerPort=380890674&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxp&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,663 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1228004411:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr] is connected
2012-08-16 04:04:29,663 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkManager(2)-39) adding callback handler ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr]
2012-08-16 04:04:29,663 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkManager(2)-39) found calllback handler for remoting session ...-h5xkcoyk-mxn UID=ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn
2012-08-16 04:04:29,663 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] (WorkManager(2)-39) registered connection ConnectionEndpoint[uxm-nyockx5h-1-ocvmix5h-rrczb6-x171ga] as ...-h5xkcoyk-mxn
2012-08-16 04:04:29,663 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-39) Using queue connection JBossConnection->ConnectionDelegate[1242164731, ID=uxm-nyockx5h-1-ocvmix5h-rrczb6-x171ga, SID=0]
2012-08-16 04:04:29,664 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Setup DLQ org.jboss.resource.adapter.jms.inflow.JmsActivation@643eeb7e(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2 mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@5ed6d09c active=true dlq=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler@dca04ef transacted=true)
2012-08-16 04:04:29,664 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Destination type defined as javax.jms.Queue
2012-08-16 04:04:29,664 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Retrieving destination queue/QueueC of type javax.jms.Queue
2012-08-16 04:04:29,664 ERROR [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Unable to reconnect org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueC destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
javax.naming.NamingException: Could not dereference object [Root exception is javax.naming.NameNotFoundException: QueueC not bound]
	at org.jnp.interfaces.NamingContext.resolveLink(NamingContext.java:1399)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:864)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:713)
	at javax.naming.InitialContext.lookup(InitialContext.java:411)
	at org.jboss.util.naming.Util.lookup(Util.java:222)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation.setupDestination(JmsActivation.java:466)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation.setup(JmsActivation.java:354)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation.handleFailure(JmsActivation.java:294)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation$SetupActivation.run(JmsActivation.java:817)
	at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
	at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)
Caused by: javax.naming.NameNotFoundException: QueueC not bound
	at org.jnp.server.NamingServer.getBinding(NamingServer.java:771)
	at org.jnp.server.NamingServer.getBinding(NamingServer.java:779)
	at org.jnp.server.NamingServer.getObject(NamingServer.java:785)
	at org.jnp.server.NamingServer.lookup(NamingServer.java:443)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:753)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:713)
	at javax.naming.InitialContext.lookup(InitialContext.java:411)
	at org.jnp.interfaces.NamingContext.resolveLink(NamingContext.java:1393)
	... 13 more
2012-08-16 04:04:29,665 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Tearing down org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueC destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,665 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Removing DLQ org.jboss.resource.adapter.jms.inflow.JmsActivation@643eeb7e(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2 mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@5ed6d09c active=true dlq=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler@dca04ef transacted=true)
2012-08-16 04:04:29,665 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-39) Closing the JBossConnection->ConnectionDelegate[1242164731, ID=uxm-nyockx5h-1-ocvmix5h-rrczb6-x171ga, SID=0]
2012-08-16 04:04:29,666 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] (WorkManager(2)-39) unregistered connection ConnectionEndpoint[uxm-nyockx5h-1-ocvmix5h-rrczb6-x171ga] with remoting session ID ...-h5xkcoyk-mxn
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) SocketServerInvoker[localhost:4457] removed ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr]
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-39) removed org.jboss.remoting.transport.local.LocalClientInvoker@64ae0e6c from registry
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1228004411:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr] is disconnected
2012-08-16 04:04:29,666 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkManager(2)-39) removing callback handler ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr]
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1597310999:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn].connect(null)
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1597310999:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] connected to InvokerLocator [local://10.16.43.69:380890674/callback?callbackServerHost=10.16.43.69&callbackServerPort=380890674&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxp&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1597310999:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] is connected
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) ServerInvoker (org.jboss.remoting.transport.local.LocalServerInvoker@587914f) removing client callback handler with session id of ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn+ag171x-6bzcrr-h5ximvco-1-h5xkcoyl-mxr.
2012-08-16 04:04:29,666 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-39) removed org.jboss.remoting.transport.local.LocalClientInvoker@12a64ed6 from registry
2012-08-16 04:04:29,667 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[1597310999:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] is disconnected
2012-08-16 04:04:29,667 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-39) org.jboss.remoting.transport.local.LocalServerInvoker@587914f stopped
2012-08-16 04:04:29,667 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-39) decremented org.jboss.remoting.transport.local.LocalClientInvoker@13d97f62's count, current count 6
2012-08-16 04:04:29,667 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[411678894:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxn] is disconnected
2012-08-16 04:04:29,667 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-39) decremented org.jboss.remoting.transport.local.LocalClientInvoker@2c3a051c's count, current count 6
2012-08-16 04:04:29,667 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-39) Client[2042344471:ag171x-6bzcrr-h5ximvco-1-h5xkcoyk-mxo] is disconnected
2012-08-16 04:04:29,667 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-39) Tearing down complete org.jboss.resource.adapter.jms.inflow.JmsActivation@643eeb7e(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@754b27b2 mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@5ed6d09c active=true transacted=true)
2012-08-16 04:04:29,702 INFO  [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Attempting to reconnect org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueA destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,702 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Setting up org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueA destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,702 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Retrieving the jms provider adapter java:DefaultJMSProvider for org.jboss.resource.adapter.jms.inflow.JmsActivation@6fdd8e58(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@3aac6cc8 active=true transacted=true)
2012-08-16 04:04:29,702 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Using jms provider adapter org.jboss.jms.jndi.JNDIProviderAdapter@1a238839 for org.jboss.resource.adapter.jms.inflow.JmsActivation@6fdd8e58(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@3aac6cc8 active=true transacted=true)
2012-08-16 04:04:29,703 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Using context {java.naming.factory.initial=org.jboss.iiop.naming.ORBInitialContextFactory, java.naming.corba.orb=org.jacorb.orb.ORB@e08dcf5, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces:org.jboss.naming:org.jnp.interfaces} for org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueA destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,703 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-40) Attempting to lookup dlq connection factory java:/XAConnectionFactory
2012-08-16 04:04:29,703 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-40) Got dlq connection factory JBossConnectionFactory->ConnectionFactoryDelegate[jboss.messaging.connectionfactory:service=ConnectionFactory, SID=0] from java:/XAConnectionFactory
2012-08-16 04:04:29,703 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-40) Attempting to create queue connection with user null
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1686228266:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw].connect(ConsolidatedListener(UNINITIALIZED))
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1686228266:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] connected to InvokerLocator [bisocket://localhost:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&enableTcpNoDelay=true&failureDisconnectTimeout=0&marshaller=org.jboss.jms.wireformat.JMSWireFormat&socket.check_connection=false&stopLeaseOnFailure=true&timeout=30000&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat&useClientConnectionIdentity=true&validatorPingPeriod=10000&validatorPingTimeout=5000&writeTimeout=30000]
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1686228266:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] is connected
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[96777203:ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxx].connect(null)
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[96777203:ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxx] connected to InvokerLocator [bisocket://localhost:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&enableTcpNoDelay=true&failureDisconnectTimeout=0&marshaller=org.jboss.jms.wireformat.JMSWireFormat&socket.check_connection=false&stopLeaseOnFailure=true&timeout=30000&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat&useClientConnectionIdentity=true&validatorPingPeriod=10000&validatorPingTimeout=5000&writeTimeout=30000]
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[96777203:ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxx] is connected
2012-08-16 04:04:29,704 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) starting callback Connector: InvokerLocator [local://10.16.43.69:344873346/callback?callbackServerHost=10.16.43.69&callbackServerPort=344873346&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxy&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) org.jboss.remoting.transport.local.LocalServerInvoker@53b49af4 did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) org.jboss.remoting.transport.local.LocalServerInvoker@53b49af4 created server socket factory javax.net.DefaultServerSocketFactory@658db648
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) org.jboss.remoting.transport.local.LocalServerInvoker@53b49af4 started for locator InvokerLocator [local://10.16.43.69:344873346/callback?callbackServerHost=10.16.43.69&callbackServerPort=344873346&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxy&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.transport.Connector] (WorkManager(2)-40) org.jboss.remoting.transport.Connector@1cd6b3c6 started
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1982411802:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw].connect(null)
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1982411802:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] connected to InvokerLocator [local://10.16.43.69:344873346/callback?callbackServerHost=10.16.43.69&callbackServerPort=344873346&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxy&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1982411802:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] is connected
2012-08-16 04:04:29,705 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) ServerInvoker (org.jboss.remoting.transport.local.LocalServerInvoker@53b49af4) added client callback handler CallbackManager[3502197a] with session id of ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0 and callback handle object of null.
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-40) removed org.jboss.remoting.transport.local.LocalClientInvoker@b1bd391 from registry
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1982411802:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] is disconnected
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] (WorkManager(2)-40) Session id for callback handler is ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] (WorkManager(2)-40) ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0] using callbackTimeout value 10000
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] (WorkManager(2)-40) DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[localhost:4457]
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] (WorkManager(2)-40) DefaultCallbackErrorHandler[SocketServerInvoker[localhost:4457]] setting callback handler to ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0]
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1340004937:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0].connect(null)
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1340004937:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0] connected to InvokerLocator [local://10.16.43.69:344873346/callback?callbackServerHost=10.16.43.69&callbackServerPort=344873346&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxy&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,706 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1340004937:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0] is connected
2012-08-16 04:04:29,706 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkManager(2)-40) adding callback handler ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0]
2012-08-16 04:04:29,706 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkManager(2)-40) found calllback handler for remoting session ...-h5xkcozr-mxw UID=ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw
2012-08-16 04:04:29,707 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] (WorkManager(2)-40) registered connection ConnectionEndpoint[3ym-vzockx5h-1-ocvmix5h-rrczb6-x171ga] as ...-h5xkcozr-mxw
2012-08-16 04:04:29,707 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-40) Using queue connection JBossConnection->ConnectionDelegate[867922394, ID=3ym-vzockx5h-1-ocvmix5h-rrczb6-x171ga, SID=0]
2012-08-16 04:04:29,707 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Setup DLQ org.jboss.resource.adapter.jms.inflow.JmsActivation@6fdd8e58(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@3aac6cc8 active=true dlq=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler@110a2f9b transacted=true)
2012-08-16 04:04:29,707 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Destination type defined as javax.jms.Queue
2012-08-16 04:04:29,707 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Retrieving destination queue/QueueA of type javax.jms.Queue
2012-08-16 04:04:29,708 ERROR [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Unable to reconnect org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueA destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
javax.naming.NamingException: Could not dereference object [Root exception is javax.naming.NameNotFoundException: QueueA not bound]
	at org.jnp.interfaces.NamingContext.resolveLink(NamingContext.java:1399)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:864)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:713)
	at javax.naming.InitialContext.lookup(InitialContext.java:411)
	at org.jboss.util.naming.Util.lookup(Util.java:222)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation.setupDestination(JmsActivation.java:466)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation.setup(JmsActivation.java:354)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation.handleFailure(JmsActivation.java:294)
	at org.jboss.resource.adapter.jms.inflow.JmsActivation$SetupActivation.run(JmsActivation.java:817)
	at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)
	at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)
Caused by: javax.naming.NameNotFoundException: QueueA not bound
	at org.jnp.server.NamingServer.getBinding(NamingServer.java:771)
	at org.jnp.server.NamingServer.getBinding(NamingServer.java:779)
	at org.jnp.server.NamingServer.getObject(NamingServer.java:785)
	at org.jnp.server.NamingServer.lookup(NamingServer.java:443)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:753)
	at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:713)
	at javax.naming.InitialContext.lookup(InitialContext.java:411)
	at org.jnp.interfaces.NamingContext.resolveLink(NamingContext.java:1393)
	... 13 more
2012-08-16 04:04:29,709 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Tearing down org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d(ra=org.jboss.resource.adapter.jms.JmsResourceAdapter@6bb56582 destination=queue/QueueA destinationType=javax.jms.Queue tx=true durable=false reconnect=10 provider=DefaultJMSProvider user=null maxMessages=1 minSession=1 maxSession=15 keepAlive=30000 useDLQ=true DLQHandler=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler DLQJndiName=queue/DLQ DLQUser=null DLQMaxResent=10)
2012-08-16 04:04:29,709 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Removing DLQ org.jboss.resource.adapter.jms.inflow.JmsActivation@6fdd8e58(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@3aac6cc8 active=true dlq=org.jboss.resource.adapter.jms.inflow.dlq.GenericDLQHandler@110a2f9b transacted=true)
2012-08-16 04:04:29,709 DEBUG [org.jboss.resource.adapter.jms.inflow.dlq.AbstractDLQHandler] (WorkManager(2)-40) Closing the JBossConnection->ConnectionDelegate[867922394, ID=3ym-vzockx5h-1-ocvmix5h-rrczb6-x171ga, SID=0]
2012-08-16 04:04:29,709 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] (WorkManager(2)-40) unregistered connection ConnectionEndpoint[3ym-vzockx5h-1-ocvmix5h-rrczb6-x171ga] with remoting session ID ...-h5xkcozr-mxw
2012-08-16 04:04:29,709 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) SocketServerInvoker[localhost:4457] removed ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0]
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-40) removed org.jboss.remoting.transport.local.LocalClientInvoker@144ecb06 from registry
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1340004937:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0] is disconnected
2012-08-16 04:04:29,710 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkManager(2)-40) removing callback handler ServerInvokerCallbackHandler[ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0]
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1089667412:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw].connect(null)
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1089667412:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] connected to InvokerLocator [local://10.16.43.69:344873346/callback?callbackServerHost=10.16.43.69&callbackServerPort=344873346&callbackServerProtocol=local&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxy&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper]
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1089667412:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] is connected
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) ServerInvoker (org.jboss.remoting.transport.local.LocalServerInvoker@53b49af4) removing client callback handler with session id of ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw+ag171x-6bzcrr-h5ximvco-1-h5xkcozt-my0.
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-40) removed org.jboss.remoting.transport.local.LocalClientInvoker@11dc531c from registry
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1089667412:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] is disconnected
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.ServerInvoker] (WorkManager(2)-40) org.jboss.remoting.transport.local.LocalServerInvoker@53b49af4 stopped
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-40) decremented org.jboss.remoting.transport.local.LocalClientInvoker@13d97f62's count, current count 6
2012-08-16 04:04:29,710 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[1686228266:ag171x-6bzcrr-h5ximvco-1-h5xkcozr-mxw] is disconnected
2012-08-16 04:04:29,711 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkManager(2)-40) decremented org.jboss.remoting.transport.local.LocalClientInvoker@2c3a051c's count, current count 6
2012-08-16 04:04:29,711 DEBUG [org.jboss.remoting.Client] (WorkManager(2)-40) Client[96777203:ag171x-6bzcrr-h5ximvco-1-h5xkcozs-mxx] is disconnected
2012-08-16 04:04:29,711 DEBUG [org.jboss.resource.adapter.jms.inflow.JmsActivation] (WorkManager(2)-40) Tearing down complete org.jboss.resource.adapter.jms.inflow.JmsActivation@6fdd8e58(spec=org.jboss.resource.adapter.jms.inflow.JmsActivationSpec@2e14839d mepf=org.jboss.ejb.plugins.jms.JMSContainerInvoker@3aac6cc8 active=true transacted=true)
2012-08-16 04:04:30,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:30,178 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:31 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:30,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:30,180 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cb5 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:30,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:30,180 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:30,180 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=857,periode=1000,in_timeout]
2012-08-16 04:04:30,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:30,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:30,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=856,periode=1000,in_timeout]
2012-08-16 04:04:30,181 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:30,181 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-3 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cb5 status: ActionStatus.COMMITTED )
2012-08-16 04:04:31,174 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-137,periode=1000,active]
2012-08-16 04:04:31,174 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:32 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:31,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:31,178 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cb9 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:31,178 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:31,179 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:31,179 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=858,periode=1000,in_timeout]
2012-08-16 04:04:31,179 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:31,179 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:31,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=858,periode=1000,in_timeout]
2012-08-16 04:04:31,179 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:31,179 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-6 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cb9 status: ActionStatus.COMMITTED )
2012-08-16 04:04:32,178 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) run: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=-141,periode=1000,active]
2012-08-16 04:04:32,179 DEBUG [org.jboss.ejb.txtimer.GeneralPurposeDatabasePersistencePlugin] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) Updating next timeout date to Thu Aug 16 04:04:33 EDT 2012 for timer: 724a4113-c339-4ef8-9cbb-c912f8917466 ,timedObjectId: [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]
2012-08-16 04:04:32,180 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: in_timeout
2012-08-16 04:04:32,181 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cbd status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:32,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbActivate
2012-08-16 04:04:32,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbLoad
2012-08-16 04:04:32,181 DEBUG [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbTimeout(), timer: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=856,periode=1000,in_timeout]
2012-08-16 04:04:32,181 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbStore
2012-08-16 04:04:32,184 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cc1 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:32,184 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) setEntityContext
2012-08-16 04:04:32,184 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbActivate
2012-08-16 04:04:32,184 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbLoad
2012-08-16 04:04:32,198 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) ejbPassivate
2012-08-16 04:04:32,198 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) commit: [id=724a4113-c339-4ef8-9cbb-c912f8917466,target=[target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555],remaining=839,periode=1000,in_timeout]
2012-08-16 04:04:32,198 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) setTimerState: active
2012-08-16 04:04:32,198 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (EJB-Timer-2 [target=jboss.j2ee:jndiName=ejb/test/timer/TimerEntityExtInstPerTx,service=EJB,pk=555]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cbd status: ActionStatus.COMMITTED )
2012-08-16 04:04:32,210 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbStore
2012-08-16 04:04:32,210 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbPassivate
2012-08-16 04:04:32,210 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cc1 status: ActionStatus.COMMITTED )
2012-08-16 04:04:32,220 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cc4 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:32,221 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbActivate
2012-08-16 04:04:32,221 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbLoad
2012-08-16 04:04:32,222 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cc4 status: ActionStatus.ABORTED )
2012-08-16 04:04:32,222 ERROR [org.jboss.ejb.plugins.LogInterceptor] (WorkerThread#26[127.0.0.1:51343]) EJBException in method: public abstract void org.jboss.test.timer.interfaces.TimerEntity.stopTimer() throws java.rmi.RemoteException:
javax.ejb.EJBException: Timer is not available
	at org.jboss.test.timer.ejb.TimerEntityBean.stopTimer(TimerEntityBean.java:130)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at org.jboss.invocation.Invocation.performCall(Invocation.java:386)
	at org.jboss.ejb.EntityContainer$ContainerInterceptor.invoke(EntityContainer.java:1205)
	at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:284)
	at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:156)
	at org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:123)
	at org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:279)
	at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:104)
	at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:76)
	at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
	at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
	at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
	at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
	at org.jboss.ejb.plugins.SecurityInterceptor.process(SecurityInterceptor.java:281)
	at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:211)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.process(PreSecurityInterceptor.java:167)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.invoke(PreSecurityInterceptor.java:84)
	at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
	at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
	at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:533)
	at org.jboss.ejb.Container.invoke(Container.java:1092)
	at sun.reflect.GeneratedMethodAccessor377.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
	at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
	at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
	at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
	at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
	at org.jboss.invocation.unified.server.UnifiedInvoker.invoke(UnifiedInvoker.java:232)
	at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:967)
	at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:791)
	at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:744)
	at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586)
	at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)
2012-08-16 04:04:32,297 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cc7 status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:32,298 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbCreate(666)
2012-08-16 04:04:32,298 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbPostCreate(666)
2012-08-16 04:04:32,298 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbStore
2012-08-16 04:04:32,298 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbPassivate
2012-08-16 04:04:32,299 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cc7 status: ActionStatus.COMMITTED )
2012-08-16 04:04:32,314 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::insert ( BasicAction: a102b45:e3f5:502c9e68:7cca status: ActionStatus.RUNNING, 300 )
2012-08-16 04:04:32,315 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbActivate
2012-08-16 04:04:32,315 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) ejbLoad
2012-08-16 04:04:32,315 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) TimerEntityBean.startSingleTimer(), try to get a Timer Service from the Entity Context
2012-08-16 04:04:32,315 DEBUG [org.jboss.ejb.txtimer.EJBTimerServiceImpl] (WorkerThread#26[127.0.0.1:51343]) createTimerService: org.jboss.ejb.txtimer.TimerServiceImpl@48d3c733
2012-08-16 04:04:32,316 INFO  [org.jboss.test.timer.ejb.TimerEntityExtBean] (WorkerThread#26[127.0.0.1:51343]) TimerEntityBean.startSingleTimer(), create a timer if not already done
2012-08-16 04:04:32,316 DEBUG [org.jboss.ejb.txtimer.EJBTimerServiceImpl] (WorkerThread#26[127.0.0.1:51343]) removeTimerService: org.jboss.ejb.txtimer.TimerServiceImpl@48d3c733
2012-08-16 04:04:32,316 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (WorkerThread#26[127.0.0.1:51343]) TransactionReaper::remove ( BasicAction: a102b45:e3f5:502c9e68:7cca status: ActionStatus.ABORTED )
2012-08-16 04:04:32,316 ERROR [org.jboss.ejb.plugins.LogInterceptor] (WorkerThread#26[127.0.0.1:51343]) EJBException in method: public abstract void org.jboss.test.timer.interfaces.TimerEntity.startSingleTimer(long) throws java.rmi.RemoteException:
javax.ejb.EJBException: Timer is already set
	at org.jboss.test.timer.ejb.TimerEntityBean.startSingleTimer(TimerEntityBean.java:89)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at org.jboss.invocation.Invocation.performCall(Invocation.java:386)
	at org.jboss.ejb.EntityContainer$ContainerInterceptor.invoke(EntityContainer.java:1205)
	at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invoke(EntitySynchronizationInterceptor.java:284)
	at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:156)
	at org.jboss.ejb.plugins.EntityReentranceInterceptor.invoke(EntityReentranceInterceptor.java:123)
	at org.jboss.ejb.plugins.EntityInstanceInterceptor.invoke(EntityInstanceInterceptor.java:279)
	at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:104)
	at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:76)
	at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
	at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
	at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:350)
	at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
	at org.jboss.ejb.plugins.SecurityInterceptor.process(SecurityInterceptor.java:281)
	at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:211)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.process(PreSecurityInterceptor.java:167)
	at org.jboss.ejb.plugins.security.PreSecurityInterceptor.invoke(PreSecurityInterceptor.java:84)
	at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
	at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
	at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:533)
	at org.jboss.ejb.Container.invoke(Container.java:1092)
	at sun.reflect.GeneratedMethodAccessor377.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
	at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
	at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
	at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
	at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
	at org.jboss.invocation.unified.server.UnifiedInvoker.invoke(UnifiedInvoker.java:232)
	at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:967)
	at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:791)
	at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:744)
	at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586)
	at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234)

      Seems like there is some comm break. At some point in(555) test.

      Attachments

        1. JBPAPP-9713.patch
          9 kB
          Bartosz Baranowski

        Issue Links

          blocks

          Task - Represents a small unit of work that is not end-user facing. JBPAPP-9712 Regression in EAP 5.2 testsuite

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Resolved

          Activity

            People

              rhn-cservice-bbaranow Bartosz Baranowski
              rhn-cservice-bbaranow Bartosz Baranowski
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: