[jboss-dev-forums] [Design of Messaging on JBoss (Messaging/JBoss)] - Sporadic read timeouts for app client reading a msg sent fro
scott.stark@jboss.org
do-not-reply at jboss.com
Thu Sep 11 13:38:45 EDT 2008
We 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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
|
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4175935#4175935
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4175935
More information about the jboss-dev-forums
mailing list