[jboss-jira] [JBoss JIRA] Commented: (JBMESSAGING-893) Failover valve logic flawed, causing MultiThreadFailoverTest.testMultiThreadFailoverSeveralThreadsTransacted() to loop forever

[Ovidiu Feodorov (JIRA)]

    [ http://jira.jboss.com/jira/browse/JBMESSAGING-893?page=comments#action_12354195 ] 
            
Ovidiu Feodorov commented on JBMESSAGING-893:
---------------------------------------------

Valve test that simulates the situation (and currently fails): FailoverValveTest.testConcurrentClose()

> Failover valve logic flawed, causing MultiThreadFailoverTest.testMultiThreadFailoverSeveralThreadsTransacted() to loop forever
> ------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: JBMESSAGING-893
>                 URL: http://jira.jboss.com/jira/browse/JBMESSAGING-893
>             Project: JBoss Messaging
>          Issue Type: Sub-task
>            Reporter: Ovidiu Feodorov
>         Assigned To: Clebert Suconic
>            Priority: Blocker
>             Fix For: 1.2.0.GA
>
>
> This is an analysis of the MultiThreadFailoverTest.testMultiThreadFailoverSeveralThreadsTransacted() failure
> 5 producers and 10 consumers concurrently send/receive messages transactionally, using a connection to server 1.
> At 20:18:23,484, the test kills server 1:
> 20:18:23,484 INFO  @main [MultiThreadFailoverTest] Killing server 1
> At 20:18:24,156, the first failure is detected, LocalThreadConsumer-6 that was sending a transaction to the server detects remoting failure:
> 20:18:24,156 DEBUG @LocalThreadConsumer-6 [MicroSocketClientInvoker] SocketClientInvoker[faa03e, bisocket://localhost:2808] got SocketException java.net.SocketException: Connection reset
> LocalThreadConsumer-6 triggers FailoverValveInterceptor and notifies FailoverCommandCenter of failure, that uses it to close the valve:
> 20:18:24,234 DEBUG @LocalThreadConsumer-6 [FailoverValveInterceptor] FailoverValve.ConnectionDelegate[5, SID=1] detected network failure, putting sendTransaction() on hold until failover completes
> 20:18:24,234 DEBUG @LocalThreadConsumer-6 [FailoverCommandCenter] failure detected by FailoverValve.ConnectionDelegate[5, SID=1]
> 20:18:24,234 TRACE @LocalThreadConsumer-6 [FailoverCommandCenter] FailoverCommandCenter[ConnectionState[5]] broadcasting FAILURE_DETECTED
> 20:18:24,234 DEBUG @LocalThreadConsumer-6 [FailoverCommandCenter] FailoverCommandCenter[ConnectionState[5]] initiating client-side failover
> 20:18:24,234 DEBUG @LocalThreadConsumer-6 [FailoverValve] FailoverValve[connectionID=5] closing ...
> However, the valve cannot be closed at this moment, since it's "busy", the write lock is taken by other threads, so LocalThreadConsumer-6 starts looping trying to close it.
> Concurrently, various other threads detect failure, in this order: LocalThreadConsumer-2 (20:18:25,234), @Thread-117 (connection validator thread, 20:18:25,328), LocalThreadConsumer-0 (20:18:26,234), LocalThreadProducer-1 (20:18:27,250), LocalThreadProducer-3 (20:18:28,250), LocalThreadProducer-2 (20:18:29,250), LocalThreadConsumer-9 (20:18:30,359), LocalThreadProducer-4 (20:18:31,359 ), LocalThreadConsumer-1 (20:18:32,375).
> They cannot close the valve, so they start looping.
> At 20:18:33,281, LocalThreadProducer-0 detects failure, and successfully closes the valve, and the client side fail-over begins:
> 20:18:33,281 DEBUG @LocalThreadProducer-0 [MicroSocketClientInvoker] SocketClientInvoker[faa03e, bisocket://localhost:2808] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 906 ms
> 20:18:33,281 DEBUG @LocalThreadProducer-0 [FailoverValveInterceptor] FailoverValve.ConnectionDelegate[5, SID=1] detected network failure, putting sendTransaction() on hold until failover completes
> 20:18:33,281 DEBUG @LocalThreadProducer-0 [FailoverCommandCenter] failure detected by FailoverValve.ConnectionDelegate[5, SID=1]
> 20:18:33,281 TRACE @LocalThreadProducer-0 [FailoverCommandCenter] FailoverCommandCenter[ConnectionState[5]] broadcasting FAILURE_DETECTED
> 20:18:33,281 DEBUG @LocalThreadProducer-0 [FailoverCommandCenter] FailoverCommandCenter[ConnectionState[5]] initiating client-side failover
> 20:18:33,281 DEBUG @LocalThreadProducer-0 [FailoverValve] FailoverValve[connectionID=5] closing ...
> 20:18:33,281 DEBUG @LocalThreadProducer-0 [FailoverValve] FailoverValve[connectionID=5] closed
> ...
> 20:18:34,281 TRACE @LocalThreadProducer-0 [FailoverCommandCenter] FailoverCommandCenter[ConnectionState[5]] broadcasting FAILOVER_STARTED
> 20:18:34,281 TRACE @LocalThreadProducer-0 [ClientLogInterceptor] invoking ClusteredConnectionFactoryDelegate[SIDs={0,2}].createConnectionDelegate(null, *****, 1)
> ...
> However, the threads that were trying to close the valve are still spinning, and they will, forever.
> For example:
> 20:18:40,250 WARN  @LocalThreadConsumer-2 [FailoverValve] FailoverValve[connectionID=6] could not close, trying again ...
> java.lang.Exception
>         at org.jboss.jms.client.FailoverValve.close(FailoverValve.java:160)
>         at org.jboss.jms.client.FailoverCommandCenter.failureDetected(FailoverCommandCenter.java:80)

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira