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

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

      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.

        1. JBPAPP-9713.patch
          9 kB
          Bartosz Baranowski

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

                Created:
                Updated:
                Resolved: