I hope it is appropriate to attach the ok-call and failed-call chrome logs, captured using '--enable-logging --vmodule=*/webrtc/*=1' flags. Both have been gzip'ed for better upload size. The only difference between the 2 calls is the addition of a non-responsive STUN server to the working call setup.

Deleted: chrome_debug.log.fails.gz 33.6 KB

chrome_debug.log.fails.gz 33.6 KB Download

Deleted: chrome_debug.log.works.gz 39.1 KB

chrome_debug.log.works.gz 39.1 KB Download

Thanks for filing the issue!

@Reporter: Could you please provide sample Test File/URL that reproduces the issue which help in further triaging the issue in better way. If possible provide screencast of the issue which help in better understanding.

Thanks!

viswa.karala: it is very unlikely that a screencast is going to help with a problem that occurs at the network level.

davies147: do you use trickle ice? (even though the error sounds like the opposite of 'non-trickle does not work with a broken stun server)

No, we do not *actually* use trickle ice. Because the Asterisk endpoint does not support it, we collect ICE candidates for a finite (2 second max) period, add it to the generated offer, and pass it to the far-end. Asterisk will then respond with all ice candidates present in the SDP (as above).

I have just re-tried the test with all a=extmap: lines and with a=ice-options:trickle removed from the initial offer, but that makes no change.

Experimentally with a bit of guesswork involved, it appears that it is necessary to have called setRemoteDescription() before the icegatheringstatechange transitions from gathering => complete. If the icegatheringstatechange occurs first, then the setup fails.

Based on this theory I will attempt to "force the error" in an environment where Asterisk is not involved.

Thank you for providing more feedback. Adding the requester to the cc list.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

PS. I am happy to do a version bisect to pin down this issue to a more specific build but will need some pointers on how to do so if necessary/useful/required.

1) Sadly, I have failed to replicate this in a Chrome <-> Chrome environment, even replicating the ICE gather/collate mechanism, and ensuring that the order and timing of calls to the various methods is similar to our JsSIP <-> Asterisk scenario.

2) Interestingly, I have found a curious workaround! During setup we have events as follows:

signalingstate => have-local-offer
icegatherisngstate => gathering
... ice ...
iceconnectionstate => checking
icegatheringstate => complete
... setRemote ...
signalingstate => stable
iceconnectionstate => failed      <- ***
iceconnectionstate => completed

If I act upon failed (at ***), then I will close the connection. If I IGNORE the failed report, it immediately transitions to completed with only a 3ms delay in my tests!

I am attaching a debug log of the case when I ignore the 'failed' indication and allow the call to proceed.

Deleted: chrome_debug.log.workaround.gz 40.3 KB

chrome_debug.log.workaround.gz 40.3 KB Download

failed->completed sounds like a very buggy transition. You might want to look at wireshark dumps too (which are more accessible than chrome logs :-))

jonasolson: maybe this is related to your changes too?

Wireshark dump taken - timings should be pretty accurate as they use the same local system clock.

It would appear that the 'failed' event occurs in the small gap between all external STUN/TURN bindings completing and the receipt of the first host candidate's STUN response, and that it flips back to 'completed' as soon as a STUN response is received from the host candidate.

1st pcap attached, the significant events/timings are:

14:41:15.556 "checking" 
frame 490/491

14:41:15.641 "failed" (Ignored by user-agent)
frame 598

14:41:15.647 "completed"
frame 604

14:41:18.018 "closed" (By user)


I also did a really simple test with no external STUN/TURN specified. In this case 'failed' happens when Chrome sends the first host-binding request, and 'completed' happens immediately after that, even beforethe host-binding-success packet is received.

2nd pcap attached, the significant events/timings are:

14:56:40.682 "checking"
frame 6

14:56:40.763 "failed"  (Ignored by user-agent)
frame 17/18

14:56:40.764 "completed"
frame 17/18

14:56:42.568 "closed" (By user)


​Hope this helps.
Regards,
Steve

Deleted: webrtc_wireshark.pcapng.gz 86.9 KB

webrtc_wireshark.pcapng.gz 86.9 KB Download

Deleted: webrtc_wireshark_no_ice.pcapng.gz 47.2 KB

webrtc_wireshark_no_ice.pcapng.gz 47.2 KB Download

This issue is likely related to this WebRTC bug: https://bugs.chromium.org/p/webrtc/issues/detail?id=9218.

libwebrtc implementation reports the 'failed' state if all currently available candidate pairs fail the connectivity check. As a result, if STUN/TURN transaction is slow and delays the gathering and trickling process, while the gathered host candidate is not reachable from the remote peer, the remote peer would see a 'false-alarm' failure and then 'connected' if the later signaled other candidates are reachable.

As a result, the 'failed' state used not to be a terminal state. My suggestion is to have some waiting logic upon 'failed', combined with ICE restart to be robust.

jonasolsson@ has been recently working on making the interpretation of states consistent with the spec (which I believe has been introduced to M73 canary). For what is worth, there may be a caveat that if the new state signal prevents the transition from 'failed' to 'connected', forcing 'failed' to be a terminal state, Web apps could get stuck.

#11: does this only surface due to the recent changes in chrome?

Given the guidance we gave in the spec about restarting in https://github.com/w3c/webrtc-pc/pull/1910 shipping this would cause quite a number of undesirable restarts.

Jonas, can you take a look?

I think this behavior is incorrect per https://tools.ietf.org/html/draft-ietf-ice-trickle-21#section-8 - when trickling, we should only go to failed when we have received end-of-candidates. (and hence, failed should be a terminal state)

I think we should probably roll back the offending CL until we can figure out the exact path forward here.

Revert CL should be landing soon: https://chromium-review.googlesource.com/c/chromium/src/+/1418314

Great. That only rolls back the thing that wires up the new logic for the ICE states, so the actual root cause CL is elsewhere - we can let Jonas track that down.

davies147: can you try removing the 10.x host candidate from the asterisk description? Its a long shot but if that makes the failure go away might provide a bit more insight.

I removed the host candidate, which correctly forced the use of the relay entry (the net topology/NAT means that srflx cannot be used), but still observed the transition via the 'failed' state.

Now I've had some time to dig into this, and I'm really confused.

In order for us to emit failed on the new iceconnectionstate path (which 73 should have been on until the revert in #18) this check has to evaluate to true: https://cs.chromium.org/chromium/src/third_party/webrtc/p2p/base/p2p_transport_channel.cc?rcl=74ba99062c48b278675cfe52643719202296fddc&l=409

This means that writable_ has to have been true at some point while it's currently false.

writable_ is only set by SetWritable, which also logs a line containing "Changed writable_ to ". This line occurs exactly once in each of the submitted logs, when writable_ becomes true.

This definitely feels like a timing issue, one of our systems will work about 1 time in 10.

Looking at the same piece of code as referred to in comment#22 just below line 409, if

(has_been_writable_ == false && gathering_state_ == kIceGatheringComplete && has_connection == false)

which I believe is possible / true then this method can still return 'failed'. It does depend on how/when this method is triggered to re-evaluate the state.

Forgive me if the above is a naive interpretation, but it does also reflect that if I provide a broken/slow TURN server, then gathering_state_ will not yet be kIceGatheringComplete?

Never mind, some rubber duck debugging made things clearer. I think we're actually hitting this code path: https://cs.chromium.org/chromium/src/third_party/webrtc/p2p/base/p2p_transport_channel.cc?rcl=74ba99062c48b278675cfe52643719202296fddc&l=421

I.e. the gathering_state_ variable is kIceGatheringComplete, but we don't have any active connections. This seems to match the chrome_debug.log.fails log, where 
"[1:17:0116/174627.503729:INFO:p2ptransportchannel.cc(843)] P2PTransportChannel: 0, component 1 gathering complete"
occurs before AddConnection() gets called for the first time.

Is this a bug with gathering_state_, or did I misunderstand the meaning of "gathering complete"? I've implicitly assumed that once the gathering is completed no more connections will be added, which is why I made "gathering complete with no connections" map to failure.

gathering complete only means the local candidates have all been gathered but you can still create new pairs with newly trickled remote candidates.

That explains where I went wrong then, thanks! Since end-of-candidates signalling isn't implemented yet (see #11) we should probably avoid transitioning to completed at all for now. I'll tweak the webrtc guts and then I'll re-enable the new ice connection state. If we keep running into issues we can always revert to the old implementation again.