ICE failed with ICMP error (Windows only seems?)
Categories
(Core :: WebRTC: Networking, defect, P2)
Tracking
()
| Tracking | Status | |
|---|---|---|
| firefox67 | --- | fixed |
People
(Reporter: steven.yutang, Assigned: bwc)
References
Details
(Keywords: parity-chrome, platform-parity)
Attachments
(8 files)
User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.97 Safari/537.36 Vivaldi/2.4.1455.4
Steps to reproduce:
- Have client and server on the same LAN (host to host ICE works)
- Client CreateOffer with audio + stun + turn iceservers
- Client receives an answer SDP from server
- Client applies the sdp as the remote description
- wait
Actual results:
After a few ICE STUN messages (according to wireshark), FF stops sending/responding STUN, and no media is flowing. STUN seems to stop once FF starts TURN allocations.
ICE eventually fails.
In the about:webrtc log, I see:
(ice/INFO) ICE-PEER(PC:1550257820610000 (id=2147483666 url=https://testserver:8080/demo/conference.html):default): all checks completed success=1 fail=0
.... Some TURN allocation going on ...
(stun/INFO) STUN-CLIENT(relay(IP4:10.42.35.26:0/TCP|some_turn.com:443)::TURN): Timed out
(ice/INFO) ICE-PEER(PC:1550257820610000 (id=2147483666 url=https://testserver:8080/demo/conference.html):default): all checks completed success=0 fail=1
Expected results:
ICE should have succeeded and media should start flowing whether TURN fails or succeeds.
This works fine on Linux, and works fine with Chrome.
|
Reporter | |
Comment 1•5 years ago
|
||
|
|
Reporter | |
Comment 2•5 years ago
|
||
Comment on attachment 9044259 [details] Linux log that worked fine. insert 'ice' (registry) succeeded: ice insert 'ice.pref' (registry) succeeded: ice.pref insert 'ice.pref.type' (registry) succeeded: ice.pref.type insert 'ice.pref.type.srv_rflx' (UCHAR) succeeded: 0x64 insert 'ice.pref.type.peer_rflx' (UCHAR) succeeded: 0x6e insert 'ice.pref.type.host' (UCHAR) succeeded: 0x7e insert 'ice.pref.type.relayed' (UCHAR) succeeded: 0x05 insert 'ice.pref.type.srv_rflx_tcp' (UCHAR) succeeded: 0x63 insert 'ice.pref.type.peer_rflx_tcp' (UCHAR) succeeded: 0x6d insert 'ice.pref.type.host_tcp' (UCHAR) succeeded: 0x7d insert 'ice.pref.type.relayed_tcp' (UCHAR) succeeded: 0x00 insert 'stun' (registry) succeeded: stun insert 'stun.client' (registry) succeeded: stun.client insert 'stun.client.maximum_transmits' (UINT4) succeeded: 7 insert 'ice.trickle_grace_period' (UINT4) succeeded: 5000 insert 'ice.tcp' (registry) succeeded: ice.tcp insert 'ice.tcp.so_sock_count' (INT4) succeeded: 0 insert 'ice.tcp.listen_backlog' (INT4) succeeded: 10 insert 'ice.tcp.disable' (char) succeeded: \000 /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): failed to create passive TCP host candidate: 3 /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): failed to create passive TCP host candidate: 3 /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): failed to create passive TCP host candidate: 3 /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:173 function nr_socket_multi_tcp_create_stun_server_socket skipping UDP STUN server(addr:) /build/firefox-mzqi2a/firefox-65.0+build2/media/mtransport/third_party/nICEr/src/net/nr_socket_multi_tcp.c:617 function nr_socket_multi_tcp_listen failed with error 3 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): failed to create passive TCP host candidate: 3 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) has no stream matching stream PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9 ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(QlL8): setting pair to state FROZEN: QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/CAND-PAIR(QlL8): Pairing candidate IP4:10.42.37.57:36175/UDP (7e7f00ff):IP4:10.42.35.138:48335/UDP (780001ff) priority=8646913483524145663 (780001fffcfe01ff) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(T8CF): setting pair to state FROZEN: T8CF|IP4:172.17.0.1:49474/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:172.17.0.1:49474/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/CAND-PAIR(T8CF): Pairing candidate IP4:172.17.0.1:49474/UDP (7e7e00ff):IP4:10.42.35.138:48335/UDP (780001ff) priority=8646913483524014591 (780001fffcfc01ff) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(QlL8): setting pair to state WAITING: QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(T8CF): setting pair to state WAITING: T8CF|IP4:172.17.0.1:49474/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:172.17.0.1:49474/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/ICE-STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9): Starting check timer for stream. ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(QlL8): setting pair to state IN_PROGRESS: QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) is now checking ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) no streams with pre-answer requests STUN-CLIENT(QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host)): Received response; processing ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(QlL8): setting pair to state SUCCEEDED: QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1)/CAND-PAIR(QlL8): nominated pair is QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1)/CAND-PAIR(QlL8): cancelling all pairs but QlL8|IP4:10.42.37.57:36175/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:10.42.37.57:36175/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1)/CAND-PAIR(T8CF): cancelling FROZEN/WAITING pair T8CF|IP4:172.17.0.1:49474/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:172.17.0.1:49474/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) because CAND-PAIR(QlL8) was nominated. ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(T8CF): setting pair to state CANCELLED: T8CF|IP4:172.17.0.1:49474/UDP|IP4:10.42.35.138:48335/UDP(host(IP4:172.17.0.1:49474/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/ICE-STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9): all active components have nominated candidate pairs ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default): all checks completed success=1 fail=0 Firing write callback (0) Firing write callback (0) Firing write callback (0) Firing write callback (0) ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): Message does not correspond to any registered stun ctx UpdateBufferedAmount: (tracking 1): 0, waiting: no STUN-CLIENT(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)::TURN): Received response; processing STUN-CLIENT(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)::TURN): Error processing response: Retry may be possible, stun error code 401. UpdateBufferedAmount: (tracking 2): 0, waiting: no UpdateBufferedAmount: (tracking 1): 0, waiting: no STUN-CLIENT(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)::TURN): Received response; processing TURN(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)): Succesfully allocated addr IP4:10.9.230.115:60000/UDP lifetime=3600 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) pairing local trickle ICE candidate turn-relay(IP4:10.42.37.57:0/TCP|IP4:10.9.230.115:60000/UDP) ICE-PEER(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default)/CAND-PAIR(mKZ7): setting pair to state FROZEN: mKZ7|IP4:10.9.230.115:60000/UDP|IP4:10.42.35.138:48335/UDP(turn-relay(IP4:10.42.37.57:0/TCP|IP4:10.9.230.115:60000/UDP)|candidate:1 1 udp 2013266431 10.42.35.138 48335 typ host) ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/CAND-PAIR(mKZ7): Pairing candidate IP4:10.9.230.115:60000/UDP (7f1fff):IP4:10.42.35.138:48335/UDP (780001ff) priority=35782506145907710 (7f1ffff00003fe) Error in string: 14/16 Unable to parse NONCE STUN-CLIENT(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)::TURN): Received response; processing Missing MESSAGE-INTEGRITY STUN-CLIENT(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)::TURN): Error processing response: Operation rejected, stun error code 0. ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): Message does not correspond to any registered stun ctx UpdateBufferedAmount: (tracking 1): 0, waiting: no STUN-CLIENT(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)::TURN): Received response; processing STUN-CLIENT(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)::TURN): Error processing response: Retry may be possible, stun error code 401. UpdateBufferedAmount: (tracking 2): 0, waiting: no STUN-CLIENT(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)::TURN): Received response; processing TURN(relay(IP4:10.42.37.57:0/TCP|someturn.com:443)): Succesfully allocated addr IP4:10.9.230.115:13479/UDP lifetime=3600 ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) pairing local trickle ICE candidate turn-relay(IP4:10.42.37.57:0/TCP|IP4:10.9.230.115:13479/UDP) UpdateBufferedAmount: (tracking 1): 0, waiting: no Error in string: 13/16 Unable to parse NONCE STUN-CLIENT(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)::TURN): Received response; processing Missing MESSAGE-INTEGRITY STUN-CLIENT(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)::TURN): Error processing response: Operation rejected, stun error code 0. ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): Message does not correspond to any registered stun ctx Unrecognized attribute: 0x802b Unrecognized attribute: 0x802c STUN-CLIENT(srflx(IP4:10.42.37.57:36175/UDP|somestun.com:3478)): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) pairing local trickle ICE candidate srflx(IP4:10.42.37.57:36175/UDP|somestun.com:3478) Unrecognized attribute: 0x802b Unrecognized attribute: 0x802c STUN-CLIENT(srflx(IP4:172.17.0.1:49474/UDP|somestun.com:3478)): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) pairing local trickle ICE candidate srflx(IP4:172.17.0.1:49474/UDP|somestun.com:3478) Unrecognized attribute: 0x802b Unrecognized attribute: 0x802c STUN-CLIENT(srflx(IP4:10.42.37.57:57221/UDP|somestun.com:3478)): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) pairing local trickle ICE candidate srflx(IP4:10.42.37.57:57221/UDP|somestun.com:3478) Unrecognized attribute: 0x802b Unrecognized attribute: 0x802c STUN-CLIENT(srflx(IP4:172.17.0.1:44895/UDP|somestun.com:3478)): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) pairing local trickle ICE candidate srflx(IP4:172.17.0.1:44895/UDP|somestun.com:3478) STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): peer (PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?):default) Trickle grace period is over; marking every component with only failed pairs as failed. STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed STUN-CLIENT(relay(IP4:10.42.37.57:36175/UDP|someturn.com:3478)::TURN): Timed out TURN(relay(IP4:10.42.37.57:36175/UDP|someturn.com:3478)): mode 20, nr_turn_client_error_cb TURN(relay(IP4:10.42.37.57:36175/UDP|someturn.com:3478)) failed TURN(relay(IP4:10.42.37.57:36175/UDP|someturn.com:3478)): cancelling ICE-CANDIDATE(relay(IP4:10.42.37.57:36175/UDP|someturn.com:3478)): nr_turn_allocated_cb called with state 4 ICE-CANDIDATE(relay(IP4:10.42.37.57:36175/UDP|someturn.com:3478)): nr_turn_allocated_cb failed STUN-CLIENT(relay(IP4:172.17.0.1:49474/UDP|someturn.com:3478)::TURN): Timed out TURN(relay(IP4:172.17.0.1:49474/UDP|someturn.com:3478)): mode 20, nr_turn_client_error_cb TURN(relay(IP4:172.17.0.1:49474/UDP|someturn.com:3478)) failed TURN(relay(IP4:172.17.0.1:49474/UDP|someturn.com:3478)): cancelling ICE-CANDIDATE(relay(IP4:172.17.0.1:49474/UDP|someturn.com:3478)): nr_turn_allocated_cb called with state 4 ICE-CANDIDATE(relay(IP4:172.17.0.1:49474/UDP|someturn.com:3478)): nr_turn_allocated_cb failed STUN-CLIENT(relay(IP4:10.42.37.57:57221/UDP|someturn.com:3478)::TURN): Timed out TURN(relay(IP4:10.42.37.57:57221/UDP|someturn.com:3478)): mode 20, nr_turn_client_error_cb TURN(relay(IP4:10.42.37.57:57221/UDP|someturn.com:3478)) failed TURN(relay(IP4:10.42.37.57:57221/UDP|someturn.com:3478)): cancelling ICE-CANDIDATE(relay(IP4:10.42.37.57:57221/UDP|someturn.com:3478)): nr_turn_allocated_cb called with state 4 ICE-CANDIDATE(relay(IP4:10.42.37.57:57221/UDP|someturn.com:3478)): nr_turn_allocated_cb failed STUN-CLIENT(relay(IP4:172.17.0.1:44895/UDP|someturn.com:3478)::TURN): Timed out TURN(relay(IP4:172.17.0.1:44895/UDP|someturn.com:3478)): mode 20, nr_turn_client_error_cb TURN(relay(IP4:172.17.0.1:44895/UDP|someturn.com:3478)) failed TURN(relay(IP4:172.17.0.1:44895/UDP|someturn.com:3478)): cancelling ICE-CANDIDATE(relay(IP4:172.17.0.1:44895/UDP|someturn.com:3478)): nr_turn_allocated_cb called with state 4 ICE-CANDIDATE(relay(IP4:172.17.0.1:44895/UDP|someturn.com:3478)): nr_turn_allocated_cb failed STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed STUN-CLIENT(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)::TURN): Timed out TURN(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): mode 20, nr_turn_client_error_cb TURN(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)) failed TURN(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): cancelling ICE-CANDIDATE(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): nr_turn_allocated_cb called with state 4 ICE-CANDIDATE(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): nr_turn_allocated_cb failed STUN-CLIENT(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)::TURN): Timed out TURN(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): mode 20, nr_turn_client_error_cb TURN(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)) failed TURN(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): cancelling ICE-CANDIDATE(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): nr_turn_allocated_cb called with state 4 ICE-CANDIDATE(relay(IP4:172.17.0.1:0/TCP|someturn.com:443)): nr_turn_allocated_cb failed STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?)): Message does not correspond to any registered stun ctx STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed STUN-CLIENT(consent): Received response; processing ICE(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?))/STREAM(PC:1550175571570679 (id=2147483653 url=https://testserver:8080/demo/conference.html?) transport-id=transport_0 - a57015db:4bf6a16d5ac26f5a635b429e0c1319c9)/COMP(1): Consent refreshed +++++++ END ++++++++
|
||
Updated•5 years ago
|
|
|
Reporter | |
Comment 3•5 years ago
|
||
Tried on nightly as well and still fails 100% of the times. And as soon as we remove the turn server from ice servers, things work reliably.
Name Firefox
Version 67.0a1
Build ID 20190215095516
Update History
Update Channel nightly
User Agent Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0
OS Windows_NT 10.0
|
Assignee | |
Comment 4•5 years ago
|
||
Can you attach a wireshark capture for the windows case?
|
|
Reporter | |
Comment 5•5 years ago
|
||
|
|
Reporter | |
Comment 6•5 years ago
|
||
@Byron, I've attached a filtered wireshark capture. If you need more categories to be captured please let me know. I see the media server keeps trying with DTLS handshakes and the client (FF) seems to be ignoring them as well.
|
|
Assignee | |
Comment 7•5 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=008309fa9532bd9f10f6c3c5e15de6db0d2b8f8e
|
|
Assignee | |
Comment 8•5 years ago
|
||
So we definitely cannot reach the TURN server; we're getting ICMP errors, and after we get that ICMP error Firefox sends no packets from that port again. This looks exactly like bug 1448846, but that was fixed in 63.
I'm going to try making the error-handling for UDP yet more forgiving, and see what happens.
|
|
Reporter | |
Comment 9•5 years ago
|
||
Thank you Byron,
That's absolutely true that the turn udp port isn't reachable. What makes no sense is it makes the entire port unusable after that instead of the candidate itself. And the behaviour difference between Windows and Linux also seems strange, and I can confirm on linux I got the same icmp errors, over and over again, and media was uninterrupted.
|
|
Assignee | |
Comment 10•5 years ago
|
||
Ok, can you try either the 32 bit build here: https://queue.taskcluster.net/v1/task/d6dmZFP0Tr62YRmtQq3HuQ/runs/0/artifacts/public/build/install/sea/target.installer.exe
Or the 64 bit build here: https://queue.taskcluster.net/v1/task/frmqiElZRBiNmotnJ8vauQ/runs/0/artifacts/public/build/install/sea/target.installer.exe
If it still does not work, can you attach the console (stdout/stderr, not JS) output to this bug?
|
|
Reporter | |
Comment 11•5 years ago
|
||
Hi Byron, thanks for the quick turnaround, it seems I'm having issues running the build. The 32bit version was not allowed to be installed due to company AV software warning. And the 64bit was installed and fails to launch with the following error. Is there an official nightly build I could try?
DLL blocklist was unable to intercept AppInit DLLs.
Assertion failure: false (MOZ_ASSERT_UNREACHABLE: Opcode sequence includes commands after JMP), at z:/build/build/src/obj-firefox/dist/include/mozilla/interceptor/PatcherDetour.h:633
|
||
Comment 12•5 years ago
|
||
Steven, could you try this build instead? It's the same version but a 64-bit non-debug PGO build (optimized the same way as the official Nightly version). Non-debug means assertions like the one you hit are disabled.
|
|
Reporter | |
Comment 13•5 years ago
|
||
Thank you Andreas, I've just tried this build, and unfortunately the issue is still present. Is there anything particular you want me to capture (NSPR_LOG_MODULES=)? --console does not seem to have anything printed by default.
|
|
||
Comment 14•5 years ago
|
||
I'm not sure what modules would be useful in this part of the code. Let's ask Byron for next steps.
|
|
Assignee | |
Comment 15•5 years ago
|
||
Try running with MOZ_LOG=UDPSocket:4
|
|
Reporter | |
Comment 16•5 years ago
|
||
|
|
Reporter | |
Comment 17•5 years ago
|
||
Hi Bryon, I've attached the udpsocket logs and the wireshark from the same session.
|
|
Assignee | |
Comment 19•5 years ago
•
|
||
Unfortunately, the UDPSocket log isn't telling me anything useful. It would be really nice if we could get a debug build running, because that will output NS_WARNING to the console...
I can try adding some logging to UDPSocket.
|
|
Assignee | |
Comment 20•5 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c1c4769f98d40b18015a2fbb269e9fa7759fb8f2
|
|
Reporter | |
Comment 21•5 years ago
|
||
Hi Byron, I convinced our IT to whitelist the 32bit build you posted previously, however with the MOZ_LOG I only got a few lines of prints in the console during the test, which I've no idea if this is helpful.
Once we have a build with additional logging, I'll try again.
[Parent 12432, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 995
[Parent 12432, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file z:/build/build/src/layout/base/nsDocumentViewer.cpp, line 3215
(unknown/DEBUG) Address 0: IP6:[fe80::a969:af59:f2a1:7fec]:0/UDP on be03764e2f50b1d40383c43f98480f85, type: wired, estimated speed: 1000000 kbps
(unknown/DEBUG) Address 1: IP4:10.42.35.26:0/UDP on be03764e2f50b1d40383c43f98480f85, type: wired, estimated speed: 1000000 kbps
(unknown/DEBUG) Address 2: IP6:[::1]:0/UDP on 80c5fc6a8cefd529f7e1955e99b2d15c, type: unknown, estimated speed: 1073741 kbps
(unknown/DEBUG) Address 3: IP4:127.0.0.1:0/UDP on 80c5fc6a8cefd529f7e1955e99b2d15c, type: unknown, estimated speed: 1073741 kbps
[Parent 12432, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 126
[Parent 12432, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp, line 756
[Parent 12432, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
|
|
Assignee | |
Comment 22•5 years ago
|
||
So, I'm not seeing the NS_WARNING I would expect to see if we were running into bug 1448846. You could try the binaries in the try push in comment 20, but I doubt that will shine any more light on the situation. Can you attach the ICE logging from about:webrtc for the binary you tested in comment 21?
|
|
Reporter | |
Comment 23•5 years ago
|
||
|
|
Reporter | |
Comment 24•5 years ago
|
||
One more thing I tried yesterday was turning on logging to nsSocketTransport. Then I saw something like below (I think the send was the one receiving ICMP error). Does it mean that the socket wasn't in a bad state? As even after the ICE failure, I still saw the outFlags been set to 1, i.e. something is pending to be read? Could the problem be happening at a higher level?
[Parent 20316: Socket Thread]: D/UDPSocket nsUDPSocket::OnMsgAttach [this=000001D310BBF120]
[Child 21516: mtransport]: D/UDPSocket RecvCallbackOpened: 10.42.35.26:58380
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=000001D3160A0C00 outFlags=1]
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=000001D3160A0C00 status=804b0006]
[Child 21516: mtransport]: D/UDPSocket SendWithAddress: 44 bytes
....
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=000001D3160A0C00 outFlags=1]
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=000001D3160A0C00 status=804b0006]
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=000001D3160A0C00 status=804b0005]
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=000001D3160A0C00 outFlags=1]
[Parent 20316: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=000001D3160A0C00 status=804b0006]
|
|
Reporter | |
Comment 25•5 years ago
|
||
One more thing I noticed in the console was, not 100% of the times, I'll get the following error, does it make ICE fail always? could the TURN code that received the ICMP error incorrectly made ICE to fail completely?
ICE failed, your TURN server appears to be broken, see about:webrtc for more details.
|
|
Assignee | |
Comment 26•5 years ago
|
||
(In reply to Steven Tang from comment #24)
One more thing I tried yesterday was turning on logging to nsSocketTransport. Then I saw something like below (I think the send was the one receiving ICMP error). Does it mean that the socket wasn't in a bad state? As even after the ICE failure, I still saw the outFlags been set to 1, i.e. something is pending to be read? Could the problem be happening at a higher level?
I doubt it; STUN packets being sent to Firefox are getting ICMP errors, so the port is closed (or, at least Windows is deciding the port is not reachable).
|
|
Assignee | |
Comment 27•5 years ago
|
||
(In reply to Steven Tang from comment #25)
One more thing I noticed in the console was, not 100% of the times, I'll get the following error, does it make ICE fail always? could the TURN code that received the ICMP error incorrectly made ICE to fail completely?
ICE failed, your TURN server appears to be broken, see about:webrtc for more details.
That's an error that we print when ICE fails and the TURN server seems to be broken, so it doesn't tell us anything new unfortunately.
|
|
Reporter | |
Comment 28•5 years ago
|
||
(In reply to Byron Campen [:bwc] from comment #26)
(In reply to Steven Tang from comment #24)
One more thing I tried yesterday was turning on logging to nsSocketTransport. Then I saw something like below (I think the send was the one receiving ICMP error). Does it mean that the socket wasn't in a bad state? As even after the ICE failure, I still saw the outFlags been set to 1, i.e. something is pending to be read? Could the problem be happening at a higher level?
I doubt it; STUN packets being sent to Firefox are getting ICMP errors, so the port is closed (or, at least Windows is deciding the port is not reachable).
Good point, packet captures do show subsequent stuns to the socket being responded with ICMP errors. However, if the socket is indeed closed somehow, shouldn't firefox still be logging something for that? I guess unless it thinks it is a normal closure?
|
|
Reporter | |
Comment 29•5 years ago
|
||
If it is an issue at the system level, then I would expect Chrome would suffer the same issue. But according to wireshark, after the same ICMP error to the TURN port, Chrome is still sending/receiving stuns on the same port fine. I can attach a pcap if necessary.
|
|
Assignee | |
Comment 30•5 years ago
|
||
I guess try running with R_LOG_LEVEL=7 and R_LOG_DESTINATION=stderr as environment variables?
|
|
Assignee | |
Comment 31•5 years ago
|
||
(In reply to Steven Tang from comment #28)
(In reply to Byron Campen [:bwc] from comment #26)
(In reply to Steven Tang from comment #24)
One more thing I tried yesterday was turning on logging to nsSocketTransport. Then I saw something like below (I think the send was the one receiving ICMP error). Does it mean that the socket wasn't in a bad state? As even after the ICE failure, I still saw the outFlags been set to 1, i.e. something is pending to be read? Could the problem be happening at a higher level?
I doubt it; STUN packets being sent to Firefox are getting ICMP errors, so the port is closed (or, at least Windows is deciding the port is not reachable).
Good point, packet captures do show subsequent stuns to the socket being responded with ICMP errors. However, if the socket is indeed closed somehow, shouldn't firefox still be logging something for that? I guess unless it thinks it is a normal closure?
I would have expected us to hit some of the NS_WARNING logging in this case, yes.
|
|
Reporter | |
Comment 32•5 years ago
|
||
Attached the logs.
Also read an old ticket from chromium, and looks like it was something Chrome encountered as well.
|
|
Reporter | |
Comment 33•5 years ago
|
||
Not an expert of the FF source, so just wondering, if what the chromium ticket said was true, then wouldn't the code below be a problem? count is unsigned, and PR_RecvFrom can return -1?
uint32_t count;
char buff[9216];
count = PR_RecvFrom(mFD, buff, sizeof(buff), 0, &prClientAddr,
PR_INTERVAL_NO_WAIT);
mByteReadCount += count;
|
|
Assignee | |
Comment 34•5 years ago
|
||
(In reply to Steven Tang from comment #33)
Not an expert of the FF source, so just wondering, if what the chromium ticket said was true, then wouldn't the code below be a problem? count is unsigned, and PR_RecvFrom can return -1?
uint32_t count;
char buff[9216];
count = PR_RecvFrom(mFD, buff, sizeof(buff), 0, &prClientAddr,
PR_INTERVAL_NO_WAIT);
mByteReadCount += count;
Ok, that's completely broken, and could cause the logging I'm seeing! Let me try spinning a fix.
|
|
Assignee | |
Comment 35•5 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=08e37dcd6d105eb14c1b166ab5763a70d3efd883
|
|
Reporter | |
Comment 37•5 years ago
|
||
I was excited trying this new build, but unfortunately, I'm not seeing much difference. As soon as the ICMP error hits, all traffic on that port goes. The last patch also did not add a print to the -1 case, so I'm unsure if we've caught that error case or not.
[Child 24284: mtransport]: D/UDPSocket Bind: 10.42.35.26:0
[Parent 21840: IPDL Background]: D/UDPSocket RecvBind: 10.42.35.26:0
[Parent 21840: IPDL Background]: D/[this=2205E100] 10.42.35.26:0 addressReuse: 0 loopback: 0 recvBufferSize: 0, sendBufferSize: 0
[Parent 21840: IPDL Background]: D/UDPSocket RecvBind: SendCallbackOpened: 10.42.35.26:60605
[Parent 21840: Socket Thread]: D/[this=22066C40]
[Child 24284: mtransport]: D/UDPSocket RecvCallbackOpened: 10.42.35.26:60605
[Child 24284: mtransport]: D/UDPSocket Bind: 10.42.35.26:0
[Parent 21840: IPDL Background]: D/UDPSocket RecvBind: 10.42.35.26:0
[Parent 21840: IPDL Background]: D/[this=28ECD9C0] 10.42.35.26:0 addressReuse: 0 loopback: 0 recvBufferSize: 0, sendBufferSize: 0
[Parent 21840: IPDL Background]: D/UDPSocket RecvBind: SendCallbackOpened: 10.42.35.26:60606
[Parent 21840: Socket Thread]: D/[this=28ECB200]
[Child 24284: mtransport]: D/UDPSocket RecvCallbackOpened: 10.42.35.26:60606
[Child 24284: mtransport]: D/UDPSocket SendWithAddress: 20 bytes
[Child 24284: mtransport]: D/UDPSocket SendWithAddress: 96 bytes
[Parent 21840: IPDL Background]: D/[this=2928FC00], len 84
[Parent 21840: IPDL Background]: D/UDPSocket OnPacketReceived: 10.236.81.124:10877, length 84
[Child 24284: mtransport]: D/UDPSocket RecvCallbackReceivedData: 10.236.81.124:10877 length 84
[Child 24284: mtransport]: D/UDPSocket SendWithAddress: 44 bytes
[Child 24284: mtransport]: D/UDPSocket SendWithAddress: 20 bytes
[Child 24284: mtransport]: D/UDPSocket SendWithAddress: 44 bytes
|
|
Reporter | |
Comment 38•5 years ago
|
||
Looking at the Chromium change, it looks like the fix applies to both sendTo and recvFrom. And looking at the FF code, in the send case, the error would get propagated back to the higher level, and my guess is NrUdpSocketIpc::sendto_i would then mark the socket as failed as well. Do you think that's also a possibility? Could you add logging to both the failure cases of sendto and recvfrom?
|
|
Assignee | |
Comment 39•5 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5dda2c7b70b10bcf2cf074a5005016df7d960630
|
|
Reporter | |
Comment 40•5 years ago
|
||
I got another log with mtransport logging level bumpped up. It looks like on Windows after the ICMP error, the sendto is constantly returning an error, while on linux that isn't seen.
Bad log from Windows:
Child 19736: Socket Thread]: V/transport_0(none)];dtls]: Receive would have blocked
Child 19736: mtransport]: D/UDPSocket SendWithAddress: 44 bytes
Child 19736: Socket Thread]: V/mtransport Successfully protected an SRTCP packet of len 28
Child 19736: Socket Thread]: E/mtransport Couldn't send media on 'PC:1550683043014000 (id=4294967301 url=https://bbm-dev-conf.bbm.orion.altus.bblabs/demo/) transport-id=transport_0'
Child 19736: Socket Thread]: V/mtransport Successfully protected an SRTCP packet of len 60
Child 19736: Socket Thread]: E/mtransport Couldn't send media on 'PC:1550683043014000 (id=4294967301 url=https://bbm-dev-conf.bbm.orion.altus.bblabs/demo/) transport-id=transport_0'
Good log from Linux:
Child 2406: Socket Thread]: V/transport_0(none)];dtls]: Receive would have blocked
Child 2406: Socket Thread]: V/transport_0(none)];ice]: PacketReceived(PC:1550684821607748 (id=2147483652 url=https://bbm-dev-conf.bbm.orion.altus.bblabs/demo/) transport-id=transport_0,1,31)
Child 2406: Socket Thread]: V/transport_0(none)];dtls]: PacketReceived(31)
Child 2406: Socket Thread]: V/mtransport Successfully unprotected an SRTP packet of len 15
Child 2406: Socket Thread]: D/webrtc_trace (rtp_receiver_audio.cc:151): Received first audio RTP packet
Child 2406: Socket Thread]: D/webrtc_trace (neteq_impl.cc:2044): SetSampleRateAndChannels 48000 2
Parent 2331: IPDL Background]: D/this=0x7f49b94a7df0], len 31
Parent 2331: IPDL Background]: D/UDPSocket OnPacketReceived: 10.236.81.124:10018, length 31
Child 2406: mtransport]: D/UDPSocket RecvCallbackReceivedData: 10.236.81.124:10018 length 31
Child 2406: Socket Thread]: V/transport_0(none)];ice]: PacketReceived(PC:1550684821607748 (id=2147483652 url=https://bbm-dev-conf.bbm.orion.altus.bblabs/demo/) transport-id=transport_0,1,31)
Child 2406: Socket Thread]: V/transport_0(none)];dtls]: PacketReceived(31)
Child 2406: Socket Thread]: V/mtransport Successfully unprotected an SRTP packet of len 15
Child 2406: Unnamed thread 0x7fc6059c1a60]: D/webrtc_trace (rtp_sender_audio.cc:248): First audio RTP packet sent to pacer
Child 2406: Socket Thread]: V/mtransport Successfully protected an SRTCP packet of len 60
Child 2406: Socket Thread]: V/transport_0(none)];ice]: SendPacket(60) succeeded
|
|
Assignee | |
Comment 41•5 years ago
|
||
The logging from comment 32 shows me that the reason sendto is failing is because the socket had been marked closed earlier, right after the ALLOCATE request was sent.
|
|
Reporter | |
Comment 42•5 years ago
|
||
Indeed, with R_LOG I see. (generic/DEBUG) UDP socket closed this=176FCF10 right after the send, so somehow the socket gets closed after the sendto, which received the ICMP error. I'm not sure where that code is, as it seems to be buried under all the IPC socket stuff.
|
|
Reporter | |
Comment 43•5 years ago
|
||
Another log, and I think it is narrowed down quite a bit, but it is now very confusing. It looks like indeed the issue happened in DoPollIteration after the active handler gets the OnSocketReady and the condition becomes failed. However, your change should have addressed that or should at least log something.
D/UDPSocket nsUDPSocket::OnMsgAttach [this=33EC1020]
D/nsSocketTransport nsSocketTransportService::AttachSocket [handler=33EC1020]
D/nsSocketTransport nsSocketTransportService::AddToIdleList [handler=33EC1020]
D/nsSocketTransport idle [0] { handler=33EC1020 condition=0 pollflags=5 }
D/nsSocketTransport nsSocketTransportService::AddToPollList [handler=33EC1020]
D/nsSocketTransport SocketContext::EnsureTimeout socket=33EC1020
D/nsSocketTransport engaging
D/nsSocketTransport active=19 idle=1
D/nsSocketTransport nsSocketTransportService::RemoveFromIdleList [handler=33EC1020]
26:52123/UDP|)::TURN): Sending to IP4:208.65.74.115:3478/UDP [44]=000300182112a442cf993a55c23456f17ae692170019000411000000000d000400000e1080280004b564c40f
(stun/D/UDPSocket SendWithAddress: 44 bytes
D/nsSocketTransport SocketContext::TimeoutIn socket=33EC1020, timeout=65535s
D/nsSocketTransport active [18] { handler=33EC1020 condition=0 pollflags=5 }
D/nsSocketTransport SocketContext::EnsureTimeout socket=33EC1020
D/nsSocketTransport SocketContext::TimeoutIn socket=33EC1020, timeout=65535s
D/nsSocketTransport SocketContext::DisengageTimeout socket=33EC1020
D/nsSocketTransport nsSocketTransportService::DetachSocket [handler=33EC1020]
D/nsSocketTransport nsSocketTransportService::RemoveFromPollList [handler=00000000]
(generic/DEBUG) UDP socket closed this=17C55F1
|
|
Reporter | |
Comment 44•5 years ago
|
||
(In reply to Byron Campen [:bwc] from comment #36)
Can you try this binary?
Hey Byron, are you sure this is the right build? I tried the target.zip I grabbed yesterday for the 32bit windows for the try build rev 08e37dcd6d10, and it worked. I didn't bother trying it until now as you sent the installer instead.
|
|
Reporter | |
Comment 45•5 years ago
|
||
Okay, I grabbed the build with the last revision, 5dda2c7b70b10bcf2cf074a5005016df7d960630, and got the following log, and issue is fixed.
@Byron, let me know if you want me to try a final installer to be 100% sure.
2019-02-20 21:12:49.462000 UTC - [Parent 20388: Socket Thread]: D/nsSocketTransport SocketContext::DisengageTimeout socket=000001C381CC3970
2019-02-20 21:12:49.463000 UTC - [Parent 20388: Socket Thread]: D/UDPSocket nsUDPSocket::OnSocketReady: PR_RecvFrom returned no data [this=000001C381CC3970]
s2019-02-20 21:12:38.919000 UTC - [Parent 20388: Socket Thread]: D/nsSocketTransport active [18] { handler=000001C381CC3970 condition=0 pollflags=5 }
|
|
Reporter | |
Comment 46•5 years ago
|
||
(In reply to Steven Tang from comment #44)
(In reply to Byron Campen [:bwc] from comment #36)
Can you try this binary?
Hey Byron, are you sure this is the right build? I tried the target.zip I grabbed yesterday for the 32bit windows for the try build rev 08e37dcd6d10, and it worked. I didn't bother trying it until now as you sent the installer instead.
Pretty sure this build is from the initial change, c1c4769f98d4.
Task: YL29bkBlSH2fJr89kEvCAw
Build: - windows2012-32 -
Job name: build-win32/opt
Requested: Tue, Feb 19, 10:01:04
Started: Tue, Feb 19, 10:06:36
Ended: Tue, Feb 19, 11:02:25
|
|
Assignee | |
Comment 47•5 years ago
|
||
Ok, so it looks like we have a solution, plus some logging improvements. I'll put it up for review.
|
|
Assignee | |
Comment 48•5 years ago
|
||
|
|
Reporter | |
Comment 49•5 years ago
|
||
(In reply to Byron Campen [:bwc] from comment #47)
Ok, so it looks like we have a solution, plus some logging improvements. I'll put it up for review.
Excellent! Thanks again for the help!
|
||
Updated•5 years ago
|
|
|
Assignee | |
Comment 50•5 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=de5cf23e12f1fac9b2c05ed9eec74782141a2281
|
||
Comment 51•5 years ago
|
||
Pushed by bcampen@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d158405da514 Logging improvements in nsUDPSocket, and handle negative returns from PR_RecvFrom properly. r=mayhemer
|
||
Comment 52•5 years ago
|
||
Backed out changeset d158405da514 (bug 1528352) for perma failing test_udpsocket.js
push that caused the failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&selectedJob=230861225&revision=d158405da51437dd36d5ce3e946fc1cc6f54ed38
backout: https://hg.mozilla.org/integration/autoland/rev/cce8077b2174bc21e2ab776a40fbb541635d050c
|
|
Assignee | |
Comment 53•5 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=52fed581fc43b20350dc74f65b43d0df29b0297e
|
|
Assignee | |
Comment 55•5 years ago
|
||
I don't know why the try links that mach puts in bugzilla aren't working reliably, but here's one that does work:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=251bb9bdc990d42e4d04be4b8e754f840bcf1e5c
|
|
||
Comment 56•5 years ago
|
||
Pushed by bcampen@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/99eceab65655 Logging improvements in nsUDPSocket, and handle negative returns from PR_RecvFrom properly. r=mayhemer
|
|
Assignee | |
Updated•5 years ago
|
|
||
Comment 57•5 years ago
|
||
| bugherder | ||
Description
•