[jboss-dev-forums] [Design of Messaging on JBoss (Messaging/JBoss)] - Sporadic read timeouts for app client reading a msg sent fro

Thursday, 11 September 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@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
  | 

View the original post :
http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4175935#...

Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...

2026

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

[jboss-dev-forums] [Design of Messaging on JBoss (Messaging/JBoss)] - Sporadic read timeouts for app client reading a msg sent fro