Details
-
Bug
-
Status: Closed
-
Major
-
Resolution: Fixed
-
0.30, 0.32, qpid-java-6.0, qpid-java-6.0.2
-
None
Description
Unlike the 0-8 path, creating a JMS session Connection#createSession() does not take the failover mutex. This means that an application's call to createSession does not block whilst failover is in flight. This gives rise to a race between application's creation of the new session and the re-subscription of the existing sessions. In an unlucky case, this may cause the client to try and attach the same session twice. This will be rejected by the Broker with a SESSION_BUSY.
Following annotated log excerpt is from 6.0.2.
# Failover has just reconnected an application with existing JMS sessions, but failover is not yet 'finished' 2016-05-04 17:31:26,778 DEBUG [com/192.168.0.1:18575] [ Connection] RECV: [conn:eb35720] ch=0 ConnectionOpenOk(knownHosts=[]) 2016-05-04 17:31:26,779 INFO [com/192.168.0.1:18575] [ AMQConnection] Connection 1 now connected from /192.168.0.2:48956 to myhost.example.com/192.168.0.1:18 575 # Application thread gets in and creates a new session 2016-05-04 17:31:26,779 DEBUG [ app-listener-thread:01] [ Connection] SEND: [conn:eb35720] ch=2 SessionAttach(name="916a6c14-069f-4cd0-ba8b-dde789766864") 2016-05-04 17:31:26,779 DEBUG [ app-listener-thread:01] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,779 DEBUG [ app-listener-thread:01] [ Connection] SEND: [conn:eb35720] ch=2 SessionRequestTimeout(timeout=0) # Failover begins to 'rewire' the existing JMS objects 2016-05-04 17:31:26,780 INFO [com/192.168.0.1:18575] [ AMQConnectionDelegate_0_10] Resuming connection 2016-05-04 17:31:26,780 DEBUG [ app-listener-thread:01] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 SessionAttach(name="edd4afef-052f-4dfc-8af0-ca96a887977c") 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 SessionRequestTimeout(timeout=0) 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 SessionCommandPoint(commandId=12383, commandOffset=0) 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 id=12383 ExecutionSync() 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 SessionCommandPoint(commandId=12384, commandOffset=0) 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 SessionFlush(completed=true) 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=3 id=12384 TxSelect() 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] # DEFECT Failover treats the application's new session as if it were an existing one 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=4 SessionAttach(name="916a6c14-069f-4cd0-ba8b-dde789766864") 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,781 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=4 SessionRequestTimeout(timeout=0) 2016-05-04 17:31:26,782 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,782 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=4 SessionCommandPoint(commandId=0, commandOffset=0) 2016-05-04 17:31:26,782 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] 2016-05-04 17:31:26,782 DEBUG [com/192.168.0.1:18575] [ Connection] SEND: [conn:eb35720] ch=4 SessionFlush(completed=true) 2016-05-04 17:31:26,782 DEBUG [com/192.168.0.1:18575] [ Connection] FLUSH: [conn:eb35720] ... 2016-05-04 17:31:26,782 INFO [com/192.168.0.1:18575] [ AMQConnectionDelegate_0_10] Resubscribing sessions = [org.apache.qpid.client.AMQSession_0_10@2a3998ec, org.apache.qpid.client.A MQSession_0_10@4b230bb3] sessions.size=2 2016-05-04 17:31:26,783 DEBUG [com/192.168.0.1:18575] [ AMQSession] Resubscribing producers = [] producers.size=0 … # Broker rejects the attempt to attach the same session to the second transport 2016-05-04 17:31:26,798 DEBUG [com/192.168.0.1:18575] [ Connection] RECV: [conn:eb35720] ch=4 SessionDetached(name="916a6c14-069f-4cd0-ba8b-dde789766864", code=SESSION _BUSY)