1357400 - ICE failed after state connected

Status: RESOLVED DUPLICATE of bug 1317946

(Core :: WebRTC: Networking, defect)

Description

[pierre.bodilis+github]

Attachment: ice_failed.pcap

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0
Build ID: 20170329150444

Steps to reproduce:

My set up involves Firefox and our VoIP PBX. (Firefox sends the INVITE, our PBX answers)
As we don't use ICE, I don't wait for firefox to get candidates to create an offer.

Here is the offer sent by firefox:

t=0 0
a=sendrecv
a=fingerprint:sha-256 D9:1D:D7:4D:AF:5B:BB:99:97:7F:CE:31:DB:72:36:7A:B3:98:C9:0D:9C:F8:D8:CD:ED:7A:48:38:A2:3C:7C:00
a=ice-options:trickle
a=msid-semantic:WMS *
m=audio 9 UDP/TLS/RTP/SAVPF 109 9 0 8 101
c=IN IP4 0.0.0.0
a=sendrecv
a=extmap:1/sendonly urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=fmtp:109 maxplaybackrate=48000;stereo=1;useinbandfec=1
a=fmtp:101 0-15
a=ice-pwd:93e49f242d7c7dbef36d77a828b683c5
a=ice-ufrag:80704c4b
a=mid:sdparta_0
a=msid:{fe451146-72b0-4ff9-a870-e9904ec91b97} {c0774c57-2f0e-456b-a02d-d716e067f7ba}
a=rtcp-mux
a=rtpmap:109 opus/48000/2
a=rtpmap:9 G722/8000/1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=setup:actpass
a=ssrc:166806762 cname:{90e5e831-1b13-4b04-8e3c-655e55b6a741}

Then, the ice callbacks are activated:
14:9:3.62   |DEBUG  |swsipvoip.mediahandler: ICE candidate, gathering "gathering", connection: "new"  base.js:600:227
14:9:3.63   |DEBUG  |swsipvoip.mediahandler: ICE candidate received: candidate:0 1 UDP 2122252543 192.168.166.90 57873 typ host  base.js:600:227
14:9:3.65   |DEBUG  |swsipvoip.mediahandler: ICE candidate, gathering "complete", connection: "new"  base.js:600:227
14:9:3.66   |DEBUG  |swsipvoip.mediahandler: ICE candidate received: candidate:0 2 UDP 2122252542 192.168.166.90 57874 typ host  base.js:600:227
14:9:3.67   |DEBUG  |swsipvoip.mediahandler: ICE candidate, gathering "complete", connection: "new"  base.js:600:227

The answer provided by our PBX:
v=0
o=- 1492513743164 1492513743164 IN IP4 62.39.100.132
s=-
t=0 0
a=ice-lite
a=fingerprint:sha-256 AE:B4:F2:C9:D8:3C:C5:C8:ED:8E:86:4E:D6:87:19:02:C9:A6:F8:67:11:6E:9D:BC:92:6C:1F:39:15:95:35:77
m=audio 20136 UDP/TLS/RTP/SAVPF 109
c=IN IP4 62.39.100.132
a=rtpmap:109 opus/48000/2
a=ptime:20
a=rtcp-mux
a=rtcp:20136 IN IP4 62.39.100.132
a=candidate:0 1 udp 2130706431 62.39.100.132 20136 typ host
a=candidate:0 2 udp 2130706430 62.39.100.132 20136 typ host
a=setup:passive
a=ice-ufrag:O0A9N2NsT2RmC6gG
a=ice-pwd:23TAfBLJBooftqhTcZGPFtGI
a=fmtp:109 maxplaybackrate=48000;stereo=1;useinbandfec=1
a=sendrecv

Finally, here is the answer fed to the browser:
Setting new answer: 
v=0
o=- 1492513743164 1492513743164 IN IP4 62.39.100.132
s=-
t=0 0
a=ice-lite
a=fingerprint:sha-256 AE:B4:F2:C9:D8:3C:C5:C8:ED:8E:86:4E:D6:87:19:02:C9:A6:F8:67:11:6E:9D:BC:92:6C:1F:39:15:95:35:77
m=audio 20136 UDP/TLS/RTP/SAVPF 109
c=IN IP4 62.39.100.132
a=rtpmap:109 opus/48000/2
a=fmtp:109 maxplaybackrate=48000;stereo=0;useinbandfec=1;maxaveragebitrate=28000
a=rtcp:20136 IN IP4 62.39.100.132
a=setup:passive
a=ptime:20
a=sendrecv
a=ice-ufrag:O0A9N2NsT2RmC6gG
a=ice-pwd:23TAfBLJBooftqhTcZGPFtGI
a=candidate:0 1 udp 2130706431 62.39.100.132 20136 typ host
a=candidate:0 2 udp 2130706430 62.39.100.132 20136 typ host
a=rtcp-mux

After a call to ontrack, the oniceconnectionstatechange is called:
14:9:3.730  |DEBUG  |swsipvoip.mediahandler: ICE connection state updated, gathering "complete", connection: "checking"  base.js:600:227
14:9:3.731  |DEBUG  |swsipvoip.mediahandler: ICE connection state updated, gathering "complete", connection: "connected"  base.js:600:227


And 10 second later, we see 
14:9:13.424 |DEBUG  |swsipvoip.mediahandler: ICE connection state updated, gathering "complete", connection: "failed"  base.js:600:227
14:9:13.434 |DEBUG  |swsipvoip.mediahandler: closing PeerConnection  base.js:600:227
14:9:13.436 |DEBUG  |swsipvoip.mediahandler: ICE connection state updated, gathering "complete", connection: "closed"  base.js:600:227






Actual results:

The ICE Connection state switches to "failed". Why is that? You'll find enclosed the wireshark traces capture, and I didn't see any trouble regarding the STUN requests and responses.

I failed to get the STUN logs (they are using a windows machine, and any attempt using linux did not reproduce the issue).


Expected results:

This behavior happens with both firefox 52 and 53, but seems to be fixed with firefox 54.
No chrome version fails.

What's wrong with this setup ?

Comment 1

[Dan Minor [:dminor]]

Nils, do you have any insights on this one? Thanks!

Comment 2

[Nils Ohlmeier [:drno]]

Thanks for the Wireshark trace, that helped to identify the issue right away.

This is duplicated of bug 1317946.

The issue causing the disconnect is that your PBX sends UDP packets with no payload at all as a keep alive for NATs. As you can see in bug 1317946 this causes problems if Firefox is running with multi process enabled.

So you basically have the following options at this point:
- turn off the empty UDP NAT keepalive packets in your PBX
- add some data to the UDP keepalive packet, so they are not longer 0 size
- try to dis-able e10s a.k.a. Multiprocess Windows (check on about:support), but I don't think that users can still control this
- upgrade your Firefox users to Firefox 54

Comment 3

[pierre.bodilis+github]

Thanks, will modify our PBX :)

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

If all your (older than FF 54) users are not on the same LAN as the PBX, you might be able to cheat and send the 0-payload 'prop-open' packets with a TTL barely more hops than the NAT is from the PBX ... i.e. the packets would hopefully never reach the firefox instances, but would prop open the NAT.

Likely that's not an option on your PBX though, or you have users behind the NAT.