[Blink] Chat stream failed: MSRPBindSessionTimeout
Gaurav Nangla
Gaurav.Nangla at globallogic.com
Fri Mar 25 21:32:10 CET 2011
Hello,
We tried setting up a MSRP chat session between two blinks(let's call them Blink-1, Blink-2) with a SBC lying in the signalling and media paths.
As far as signalling plane(SBC-SP) is concerned the SBC sbove is in a strict B2BUA mode. In the media plane(SBC-MP) it's acting strictly as a relay (i.e. NAT-PT mode).
Now, the scenario we've setup is a special one.
It's a [RFC6135] MSRP Alternative Connection Model (ACM) scenario wherein we've ensured that OFFER and ANSWER both contain 'a=setup:active' attribute.
What this means is that the SBC will be receiving SYNs from both the Blinks and handling them using the 'TCP splicing' technique.
It's basically making both the UAs think that they've each initiated and setup a MSRP TCP connection.
The partial call flow below should clear up things a little more:
| 10.201.1.152(Blink-1) | 10.201.1.99(Blink-2) |
| |10.204.1.28(SBC-SP)| |10.207.1.100(SBC-MP)
| Request: INVITE sip | | |SIP/SDP: Request: INVITE sip:12345 at 10.204.1.28, with session description
|(5060)------------->(5060) | | |
| Status: 100 Trying | | |SIP: Status: 100 Trying
|(5060)<-------------(5060) | | |
| | Request: INVITE sip | |SIP/SDP: Request: INVITE sip:12345 at 10.201.1.99, with session description
| |(5060)------------->(5060) | |
| | Status: 100 Trying | |SIP: Status: 100 Trying
| |(5060)<-------------(5060) | |
| | Status: 180 Ringing | |SIP: Status: 180 Ringing
| |(5060)<-------------(5060) | |
| Status: 180 Ringing | | |SIP: Status: 180 Ringing
|(5060)<-------------(5060) | | |
| | Status: 200 OK | |SIP/SDP: Status: 200 OK, with session description
| |(5060)<-------------(5060) | |
| Status: 200 OK | | |SIP/SDP: Status: 200 OK, with session description
|(5060)<-------------(5060) | | |
| Request: ACK sip | | |SIP: Request: ACK sip:12345 at 10.204.1.28:5060
|(5060)------------->(5060) | | |
| | Request: ACK sip | |SIP: Request: ACK sip:12345 at 10.201.1.99
| |(5060)------------->(5060) | |
| 53502 > 15002 [SYN] | | |TCP: 53502 > 15002 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=3 TSV=856688003 TSER=0
|(53502)---------------------------------------------------->(15002) |
| | | 49838 > 15000 [SYN] |TCP: 49838 > 15000 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=3 TSV=971262787 TSER=0
| | |(49838)------------>(15000) |
| 15002 > 53502 [SYN, ACK] | | |TCP: 15002 > 53502 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 WS=3 TSV=856688003 TSER=0
|(53502)<----------------------------------------------------(15002) |
| | | 15000 > 49838 [SYN, ACK] |TCP: 15000 > 49838 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 WS=3 TSV=971262787 TSER=0
| | |(49838)<------------(15000) |
| | | 49838 > 15000 [ACK] |TCP: 49838 > 15000 [ACK] Seq=1 Ack=1 Win=524280 Len=0 TSV=971262787 TSER=971262787
| | |(49838)------------>(15000) |
| [TCP Dup ACK] | | |TCP: [TCP Dup ACK 921#1] 15002 > 53502 [ACK] Seq=1 Ack=1 Win=524280 Len=0 TSV=971262787 TSER=971262787
|(53502)<----------------------------------------------------(15002) |
| 53502 > 15002 [ACK] | | |TCP: 53502 > 15002 [ACK] Seq=1 Ack=1 Win=524280 Len=0 TSV=856688003 TSER=856688003
|(53502)---------------------------------------------------->(15002) |
| | | [TCP Dup ACK] |TCP: [TCP Dup ACK 922#1] 15000 > 49838 [ACK] Seq=1 Ack=1 Win=524280 Len=0 TSV=856688003 TSER=856688003
| | |(49838)<------------(15000) |
| Request: SEND Trans | | |MSRP: Request: SEND Transaction ID: 745f0cb1fb640e52
|(53502)---------------------------------------------------->(15002) |
| | | Request: SEND Trans |MSRP: Request: SEND Transaction ID: 745f0cb1fb640e52
| | |(49838)<------------(15000) |
| | | [TCP Dup ACK] |TCP: [TCP Dup ACK 923#1] 49838 > 15000 [ACK] Seq=1 Ack=1 Win=524280 Len=0 TSV=971262787 TSER=971262787
| | |(49838)------------>(15000) |
| [TCP Dup ACK 921#2] | | |TCP: [TCP Dup ACK 921#2] 15002 > 53502 [ACK] Seq=1 Ack=1 Win=524280 Len=0 TSV=971262787 TSER=971262787
|(53502)<----------------------------------------------------(15002) |
| | | Request: SEND Trans |MSRP: Request: SEND Transaction ID: 6ed1199a610a6a7d
| | |(49838)------------>(15000) |
| Request: SEND Trans | | |MSRP: Request: SEND Transaction ID: 6ed1199a610a6a7d
|(53502)<----------------------------------------------------(15002) |
| 53502 > 15002 [ACK] | | |TCP: 53502 > 15002 [ACK] Seq=227 Ack=226 Win=524280 Len=0 TSV=856688003 TSER=971262787
|(53502)---------------------------------------------------->(15002) |
| | | 15000 > 49838 [ACK] |TCP: 15000 > 49838 [ACK] Seq=227 Ack=226 Win=524280 Len=0 TSV=856688003 TSER=971262787
| | |(49838)<------------(15000) |
| | | [TCP Retransmission |MSRP: [TCP Retransmission] Request: SEND Transaction ID: 6ed1199a610a6a7d
| | |(49838)------------>(15000) |
| [TCP Retransmission | | |MSRP: [TCP Retransmission] Request: SEND Transaction ID: 6ed1199a610a6a7d
|(53502)<----------------------------------------------------(15002) |
| [TCP Dup ACK] | | |TCP: [TCP Dup ACK 935#1] 53502 > 15002 [ACK] Seq=227 Ack=226 Win=524280 Len=0 TSV=856688012 TSER=971262796
|(53502)---------------------------------------------------->(15002) |
| | | [TCP Dup ACK] |TCP: [TCP Dup ACK 936#1] 15000 > 49838 [ACK] Seq=227 Ack=226 Win=524280 Len=0 TSV=856688012 TSER=971262796
| | |(49838)<------------(15000) |
| [TCP Retransmission | | |MSRP: [TCP Retransmission] Request: SEND Transaction ID: 745f0cb1fb640e52
|(53502)---------------------------------------------------->(15002) |
| | | [TCP Retransmission |MSRP: [TCP Retransmission] Request: SEND Transaction ID: 745f0cb1fb640e52
| | |(49838)<------------(15000) |
| | | [TCP Dup ACK |TCP: [TCP Dup ACK 1027#1] 49838 > 15000 [ACK] Seq=226 Ack=1 Win=524280 Len=0 TSV=971262806 TSER=971262787
| | |(49838)------------>(15000) |
| [TCP Dup ACK | | |TCP: [TCP Dup ACK 1028#1] 15002 > 53502 [ACK] Seq=226 Ack=1 Win=524280 Len=0 TSV=971262806 TSER=971262787
|(53502)<----------------------------------------------------(15002) |
Now with reference to the above, I've got a few questions:
1. The 'SEND Transaction 745f0cb1fb640e52' from Blink-1 receives an incorrect 'Ack=1' from Blink-2 causing its retransmission. What could be the reason for this incorrect ACK from Blink-2?
(Also note above that we've relayed the final ACKs during the handshake from the Blinks to the other unnecessarily.)
2. Although 'SEND Transaction 6ed1199a610a6a7d' from BLink-2 does receive a correct ACK, the 'SEND' keeps getting retransmitted multiple times for some reason by Blink-2. What could be wrong here?
3. Is it possible that each Blink isn't sending a '200 OK' to the SENDs received because they're not expecting a SEND? i.e. are they only looking to do a SEND?
4. Does Blink support this likely scenario wherein they're both behind NATs and have no option but to use msrp-acm to resolve NAT issues (i.e. have no relays available)?
5. It appears Blink-2 is misbehaving i.e. it's sending a wrong ACK and keeps retransmitting an acknowledged TCP segment over and over again.
Its logs shows the following error: 'Chat stream failed: MSRPBindSessionTimeout'. Do you agree with this analysis?
Attached is the wireshark trace file and Blink logs are below. Hope this helps!
Gaurav
Blink-1 logs:
2011-03-25 15:36:44 [session to 12345] Changing Session state to CONNECTING
2011-03-25 15:36:44 [session to 12345] Connecting Session...
2011-03-25 15:36:44 Outgoing Session request to To: <sip:12345 at 10.204.1.28> (['chat'])
2011-03-25 15:36:47 [session to 12345] Session will start
2011-03-25 15:36:47 Chat stream established to msrp://10.207.1.100:15002/8e943e31a8e49a6597f0;tcp (12345)
2011-03-25 15:36:48 [session to 12345] Changing chat state to CONNECTED
2011-03-25 15:36:48 [session to 12345 at 10.204.1.28] Changing Session state to CONNECTED
2011-03-25 15:36:48 [session to 12345 at 10.204.1.28] Session started
2011-03-25 15:36:58 [session to 12345 at 10.204.1.28] Session will end (remote)
2011-03-25 15:36:58 [session to 12345 at 10.204.1.28] Changing Session state to FINISHED
2011-03-25 15:36:58 Session <sipsimple.session.Session object at 0x115fa310> ended, disposing...
2011-03-25 15:36:58 [session to 12345 at 10.204.1.28] Session ended
2011-03-25 15:36:58 Chat stream ended
2011-03-25 15:36:58 [session to 12345 at 10.204.1.28] Changing chat state to IDLE
Blink-2 logs:
2011-03-25 15:36:44 Incoming session from From: "56789" <sip:56789 at 10.204.1.28>;tag=3509990736-382361 with proposed streams chat
2011-03-25 15:36:47 Accepting session to From: "56789" <sip:56789 at 10.204.1.28>;tag=3509990736-382361
2011-03-25 15:36:47 [session to 56789] Handling incoming chat Stream
2011-03-25 15:36:47 [session to 56789] Changing chat state to INCOMING
2011-03-25 15:36:47 [session to 56789] Session will start
2011-03-25 15:36:57 Chat stream failed: MSRPBindSessionTimeout
2011-03-25 15:36:58 [session to 56789] Changing chat state to FAILED
2011-03-25 15:36:58 [session to 56789] Session will end (local)
2011-03-25 15:36:58 Chat stream ended
2011-03-25 15:36:59 [session to 56789] Changing Session state to FINISHED
2011-03-25 15:36:59 Session <sipsimple.session.Session object at 0x3439e30> ended, disposing...
2011-03-25 15:36:59 [session to 56789] Session ended
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ag-projects.com/pipermail/blink/attachments/20110326/2d0a6a69/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: blink_msrp.pcap
Type: application/x-extension-pcap
Size: 1000679 bytes
Desc: blink_msrp.pcap
URL: <http://lists.ag-projects.com/pipermail/blink/attachments/20110326/2d0a6a69/attachment.bin>
More information about the Blink
mailing list