10% of calls have one way audio - iceConnectionStateChange stuck in ICEConnectionStateChecking

[Leif Einar Aune]

I am having issues with sporadic one-way audio behaviour using SIPml5 webRTC client and Asterisk PBX. These are pure audio calls, no video involved. 

The missing audio flow is always in the webRTC to asterisk direction.

The behaviour seems to occur approximately 1 out of 10 calls. It has been tested on Mac OS 10.8 and Windows 7 with Chrome  31.0.1650.57, Asterisk version 11.6.0 running on CentOS 6.4.

The webRTC is behind a NAT router, the Asterisk server directly on public IP.

Single STUN server is configured on client.

What happens is:

1. Incoming call is routed from Asterisk to WebRTC client (both from SIP client and mobile phones)
2. createAnswer() is called
3. iceConnectionStateChange enters ICEConnectionStateChecking
4. WebRTC sends STUN binding request towards Asterisk on the ports sent in the SDP offer
5. Asterisk replies with STUN binding response
6. onIceCandidate callback is called 6 times (2 with the local address, 2 with the client public address and 2 with the srflx entries)
7. iceGatheringStateChange enters ICEGatheringStateComplete
   
8. The local SDP is sent to Asterisk (as reply to the SIP INVITE)
9. Asterisk starts sending STUN binding requests
10. WebRTC replies with STUN binding response
11. Audio flows from Asterisk to webRTC
12. No Audio flows from webRTC to Asterisk. iceConnectionState is still in 

    ICEConnectionStateChecking state. 

The flow seems identical to when it indeed is working, except that in 12) the state enters ICEConnectionStateConnected and WebRTC ships the audio packets.

When the problem arises the audioInputLevel is showns as 0 in chrome://webrtc-internals/, but that should be a consequence of not entering ICEConnectionStateConnected.

I have attached pcap files capturing the UDP traffic on the webRTC side as well as on the asterisk side, and you can see that the STUN binding requests sent from Asterisk are responded by the webRTC stack.

I am observing that step 4 and 5 is repeated periodically, whereas 9 and 10 is repeated with a burst of around ten request/responses and not repeated further. As webRTC is sending the responses it indeed seems like the stack has received the STUN binding request and confirmed them?

Any hints as to how to proceed further to get a more stable audio flow are appreciated.

Best Regards

Leif Einar

[Justin Uberti]

See https://code.google.com/p/webrtc/issues/detail?id=1593. It is possible that this is still not fixed in Asterisk.

--
 
---
You received this message because you are subscribed to the Google Groups "discuss-webrtc" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss-webrt...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Leif Einar Aune]

Thanks for replying.

I do not think this is the same issue, as the audio sent from the Asterisk PBX is played nicely in the webRTC client.

Both Asterisk and webRTC are replying positive to the STUN binding requests - I would except one of them to complain if the peer uses the same port for RTP and RTCP.

The SDP offer from Asterisk (although different than the session in the PCAP files):

09:10:18,876 DEBUG [WebPhone:SIPml5] recv=INVITE sip:9...@df7jal23ls0d.invalid;rtcweb-breaker=no;transport=ws SIP/2.0

Via: SIP/2.0/WS 92.42.68.57:5060;rport;branch=z9hG4bK2b99c4dd

From: "91194712"<sip:9119...@92.42.68.57>;tag=as208bb1a0

To: <sip:9...@df7jal23ls0d.invalid;rtcweb-breaker=no;transport=ws>

Contact: <sip:9119...@92.42.68.57:5060;transport=WS>

Call-ID: 57fde61179bd404b...@92.42.68.57:5060

CSeq: 102 INVITE

Content-Type: application/sdp

Content-Length: 590

Max-Forwards: 70

User-Agent: FPBX-2.11.0(11.4.0)

Date: 18 Nov 2013 08:10:18 GMT;18

Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,SUBSCRIBE,NOTIFY,INFO,PUBLISH

Supported: replaces,timer

v=0

o=root 1038298680 1038298680 IN IP4 92.42.68.57

s=Asterisk PBX 11.4.0

c=IN IP4 92.42.68.57

t=0 0

m=audio 10034 RTP/SAVPF 8 0 3 101

a=rtpmap:8 PCMA/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:3 GSM/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

a=ice-ufrag:571b25b313c0112f62b9848f27e87fcc

a=ice-pwd:261762826ad1ae643cf029be5964b198

a=candidate:H5c2a4439 1 UDP 2130706431 92.42.68.57 10034 typ host

a=candidate:H5c2a4439 2 UDP 2130706430 92.42.68.57 10035 typ host

a=sendrecv

a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:u4+FHzMUgh0T/Vbr3CKW2yjP+oYHWGS01wkWPKOZ

[Justin Uberti]

OK. Looking closer, I see that both sides think they are the ICE controlled side, but Asterisk should be the controlling side, since it is the offerer. This prevents Chrome from completing ICE.

If you look at Chrome logs, you might see some errors to this effect.

[Leif Einar Aune]

Thanks, Justin.

Clearly, Asterisk should have sent the ICE-CONTROLLING attribute.

However, there are two things that then puzzles me:

1) I have attached a pcap file for a working session, and Asterisks behaves the same way - sending ICE-CONTROLLED attribute. In this case webRTC follows up a STUN request and picks the controlling side of the ICE negotiation. So why is this behaviour normally taking place, except in aprox 10% of the calls?

2) Reading RFC 5245, chapter 7.2.1.1 defines the procedure if both the candidates claims the same role. In case of both claiming to be the controlled side, the one with the highest tie-breaker value should switch to be the controlling side. From the first pcap files:

tie-breaker value sent from Asterisk:  0a:d1:db:d2:5f:7b:d3:b7

tie-breaker value sent from webRTC: 96:44:b5:78:c3:25:26:0a

This should mean that webRTC should switch to be the controlling role - right?

The RFC also says that the one with the smallest tie-breaker value should send a STUN ERROR-CODE with value 487. I would interpret this as failure number two Asterisk is doing (sending a STUN binding success response instead in this case).

I will try to patch Asterisk with correct ICE behaviour to see if it improves the situation.

I still can't figure out why 90% of the calls does not experience any issues, though.

Leif Einar

On Wednesday, November 27, 2013 1:54:04 AM UTC+1, Justin Uberti wrote:

OK. Looking closer, I see that both sides think they are the ICE controlled side, but Asterisk should be the controlling side, since it is the offerer. This prevents Chrome from completing ICE.

If you look at Chrome logs, you might see some errors to this effect.

On Tue, Nov 26, 2013 at 1:17 PM, Leif Einar Aune <leif....@telemagic.no> wrote:

Thanks for replying.

I do not think this is the same issue, as the audio sent from the Asterisk PBX is played nicely in the webRTC client.

Both Asterisk and webRTC are replying positive to the STUN binding requests - I would except one of them to complain if the peer uses the same port for RTP and RTCP.

The SDP offer from Asterisk (although different than the session in the PCAP files):

09:10:18,876 DEBUG [WebPhone:SIPml5] recv=INVITE sip:9...@df7jal23ls0d.invalid;rtcweb-breaker=no;transport=ws SIP/2.0

Via: SIP/2.0/WS 92.42.68.57:5060;rport;branch=z9hG4bK2b99c4dd

From: "91194712"<sip:91...@92.42.68.57>;tag=as208bb1a0

To: <sip:9...@df7jal23ls0d.invalid;rtcweb-breaker=no;transport=ws>

Contact: <sip:9119...@92.42.68.57:5060;transport=WS>

Call-ID: 57fde61179bd404b20e418cd529c6cf...@92.42.68.57:5060

[ebu...@cafex.com]

If you're still having any issues, we found a similar problem when our software was in the controlled mode when calling Chrome after a change a little while back that meant Chrome changed roles. We tracked it down to a timing issue where if we sent it a STUN binding success too close to a binding request that got Chrome to change role, it would get confused and exhibit the symptoms you described (except we saw failures between 20-100% depending on exactly how we were responding to STUN). We worked around it by not responding to binding requests until after we have had a binding success.

Eric

--------------------

Note: The information contained in this message may be privileged and confidential and protected from disclosure. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited. If you have received this communication in error, please notify us immediately by replying to the message and deleting it from your computer.  Thank you.  CafeX Communications.

[Victor de Torres]

you got it? Is it possible to modify the timing requests or not responding to binding request until you have binding success?

This issue makes me crazy.

[Alex Ballesté]

We have the same issue. But it's more than 10% in some cases. Do you got any solution?

Thanks 

[desmond...@twinehealth.com]

Sorry to bother for such an old thread. I am curious if there were others having what seems to be a race condition that is keeping the ICEConnectionState to be stuck in 'checking'? 

[Samuel Thompson]

I have spent 2 weeks trying to figure this stuff out. I have nothing! After an update to Asterisk it works MOST of the time. There is a failure only 5% of the time, but that is enough to piss off customers.