Sporadic read timeouts for app client reading a msg sent fro
starksm64 Sep 11, 2008 1:38 PMWe are currently seeing sporadic failures to retrieve a msg sent from an ejb timeout in the tck tests. I have a trace level log of the server side for the period of the send until the client times out(at 00:48:55). Is there an indication of why the msg is not getting delivered in the server log?
Server side:
2008-09-11 00:48:21,760 TRACE [org.jboss.jms.wireformat.JMSWireFormat:235] (WorkerThread#4[127.0.0.1:57660]) Writing packet: org.jboss.jms.wireformat.NullResponse@6f3be7 2008-09-11 00:48:21,760 TRACE [org.jboss.jms.wireformat.JMSWireFormat:239] (WorkerThread#4[127.0.0.1:57660]) Wrote packet 2008-09-11 00:48:23,246 TRACE [org.jboss.jms.tx.MessagingXAResource:121] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) MessagingXAResource[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] starting < 131075, 28, 26, 494597495048489910158975097100585256995656484856581005655519749504848991015897509710058525699565648485658100565556 >, flags: 0 2008-09-11 00:48:23,247 TRACE [org.jboss.jms.tx.MessagingXAResource:144] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Converting local tx into global tx branch 2008-09-11 00:48:23,248 TRACE [org.jboss.jms.tx.ResourceManager:511] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) converting LocalTx[2g5-rdbgwykf-1-ihi3rykf-nhqt3u-q50ia] to MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,249 TRACE [org.jboss.jms.tx.ResourceManager:610] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) getting transaction for MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,250 TRACE [org.jboss.jms.tx.MessagingXAResource:313] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) MessagingXAResource[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] setting current xid to MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51, previous LocalTx[2g5-rdbgwykf-1-ihi3rykf-nhqt3u-q50ia] 2008-09-11 00:48:23,253 TRACE [org.jboss.jms.client.delegate.DelegateSupport:187] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] invoking org.jboss.jms.wireformat.ConnectionStartRequest@1b0108a synchronously on server using Client[19242474] 2008-09-11 00:48:23,254 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler:126] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking InvocationRequest[dfbde, JMS, org.jboss.jms.wireformat.ConnectionStartRequest@1b0108a] 2008-09-11 00:48:23,255 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:101] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].start() 2008-09-11 00:48:23,256 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:338] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] started 2008-09-11 00:48:23,257 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:121] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].start() OK 2008-09-11 00:48:23,258 TRACE [org.jboss.jms.client.delegate.DelegateSupport:191] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] got server response for org.jboss.jms.wireformat.ConnectionStartRequest@1b0108a: null 2008-09-11 00:48:23,260 TRACE [org.jboss.jms.client.container.ProducerAspect:107] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Using producer's default delivery mode: 2 2008-09-11 00:48:23,261 TRACE [org.jboss.jms.client.container.ProducerAspect:115] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Using producer's default priority: 4 2008-09-11 00:48:23,262 TRACE [org.jboss.jms.client.container.ProducerAspect:137] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Using producer's default timeToLive: 0 2008-09-11 00:48:23,264 TRACE [org.jboss.jms.client.container.ProducerAspect:160] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Using producer's default destination: JBossQueue[MY_QUEUE] 2008-09-11 00:48:23,266 TRACE [org.jboss.jms.client.container.SessionAspect:651] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) sending message JBossMessage[0]:PERSISTENT transactionally, queueing on resource manager txID=MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 sessionID= v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia 2008-09-11 00:48:23,267 TRACE [org.jboss.jms.tx.ResourceManager:129] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) addding message JBossMessage[0]:PERSISTENT for xid MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,268 TRACE [org.jboss.jms.tx.ResourceManager:610] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) getting transaction for MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,269 TRACE [org.jboss.jms.client.delegate.DelegateSupport:187] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] invoking org.jboss.jms.wireformat.ConnectionStopRequest@dcd87c synchronously on server using Client[19242474] 2008-09-11 00:48:23,270 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler:126] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking InvocationRequest[108c1a4, JMS, org.jboss.jms.wireformat.ConnectionStopRequest@dcd87c] 2008-09-11 00:48:23,271 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:101] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].stop() 2008-09-11 00:48:23,272 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:357] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Connection u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia stopped 2008-09-11 00:48:23,273 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:121] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].stop() OK 2008-09-11 00:48:23,274 TRACE [org.jboss.jms.client.delegate.DelegateSupport:191] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] got server response for org.jboss.jms.wireformat.ConnectionStopRequest@dcd87c: null 2008-09-11 00:48:23,275 TRACE [org.jboss.jms.client.container.ClosedInterceptor:257] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ClosedInterceptor.ClientProducerDelegate[NO_ID_SET] closed 2008-09-11 00:48:23,283 TRACE [org.jboss.jms.tx.MessagingXAResource:198] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) MessagingXAResource[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] ending < 131075, 28, 26, 494597495048489910158975097100585256995656484856581005655519749504848991015897509710058525699565648485658100565556 >, flags: 67108864 2008-09-11 00:48:23,284 TRACE [org.jboss.jms.tx.MessagingXAResource:325] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) MessagingXAResource[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] unsetting current xid MessagingXid (188197 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51, previous MessagingXid (2175876 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,285 TRACE [org.jboss.jms.tx.ResourceManager:311] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ending MessagingXid (188197 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51, success=true 2008-09-11 00:48:23,286 TRACE [org.jboss.jms.tx.ResourceManager:610] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) getting transaction for MessagingXid (188197 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,286 TRACE [org.jboss.jms.tx.MessagingXAResource:231] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) MessagingXAResource[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] preparing < 131075, 28, 26, 494597495048489910158975097100585256995656484856581005655519749504848991015897509710058525699565648485658100565556 > 2008-09-11 00:48:23,287 TRACE [org.jboss.jms.tx.ResourceManager:325] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) preparing MessagingXid (8914311 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,288 TRACE [org.jboss.jms.tx.ResourceManager:610] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) getting transaction for MessagingXid (8914311 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51 2008-09-11 00:48:23,288 TRACE [org.jboss.jms.client.delegate.DelegateSupport:187] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] invoking org.jboss.jms.wireformat.ConnectionSendTransactionRequest@230a58 synchronously on server using Client[19242474] 2008-09-11 00:48:23,289 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler:126] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking InvocationRequest[7c3a5a, JMS, org.jboss.jms.wireformat.ConnectionSendTransactionRequest@230a58] 2008-09-11 00:48:23,289 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:101] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].sendTransaction(TransactionRequest[TWO_PHASE_PREPARE, MessagingXid (8914311 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51], false) 2008-09-11 00:48:23,290 TRACE [org.jboss.jms.server.container.SecurityAspect:272] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) checking access permissions to JBossQueue[MY_QUEUE] 2008-09-11 00:48:23,291 DEBUG [org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore:103] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) No SecurityMetadadata was available for MY_QUEUE, using default security config 2008-09-11 00:48:23,292 TRACE [org.jboss.jms.server.security.SecurityMetadata:147] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Adding role: Role {name=guest;read=true;write=true;create=true} 2008-09-11 00:48:23,293 TRACE [org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore:175] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) authenticating user null 2008-09-11 00:48:23,296 TRACE [org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore:229] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) authorizing user null for role(s) [guest] 2008-09-11 00:48:23,299 TRACE [org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore:249] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) user null is authorized 2008-09-11 00:48:23,301 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:494] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] received TWO_PHASE_COMMIT prepare request 2008-09-11 00:48:23,302 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:797] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] processing transaction TX(20006641718100208):ACTIVE 2008-09-11 00:48:23,303 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:698] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] sending message JBossMessage[20006641718116599]:PERSISTENT in TX(20006641718100208):ACTIVE 2008-09-11 00:48:23,304 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:754] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] routing JBossMessage[20006641718116599]:PERSISTENT to queue 2008-09-11 00:48:23,305 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:766] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) sent JBossMessage[20006641718116599]:PERSISTENT 2008-09-11 00:48:23,305 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1478] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) SessionEndpoint[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] acknowledging transactionally 0 messages for TX(20006641718100208):ACTIVE 2008-09-11 00:48:23,306 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:842] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] processed transaction TX(20006641718100208):ACTIVE 2008-09-11 00:48:23,309 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:522] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] processed transaction successfully 2008-09-11 00:48:23,310 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:121] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].sendTransaction() OK 2008-09-11 00:48:23,311 TRACE [org.jboss.jms.client.delegate.DelegateSupport:191] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] got server response for org.jboss.jms.wireformat.ConnectionSendTransactionRequest@230a58: null 2008-09-11 00:48:23,312 TRACE [org.jboss.jms.tx.ResourceManager:341] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) State is now: 2 2008-09-11 00:48:23,321 TRACE [org.jboss.jms.tx.MessagingXAResource:245] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) MessagingXAResource[v65-752zvykf-1-ihi3rykf-nhqt3u-q50ia] committing < 131075, 28, 26, 494597495048489910158975097100585256995656484856581005655519749504848991015897509710058525699565648485658100565556 > (two phase) 2008-09-11 00:48:23,323 TRACE [org.jboss.jms.tx.ResourceManager:348] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) commiting xid MessagingXid (31644585 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51, onePhase=false 2008-09-11 00:48:23,323 TRACE [org.jboss.jms.tx.ResourceManager:352] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) got tx: org.jboss.jms.tx.ClientTransaction@c35f45 state 2 2008-09-11 00:48:23,324 TRACE [org.jboss.jms.client.delegate.DelegateSupport:187] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] invoking org.jboss.jms.wireformat.ConnectionSendTransactionRequest@a3d576 synchronously on server using Client[19242474] 2008-09-11 00:48:23,325 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler:126] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking InvocationRequest[13429d, JMS, org.jboss.jms.wireformat.ConnectionSendTransactionRequest@a3d576] 2008-09-11 00:48:23,326 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:101] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].sendTransaction(TransactionRequest[TWO_PHASE_COMMIT, MessagingXid (31644585 bq:97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.56 formatID:131075 gtxid:49.45.97.49.50.48.48.99.101.58.97.50.97.100.58.52.56.99.56.56.48.48.56.58.100.56.55.51], false) 2008-09-11 00:48:23,326 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:502] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] received TWO_PHASE_COMMIT commit request 2008-09-11 00:48:23,327 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:505] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Committing TX(20006641718100208):PREPARED 2008-09-11 00:48:23,330 TRACE [org.jboss.jms.server.endpoint.ServerConsumerEndpoint:219] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConsumerEndpoint[fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia] receives Reference[20006641718116599]:RELIABLE for delivery 2008-09-11 00:48:23,331 TRACE [org.jboss.jms.server.endpoint.ServerConsumerEndpoint:269] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConsumerEndpoint[fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia] has startStopLock lock, preparing the message for delivery 2008-09-11 00:48:23,332 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1315] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) SessionEndpoint[eg5-15hgwykf-1-ihi3rykf-nhqt3u-q50ia] handling delivery Delivery[Reference[20006641718116599]:RELIABLE] 2008-09-11 00:48:23,333 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1321] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Delivery id is now 0 2008-09-11 00:48:23,334 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1332] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) SessionEndpoint[eg5-15hgwykf-1-ihi3rykf-nhqt3u-q50ia] added delivery 0: Delivery[Reference[20006641718116599]:RELIABLE] 2008-09-11 00:48:23,335 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1357] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) SessionEndpoint[eg5-15hgwykf-1-ihi3rykf-nhqt3u-q50ia] doing the delivery straight away 2008-09-11 00:48:23,336 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1434] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) SessionEndpoint[eg5-15hgwykf-1-ihi3rykf-nhqt3u-q50ia] performing delivery for Reference[20006641718116599]:RELIABLE 2008-09-11 00:48:23,337 TRACE [org.jboss.jms.server.endpoint.ServerSessionEndpoint:1446] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) SessionEndpoint[eg5-15hgwykf-1-ihi3rykf-nhqt3u-q50ia] submitting message JBossMessage[20006641718116599]:PERSISTENT to the remoting layer to be sent asynchronously 2008-09-11 00:48:23,338 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:522] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia] processed transaction successfully 2008-09-11 00:48:23,339 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:121] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].sendTransaction() OK 2008-09-11 00:48:23,340 TRACE [org.jboss.jms.client.delegate.DelegateSupport:191] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] got server response for org.jboss.jms.wireformat.ConnectionSendTransactionRequest@a3d576: null 2008-09-11 00:48:23,344 TRACE [org.jboss.jms.client.delegate.DelegateSupport:187] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] invoking org.jboss.jms.wireformat.ConnectionStopRequest@571b87 synchronously on server using Client[19242474] 2008-09-11 00:48:23,345 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler:126] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking InvocationRequest[d06b6d, JMS, org.jboss.jms.wireformat.ConnectionStopRequest@571b87] 2008-09-11 00:48:23,346 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:101] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) invoking ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].stop() 2008-09-11 00:48:23,347 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint:357] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) Connection u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia stopped 2008-09-11 00:48:23,348 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:121] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionAdvised->ConnectionEndpoint[u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia].stop() OK 2008-09-11 00:48:23,348 TRACE [org.jboss.jms.client.delegate.DelegateSupport:191] (EJB-Timer-1221099538636[target=jboss.j2ee:jndiName=com_sun_ts_tests_ejb_ee_timer_entity_bmp_TestBean,service=EJB,pk=1]) ConnectionDelegate[8842257, ID=u65-642zvykf-1-ihi3rykf-nhqt3u-q50ia, SID=0] got server response for org.jboss.jms.wireformat.ConnectionStopRequest@571b87: null 2008-09-11 00:48:25,572 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger:?] (Thread-20) Periodic recovery - first pass <Thu, 11 Sep 2008 00:48:25> 2008-09-11 00:48:25,573 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger:?] (Thread-20) StatusModule: first pass 2008-09-11 00:48:25,671 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N:116] (Thread-20) [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass 2008-09-11 00:48:25,672 DEBUG [com.arjuna.ats.jta.logging.loggerI18N:114] (Thread-20) [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass 2008-09-11 00:48:35,674 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger:?] (Thread-20) Periodic recovery - second pass <Thu, 11 Sep 2008 00:48:35> 2008-09-11 00:48:35,675 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger:?] (Thread-20) AtomicActionRecoveryModule: Second pass 2008-09-11 00:48:35,675 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N:206] (Thread-20) [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass 2008-09-11 00:48:35,676 DEBUG [com.arjuna.ats.jta.logging.loggerI18N:175] (Thread-20) [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass 2008-09-11 00:48:42,292 DEBUG [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore:121] (JBossEJB3QuartzScheduler_QuartzSchedulerThread) Lock 'TRIGGER_ACCESS' is desired by: JBossEJB3QuartzScheduler_QuartzSchedulerThread 2008-09-11 00:48:42,293 DEBUG [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore:134] (JBossEJB3QuartzScheduler_QuartzSchedulerThread) Lock 'TRIGGER_ACCESS' is being obtained: JBossEJB3QuartzScheduler_QuartzSchedulerThread 2008-09-11 00:48:42,294 DEBUG [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore:168] (JBossEJB3QuartzScheduler_QuartzSchedulerThread) Lock 'TRIGGER_ACCESS' given to: JBossEJB3QuartzScheduler_QuartzSchedulerThread 2008-09-11 00:48:42,294 DEBUG [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore:193] (JBossEJB3QuartzScheduler_QuartzSchedulerThread) Lock 'TRIGGER_ACCESS' returned by: JBossEJB3QuartzScheduler_QuartzSchedulerThread 2008-09-11 00:48:55,141 TRACE [org.jboss.jms.wireformat.JMSWireFormat:258] (WorkerThread#4[127.0.0.1:57660]) Reading 2008-09-11 00:48:55,143 TRACE [org.jboss.jms.wireformat.JMSWireFormat:268] (WorkerThread#4[127.0.0.1:57660]) Stream is already DataInputStream :) 2008-09-11 00:48:55,143 TRACE [org.jboss.jms.wireformat.JMSWireFormat:292] (WorkerThread#4[127.0.0.1:57660]) Created packet ClosingRequest[ID=null, ver=0] 2008-09-11 00:48:55,143 TRACE [org.jboss.jms.wireformat.JMSWireFormat:296] (WorkerThread#4[127.0.0.1:57660]) Reading packet 2008-09-11 00:48:55,143 TRACE [org.jboss.jms.wireformat.JMSWireFormat:300] (WorkerThread#4[127.0.0.1:57660]) Read packet 2008-09-11 00:48:55,144 TRACE [org.jboss.jms.wireformat.JMSWireFormat:311] (WorkerThread#4[127.0.0.1:57660]) Returning payload: InvocationRequest[6cb1e8, JMS, ClosingRequest[ID=fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia, ver=25]] 2008-09-11 00:48:55,144 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler:126] (WorkerThread#4[127.0.0.1:57660]) invoking InvocationRequest[6cb1e8, JMS, ClosingRequest[ID=fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia, ver=25]] 2008-09-11 00:48:55,145 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:101] (WorkerThread#4[127.0.0.1:57660]) invoking ConsumerAdvised->ConsumerEndpoint[fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia].closing(-1) 2008-09-11 00:48:55,145 TRACE [org.jboss.jms.server.endpoint.ServerConsumerEndpoint:367] (WorkerThread#4[127.0.0.1:57660]) ConsumerEndpoint[fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia] closing 2008-09-11 00:48:55,146 TRACE [org.jboss.jms.server.container.ServerLogInterceptor:117] (WorkerThread#4[127.0.0.1:57660]) ConsumerAdvised->ConsumerEndpoint[fg5-8ihgwykf-1-ihi3rykf-nhqt3u-q50ia].closing() returned 0 2008-09-11 00:48:55,146 TRACE [org.jboss.jms.wireformat.JMSWireFormat:84] (WorkerThread#4[127.0.0.1:57660]) Writing InvocationResponse[1425bf, org.jboss.jms.wireformat.ClosingResponse@ba51ed] 2008-09-11 00:48:55,147 TRACE [org.jboss.jms.wireformat.JMSWireFormat:94] (WorkerThread#4[127.0.0.1:57660]) Stream is a DataOutputStream 2008-09-11 00:48:55,147 TRACE [org.jboss.jms.wireformat.JMSWireFormat:207] (WorkerThread#4[127.0.0.1:57660]) JBM Response 2008-09-11 00:48:55,147 TRACE [org.jboss.jms.wireformat.JMSWireFormat:235] (WorkerThread#4[127.0.0.1:57660]) Writing packet: org.jboss.jms.wireformat.ClosingResponse@ba51ed 2008-09-11 00:48:55,149 TRACE [org.jboss.jms.wireformat.JMSWireFormat:239] (WorkerThread#4[127.0.0.1:57660]) Wrote packet 2008-09-11 00:48:57,272 DEBUG [org.quartz.impl.jdbcjobstore.JobStoreCMT:2447] (QuartzScheduler_JBossEJB3QuartzScheduler-NON_CLUSTERED_MisfireHandler) MisfireHandler: scanning for misfires...
Client side:
09-11-2008 00:48:23: SVR-TRACE: Sending message at 1221108503259: hello from ejbTimeout 09-11-2008 00:48:23: SVR-TRACE: ejbStore 09-11-2008 00:48:23: SVR-TRACE: ejbPassivate 09-11-2008 00:48:55: TRACE: no message received WARN [ClientConsumer:668] Timed out waiting for last delivery 0 got -1