5 Replies Latest reply on Sep 12, 2008 12:08 PM by timfox

    Sporadic read timeouts for app client reading a msg sent fro

    starksm64

      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
      



        • 1. Re: Sporadic read timeouts for app client reading a msg sent
          timfox

          Can you post the code of the test?

          I had a long chat with Jesper the other day about an ejb timer test which was sporadically failing?

          Is it the same one? The problem was the test was using receiveNoWait() rather than receive() as it should.

          • 2. Re: Sporadic read timeouts for app client reading a msg sent
            starksm64

            I'm not sure what Jesper is looking at, but this is doing a receive(timeout):

             QueueConnection connection = null;
            
             try {
             TestUtil.logTrace("getting connection");
             connection = qcFactory.createQueueConnection();
             QueueSession session = connection.createQueueSession(true, 0);
             TestUtil.logTrace("creating receiver");
             QueueReceiver receiver = session.createReceiver(queue);
             connection.start();
             return getMessage(receiver, timeout);
             } catch (Exception e) {
             handleException("Error receiving message", e);
             } finally {
             if (connection != null) {
             try {
             connection.close();
             } catch (Exception e) {
             handleException("Error closing queue connection", e);
             }
             }
             }
            ...
             public static String getMessage(QueueReceiver receiver, long timeout) {
            
             TextMessage msg;
             String message;
             int retries = 0;
            
             try {
            
             do {
             Message m = receiver.receive(timeout);
            
             if (m == null) {
             TestUtil.logTrace("no message received");
             return TimerImpl.NOMSGRECEIVED;
             }
             else {
             if (m instanceof TextMessage) {
             msg = (TextMessage) m;
             message = msg.getText();
             TestUtil.logTrace("Receiving message at " +
             System.currentTimeMillis() + ": " + message);
             String mTestName = msg.getStringProperty("testName");
             String testName = TestUtil.getProperty("testName");
             if (testName.equals(mTestName)) {
             TestUtil.logTrace("test name property of message is correct: accepting");
             return message;
             }
             TestUtil.logErr("message from " + mTestName + " received - ignoring");
             ++retries;
             }
             else {
             TestUtil.logErr("non-text message received!");
             ++retries;
             }
             }
             } while (retries < 5);
             TestUtil.logTrace("No valid message received after " + retries + " attempts");
            
             } catch (Exception e) {
             TimerImpl.handleException("Error receiving message", e);
             }
             return TimerImpl.NOMSGRECEIVED;
             }
            
            



            • 3. Re: Sporadic read timeouts for app client reading a msg sent
              timfox

              What value is timeout?

              My experience of Hudson is that timing tests are prone to sporadic failure, due. I'm not sure if that is due to large gc's kicking in, or because it's virtualized and over-stretched so the non real time nature of Java thread scheduling is massively exacerbated, but we've found we've had to increase timeouts to high values (several seconds) to "guarantee" receiving messages.

              BTW I've only seen this problem on Hudson.

              For JBM 2.0 we've extracted all our timing dependent tests into a single smaller test suite, which we're going to run on a non virtualized server. I believe Hudson already has one server group which is non virtualized (?)

              • 4. Re: Sporadic read timeouts for app client reading a msg sent
                starksm64

                The test is using a 60 second timeout, so there should not be an issue there. When the test runs the msg is obtained in millisecond timing, so 60 sec should be infinite.

                What is the best way to determine exactly why a msg is not recieved, client or server side trace logging?

                • 5. Re: Sporadic read timeouts for app client reading a msg sent
                  timfox

                  As much logging as possible would help.

                  IIRC some of those app server tests are very bad at clearing up their state. Perhaps a previous test has left behind a consumer after not closing its connection properly, and that consumer has nabbed the message instead of the one you expect. (I've seen this kind of thing before)

                  The server will eventually time out and close unclosed sessions, but if the next test kicks in before this occurs you might end up with these kind of issues.

                  Just a thought.