1487278 - Intermittent PID 11358 | Assertion failure: transceiver->IsAssociated() (ICE candidate was gathered before the transceiver was associated! This should never happen.) at /builds/worker/workspace/build/src/media/webrtc/signaling/src/jsep/JsepSessionImpl.cpp

Status: RESOLVED FIXED

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: csabou [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=196532731&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/Q8lzC8G9StaGtDVKYyCwRA/runs/0/artifacts/public/logs/live_backing.log

[task 2018-08-29T23:10:22.761Z] 23:10:22     INFO - PID 11358 | (ice/WARNING) ICE(PC:1535584222090495 (id=4294967543 url=https://web-platform.test:8443/webrtc/RTCRtpTransceiver.https.html)): local addresses already set, no work to do
[task 2018-08-29T23:10:22.762Z] 23:10:22     INFO - PID 11358 | [Child 11444: Socket Thread]: I/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:731: a32bea1a82121ea1| Transmit audio[{b92886af-12c9-43ac-aa01-047c6c84adc9}] in DetachTransport_s
[task 2018-08-29T23:10:22.763Z] 23:10:22     INFO - PID 11358 | [Child 11444: Socket Thread]: I/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:731: a32bea1a82121ea1| Receive audio in DetachTransport_s
[task 2018-08-29T23:10:22.764Z] 23:10:22     INFO - PID 11358 | [Child 11444: Main Thread]: I/signaling [main|sdp_config] sdp_config.c:86: SDP: Initialized config pointer: 0xe05821c0
[task 2018-08-29T23:10:22.765Z] 23:10:22     INFO - PID 11358 | [Child 11444: Main Thread]: I/jsep [1535584222193367 (id=4294967543 url=https://web-platform.test:8443/webrtc/RTCRtpTransceiver.https.html)]: stable -> have-remote-offer
[task 2018-08-29T23:10:22.765Z] 23:10:22     INFO - PID 11358 | [Child 11444: Socket Thread]: I/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:731: ca705f3cb34b64c1| Transmit audio[{b92886af-12c9-43ac-aa01-047c6c84adc9}] in DetachTransport_s
[task 2018-08-29T23:10:22.767Z] 23:10:22     INFO - PID 11358 | [Child 11444: Socket Thread]: I/signaling [Socket Thread|MediaPipeline] MediaPipeline.cpp:731: ca705f3cb34b64c1| Receive audio in DetachTransport_s
[task 2018-08-29T23:10:22.767Z] 23:10:22     INFO - PID 11358 | Assertion failure: transceiver->IsAssociated() (ICE candidate was gathered before the transceiver was associated! This should never happen.), at /builds/worker/workspace/build/src/media/webrtc/signaling/src/jsep/JsepSessionImpl.cpp:2246
[task 2018-08-29T23:10:22.784Z] 23:10:22     INFO - PID 11358 | #01: mozilla::JsepSessionImpl::AddLocalIceCandidate(std::string const&, std::string const&, unsigned short*, std::string*, bool*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.792Z] 23:10:22     INFO - PID 11358 | #02: mozilla::PeerConnectionImpl::CandidateReady(std::string const&, std::string const&) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.795Z] 23:10:22     INFO - PID 11358 | #03: sigslot::_connection2<mozilla::PeerConnectionImpl, std::string const&, std::string const&, sigslot::single_threaded>::emit(std::string const&, std::string const&) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.803Z] 23:10:22     INFO - PID 11358 | #04: sigslot::signal2<std::string const&, std::string const&, sigslot::single_threaded>::operator()(std::string const&, std::string const&) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.805Z] 23:10:22     INFO - PID 11358 | #05: mozilla::PeerConnectionMedia::OnCandidateFound_m(std::string const&, std::string const&, unsigned short, std::string const&, unsigned short, std::string const&) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.813Z] 23:10:22     INFO - PID 11358 | #06: mozilla::runnable_args_memfn<mozilla::PeerConnectionMedia*, void (mozilla::PeerConnectionMedia::*)(std::string const&, std::string const&, unsigned short, std::string const&, unsigned short, std::string const&), std::string, std::string, unsigned short, std::string, unsigned short, std::string>::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.817Z] 23:10:22     INFO - PID 11358 | #07: nsThread::ProcessNextEvent(bool, bool*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.825Z] 23:10:22     INFO - PID 11358 | #08: NS_ProcessNextEvent(nsIThread*, bool) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.828Z] 23:10:22     INFO - PID 11358 | #09: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.832Z] 23:10:22     INFO - PID 11358 | #10: MessageLoop::RunInternal() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.840Z] 23:10:22     INFO - PID 11358 | #11: MessageLoop::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.844Z] 23:10:22     INFO - PID 11358 | #12: nsBaseAppShell::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.852Z] 23:10:22     INFO - PID 11358 | #13: XRE_RunAppShell() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.853Z] 23:10:22     INFO - PID 11358 | #14: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.854Z] 23:10:22     INFO - PID 11358 | #15: MessageLoop::RunInternal() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.856Z] 23:10:22     INFO - PID 11358 | #16: MessageLoop::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.860Z] 23:10:22     INFO - PID 11358 | #17: XRE_InitChildProcess(int, char**, XREChildData const*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.863Z] 23:10:22     INFO - PID 11358 | #18: mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-08-29T23:10:22.929Z] 23:10:22     INFO - PID 11358 | #19: main (/builds/worker/workspace/build/application/firefox/firefox)
[task 2018-08-29T23:10:23.026Z] 23:10:23     INFO - PID 11358 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x190080,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
[task 2018-08-29T23:10:23.043Z] 23:10:23     INFO - PID 11358 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x190080,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
[task 2018-08-29T23:10:23.044Z] 23:10:23     INFO - PID 11358 | ++DOCSHELL 0xdeb53800 == 6 [pid = 11358] [id = {25bc712e-e992-424d-a0ef-50bd4b6edf4f}]
[task 2018-08-29T23:10:23.045Z] 23:10:23     INFO - PID 11358 | ++DOMWINDOW == 11 (0xdf58e700) [pid = 11358] [serial = 17] [outer = (nil)]
[task 2018-08-29T23:10:23.061Z] 23:10:23     INFO - PID 11358 | ++DOMWINDOW == 12 (0xdf9bb000) [pid = 11358] [serial = 18] [outer = 0xdf58e700]
[task 2018-08-29T23:10:23.150Z] 23:10:23     INFO - PID 11358 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x190080,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
[task 2018-08-29T23:10:23.166Z] 23:10:23     INFO - PID 11358 | ++DOCSHELL 0xe0472400 == 7 [pid = 11358] [id = {8a66f03d-e0f5-4e8d-9745-a4ecbdddcbed}]
[task 2018-08-29T23:10:23.168Z] 23:10:23     INFO - PID 11358 | ++DOMWINDOW == 13 (0xdf5c4ca0) [pid = 11358] [serial = 19] [outer = (nil)]
[task 2018-08-29T23:10:23.169Z] 23:10:23     INFO - PID 11358 | ++DOMWINDOW == 14 (0xe0475c00) [pid = 11358] [serial = 20] [outer = 0xdf5c4ca0]
[task 2018-08-29T23:10:23.234Z] 23:10:23     INFO - PID 11358 | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2018-08-29T23:10:23.251Z] 23:10:23     INFO - PID 11358 | JavaScript error: resource://activity-stream/lib/TopSitesFeed.jsm, line 86: TypeError: setting getter-only property "_currentSearchHostname"
[task 2018-08-29T23:10:23.334Z] 23:10:23     INFO - PID 11358 | ++DOMWINDOW == 15 (0xe0965c00) [pid = 11358] [serial = 21] [outer = 0xdf58e700]
[task 2018-08-29T23:10:23.455Z] 23:10:23     INFO - PID 11358 | ++DOMWINDOW == 16 (0xdf9b3000) [pid = 11358] [serial = 22] [outer = 0xdf5c4ca0]
[task 2018-08-29T23:10:23.674Z] 23:10:23     INFO - PID 11358 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2018-08-29T23:10:23.675Z] 23:10:23     INFO - PID 11358 | [Child 11417, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 866

Comment 1

[Intermittent Failures Robot]

3 failures in 2545 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 2
* autoland: 1

Platform breakdown:
* linux32: 1
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-08-27&endday=2018-09-02&tree=all

Comment 2

[Intermittent Failures Robot]

6 failures in 2667 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 2
* mozilla-inbound: 3
* try: 1

Platform breakdown:
* linux64-qr: 1
* linux64: 1
* linux32: 2
* linux64-ccov: 1
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-09-03&endday=2018-09-09&tree=all

Comment 4

[Intermittent Failures Robot]

12 failures in 2684 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 5
* mozilla-inbound: 3
* try: 1
* mozilla-central: 3

Platform breakdown:
* linux32: 3
* windows10-64: 2
* windows10-64-ccov: 3
* linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-09-10&endday=2018-09-16&tree=all

Comment 6

[Intermittent Failures Robot]

17 failures in 2902 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 9
* mozilla-inbound: 5
* try: 1
* mozilla-central: 2

Platform breakdown:
* linux32: 10
* windows10-64: 2
* windows7-32: 1
* linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-09-17&endday=2018-09-23&tree=all

Comment 8

[Intermittent Failures Robot]

9 failures in 2773 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 4
* mozilla-inbound: 3
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux32: 4
* windows7-32: 2
* linux64-qr: 1
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-09-24&endday=2018-09-30&tree=all

Comment 9

[Intermittent Failures Robot]

6 failures in 2708 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 2
* mozilla-inbound: 3
* mozilla-central: 1

Platform breakdown:
* windows10-64: 1
* linux32: 1
* linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-10-01&endday=2018-10-07&tree=all

Comment 10

[Intermittent Failures Robot]

9 failures in 2740 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 2
* try: 1
* autoland: 3
* mozilla-central: 2
* mozilla-beta: 1

Platform breakdown:
* linux32: 2
* linux64: 2
* linux64-qr: 1
* windows7-32: 2
* windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-10-08&endday=2018-10-14&tree=all

Comment 11

[Intermittent Failures Robot]

11 failures in 2759 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 6
* autoland: 1
* mozilla-beta: 1
* mozilla-central: 1
* try: 2

Platform breakdown:
* windows7-32: 8
* windows10-64: 2
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-10-15&endday=2018-10-21&tree=all

Comment 12

[Intermittent Failures Robot]

11 failures in 2584 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 3
* mozilla-beta: 1
* mozilla-inbound: 3
* mozilla-central: 4

Platform breakdown:
* windows10-64: 4
* linux32: 1
* linux64: 3
* windows7-32: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-10-22&endday=2018-10-28&tree=all

Comment 15

[Intermittent Failures Robot]

7 failures in 2978 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 3
* autoland: 2
* mozilla-beta: 1
* mozilla-central: 1

Platform breakdown:
* windows7-32: 3
* windows10-64: 1
* linux64: 2
* linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-10-29&endday=2018-11-04&tree=all

Comment 16

[Byron Campen [:bwc]]

I think I know what is happening here, but I'm not 100% sure. It seems likely that we are seeing a race where a transceiver is stopped (and disassociated) due to a remote description, while a local trickle candidate is in flight from STS to main. I think the right thing to do here is just ignore such candidates.

Comment 17

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=449c699604f5da99555147b3592fee7e1e10a053

Comment 18

[Intermittent Failures Robot]

2 failures in 3007 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 1
* autoland: 1

Platform breakdown:
* linux64: 1
* linux64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-11-05&endday=2018-11-11&tree=all

Comment 19

[Byron Campen [:bwc]]

Comparing this push:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=449c699604f5da99555147b3592fee7e1e10a053&selectedJob=210096616

with its parent:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3b2d553f544ac197c623c84698937d064a4af5cd&selectedJob=211278448

It looks like this patch fixes the bug.

Comment 20

[Byron Campen [:bwc]]

Attachment: Bug 1487278: When a transceiver is stopped/disassociated by a remote description, clear its transport id too.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ade9fff502f6
When a transceiver is stopped/disassociated by a remote description, clear its transport id too. r=mjf

Comment 22

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/ade9fff502f6

Comment 23

[Ryan VanderMeulen [:RyanVM]]

Please nominate this for Beta uplift when you get a chance.

Comment 24

[Intermittent Failures Robot]

8 failures in 2917 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 4
* mozilla-beta: 1
* autoland: 2
* mozilla-central: 1

Platform breakdown:
* windows10-64: 3
* windows10-64-ccov: 1
* windows7-32: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-11-12&endday=2018-11-18&tree=all

Comment 25

[Intermittent Failures Robot]

8 failures in 2917 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 4
* autoland: 2
* mozilla-central: 1
* mozilla-beta: 1

Platform breakdown:
* windows7-32: 4
* windows10-64: 3
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1487278&startday=2018-11-12&endday=2018-11-18&tree=all

Comment 26

[Byron Campen [:bwc]]

Comment on attachment 9024758 [details]
Bug 1487278: When a transceiver is stopped/disassociated by a remote description, clear its transport id too.

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: Bug 1483338

User impact if declined: Intermittent failures in webrtc wpt.

Is this code covered by automated tests?: Yes

Has the fix been verified in Nightly?: Yes

Needs manual test from QE?: No

If yes, steps to reproduce: 

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): This is a very minor tweak.

String changes made/needed: None

Comment 27

[Julien Cristau [:jcristau]]

Comment on attachment 9024758 [details]
Bug 1487278: When a transceiver is stopped/disassociated by a remote description, clear its transport id too.

small webrtc fix, approved for 64.0b12

Comment 28

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/releases/mozilla-beta/rev/6b8aaf8b4941