There are 29 total failures in the last 7 days on linux64 asan

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231339561&repo=autoland&lineNumber=46178

[task 2019-03-01T21:44:19.164Z] 21:44:19 INFO - TEST-START | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html
[task 2019-03-01T21:44:19.692Z] 21:44:19 INFO - GECKO(1885) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-01T21:44:19.713Z] 21:44:19 INFO - GECKO(1885) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-03-01T21:44:19.957Z] 21:44:19 INFO - GECKO(1885) | Timecard created 1551476512.572324
task 2019-03-01T21:49:23.080Z] 21:49:23 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | PeerConnectionWrapper (pcRemote) stats outbound video rtp track id {9c9be27a-c933-49d7-9a2f-a59d53b2c233} - did not find extra stats with wrong media type
[task 2019-03-01T21:49:23.083Z] 21:49:23 INFO - Buffered messages finished
[task 2019-03-01T21:49:23.088Z] 21:49:23 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Test timed out.
[task 2019-03-01T21:49:23.089Z] 21:49:23 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-03-01T21:49:23.092Z] 21:49:23 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-03-01T21:49:23.094Z] 21:49:23 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-03-01T21:49:23.095Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.096Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.096Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.097Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.100Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.103Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.107Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.107Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.109Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.110Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.110Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.115Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.116Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.120Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.120Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.120Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.120Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.120Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.126Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.127Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.127Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.127Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.128Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.128Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.128Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.128Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.129Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.129Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.129Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.130Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.130Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.130Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.130Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.142Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.145Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.145Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.147Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.147Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.150Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.150Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.151Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.152Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.154Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.154Z] 21:49:23 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-01T21:49:23.157Z] 21:49:23 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
[task 2019-03-01T21:49:23.157Z] 21:49:23 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2019-03-01T21:49:23.157Z] 21:49:23 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-03-01T21:49:23.163Z] 21:49:23 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-03-01T21:49:23.163Z] 21:49:23 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-03-01T21:49:23.163Z] 21:49:23 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2019-03-01T21:49:23.164Z] 21:49:23 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2019-03-01T21:49:23.165Z] 21:49:23 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2019-03-01T21:49:23.166Z] 21:49:23 INFO - hookup@SimpleTest/setup.js:253:5
[task 2019-03-01T21:49:23.171Z] 21:49:23 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1

Nils, can you take a look?

This occurs only on linux64 asan and there are 27 total failures in the last 7 days.
Nils, can you assign someone to look at this?

Seems to have gotten much more frequent sometime between Feb 20-23.

Here's the webrtc stuff that landed in that range:

https://bugzilla.mozilla.org/buglist.cgi?list_id=14625419&chfield=resolution&chfieldfrom=2019-02-19&chfieldvalue=FIXED&resolution=FIXED&classification=Client%20Software&classification=Developer%20Infrastructure&classification=Components&classification=Server%20Software&classification=Other&chfieldto=2019-02-24&query_format=advanced&component=WebRTC&component=WebRTC%3A%20Audio%2FVideo&component=WebRTC%3A%20Networking&component=WebRTC%3A%20Signaling

Might be bug 1521879.

Ok, these tests are timing out because there's a really long hang (4-5 minutes) at the beginning of the test, maybe in gUM?

[task 2019-03-21T00:42:58.056Z] 00:42:58 INFO - GECKO(2430) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-21T00:42:58.056Z] 00:42:58 INFO - GECKO(2430) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-03-21T00:47:26.505Z] 00:47:26 INFO - GECKO(2430) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-21T00:47:26.508Z] 00:47:26 INFO - GECKO(2430) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)

[task 2019-03-21T01:43:38.039Z] 01:43:38 INFO - GECKO(2469) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-21T01:43:38.041Z] 01:43:38 INFO - GECKO(2469) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-03-21T01:47:44.903Z] 01:47:44 INFO - GECKO(2469) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-21T01:47:44.912Z] 01:47:44 INFO - GECKO(2469) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)

Yeah, here's one that timed out early enough in the test that we had the relevant logging in the buffer:

[task 2019-03-11T21:47:15.647Z] 21:47:15 INFO - GECKO(1974) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-11T21:47:15.649Z] 21:47:15 INFO - GECKO(1974) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-03-11T21:53:17.052Z] 21:53:17 INFO - GECKO(1974) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-11T21:53:17.063Z] 21:53:17 INFO - GECKO(1974) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)

...

[task 2019-03-11T21:53:20.803Z] 21:53:20 INFO - Buffered messages logged at 21:47:14
[task 2019-03-11T21:53:20.810Z] 21:53:20 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | A valid string reason is expected
[task 2019-03-11T21:53:20.817Z] 21:53:20 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Reason cannot be empty
[task 2019-03-11T21:53:20.823Z] 21:53:20 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | A valid string reason is expected
[task 2019-03-11T21:53:20.830Z] 21:53:20 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Reason cannot be empty
[task 2019-03-11T21:53:20.836Z] 21:53:20 INFO - Buffered messages logged at 21:47:15
[task 2019-03-11T21:53:20.843Z] 21:53:20 INFO - Skipping ICE Server for this test
[task 2019-03-11T21:53:20.850Z] 21:53:20 INFO - Creating PeerConnectionWrapper (pcLocal)
[task 2019-03-11T21:53:20.855Z] 21:53:20 INFO - Creating PeerConnectionWrapper (pcRemote)
[task 2019-03-11T21:53:20.863Z] 21:53:20 INFO - Run step 1: PC_SETUP_SIGNALING_CLIENT
[task 2019-03-11T21:53:20.876Z] 21:53:20 INFO - Run step 2: PC_LOCAL_SETUP_ICE_LOGGER
[task 2019-03-11T21:53:20.880Z] 21:53:20 INFO - Run step 3: PC_REMOTE_SETUP_ICE_LOGGER
[task 2019-03-11T21:53:20.881Z] 21:53:20 INFO - Run step 4: PC_LOCAL_SETUP_SIGNALING_LOGGER
[task 2019-03-11T21:53:20.883Z] 21:53:20 INFO - Run step 5: PC_REMOTE_SETUP_SIGNALING_LOGGER
[task 2019-03-11T21:53:20.886Z] 21:53:20 INFO - Run step 6: PC_LOCAL_SETUP_TRACK_HANDLER
[task 2019-03-11T21:53:20.908Z] 21:53:20 INFO - Run step 7: PC_REMOTE_SETUP_TRACK_HANDLER
[task 2019-03-11T21:53:20.935Z] 21:53:20 INFO - Run step 8: PC_LOCAL_CHECK_INITIAL_SIGNALINGSTATE
[task 2019-03-11T21:53:20.951Z] 21:53:20 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Initial local signalingState is 'stable'
[task 2019-03-11T21:53:20.971Z] 21:53:20 INFO - Run step 9: PC_REMOTE_CHECK_INITIAL_SIGNALINGSTATE
[task 2019-03-11T21:53:20.995Z] 21:53:20 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Initial remote signalingState is 'stable'
[task 2019-03-11T21:53:21.026Z] 21:53:21 INFO - Run step 10: PC_LOCAL_CHECK_INITIAL_ICE_STATE
[task 2019-03-11T21:53:21.057Z] 21:53:21 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Initial local ICE connection state is 'new'
[task 2019-03-11T21:53:21.074Z] 21:53:21 INFO - Run step 11: PC_REMOTE_CHECK_INITIAL_ICE_STATE
[task 2019-03-11T21:53:21.098Z] 21:53:21 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Initial remote ICE connection state is 'new'
[task 2019-03-11T21:53:21.099Z] 21:53:21 INFO - Run step 12: PC_LOCAL_CHECK_INITIAL_CAN_TRICKLE_SYNC
[task 2019-03-11T21:53:21.099Z] 21:53:21 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Local trickle status should start out unknown
[task 2019-03-11T21:53:21.131Z] 21:53:21 INFO - Run step 13: PC_REMOTE_CHECK_INITIAL_CAN_TRICKLE_SYNC
[task 2019-03-11T21:53:21.166Z] 21:53:21 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Remote trickle status should start out unknown
[task 2019-03-11T21:53:21.178Z] 21:53:21 INFO - Run step 14: PC_LOCAL_GUM
[task 2019-03-11T21:53:21.196Z] 21:53:21 INFO - Get 2 local streams
[task 2019-03-11T21:53:21.205Z] 21:53:21 INFO - Buffered messages logged at 21:53:17
[task 2019-03-11T21:53:21.213Z] 21:53:21 INFO - Start loopback tone at 440
[task 2019-03-11T21:53:21.232Z] 21:53:21 INFO - Call getUserMedia for {"audio":{"autoGainControl":false,"echoCancellation":false,"noiseSuppression":false},"video":true}
[task 2019-03-11T21:53:21.241Z] 21:53:21 INFO - Call getUserMedia for {"audio":{"autoGainControl":false,"echoCancellation":false,"noiseSuppression":false},"video":true}
[task 2019-03-11T21:53:21.259Z] 21:53:21 INFO - Buffered messages finished
[task 2019-03-11T21:53:21.275Z] 21:53:21 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Test timed out.

^

Looking closer, it appears that we must be hanging here on the first getUserMedia call in the test:

https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/dom/media/tests/mochitest/head.js#375

@achronop, Does this match up with bug 1441563?

Bug 1441563 is a sneaky problem that can appear in many different cases. However, I am not sure that this is happening here. That issue is appearing when a test is executing many gUM requests. Then, after a few gUM requests the test freezes on device enumeration (part of gUM request). The root cause has to do with audio thread priority.

Here, in the logs from the timed out test, I don't see any gUM request taking place. This is because I would expect to see the following log [1] for every gUM reguest, which I see when I run it locally. Thus the freeze point must be before the first gUM request. The line you pointed out is just before that thus makes sense. However, it must not be the exact same error as Bug 1441563.

[1] https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/dom/media/tests/mochitest/head.js#388

We don't always see that log line (Call getUserMedia for) because that output happens at the beginning of the test, and only so much is buffered. There are cases where the call takes long enough that there isn't enough output to run it off the end of the buffer (eg; the output in comment 27). It looks like what happened there was:

First getUserMedia call, which calls updateConfigFromFakeAndLoopbackPrefs(); (https://searchfox.org/mozilla-central/source/dom/media/tests/mochitest/head.js#367), which outputs the following directly to the console, bypassing the log buffer

[task 2019-03-11T21:47:15.647Z] 21:47:15 INFO - GECKO(1974) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-03-11T21:47:15.649Z] 21:47:15 INFO - GECKO(1974) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)

Then, we enter this code block (https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/dom/media/tests/mochitest/head.js#374-376). When looking at the buffered logging, we do not see this line until 6 minutes have gone by:

[task 2019-03-11T21:53:21.213Z] 21:53:21 INFO - Start loopback tone at 440

This is logged inside the DefaultLoopbackTone.start(); call, which indicates that we must have hung somewhere in that block, almost certainly here: https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/dom/media/tests/mochitest/head.js#375

Once all of that is done, then we see the "Call getUserMedia for..." logging later on in the function.

Sounds like bug 1441563 to me. test_peerConnection_twoAudioVideoStreamsCombined.html looks like it would do parallel gum calls, one each direction.

There are 33 total failures in the last 7 days, all on linux64 asan

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236967393&repo=autoland&lineNumber=46658

[task 2019-03-29T19:17:25.962Z] 19:17:25 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | RTP flowing for audio track {57f140e7-04f6-4e24-a65b-4ecccdc154b8}
[task 2019-03-29T19:17:25.964Z] 19:17:25 INFO - Buffered messages logged at 19:17:19
[task 2019-03-29T19:17:25.990Z] 19:17:25 INFO - Checking for stats in [["outbound_rtp_video_0",{"id":"outbound_rtp_video_0","timestamp":1553887032896,"type":"outbound-rtp","kind":"video","mediaType":"video","ssrc":193514254,"bytesSent":33529,"packetsSent":441,"bitrateMean":8050.352941176471,"bitrateStdDev":3156.2481077455013,"droppedFrames":68,"firCount":0,"framerateMean":23.176470588235297,"framerateStdDev":9.008574346960005,"framesEncoded":427,"nackCount":0,"pliCount":0,"qpSum":1904,"remoteId":"outbound_rtcp_video_0"}],["outbound_rtcp_video_0",{"id":"outbound_rtcp_video_0","timestamp":1553887032896,"type":"remote-inbound-rtp","kind":"video","mediaType":"video","ssrc":193514254,"jitter":0.02,"packetsLost":0,"packetsReceived":427,"bytesReceived":20537,"localId":"outbound_rtp_video_0","roundTripTime":4.597}],["od9Q",{"id":"od9Q","timestamp":1553887032896,"type":"candidate-pair","bytesReceived":160270,"bytesSent":155726,"componentId":1,"lastPacketReceivedTimestamp":1553887034034,"lastPacketSentTimestamp":1553887034037,"localCandidateId":"GS7h","nominated":true,"priority":7961802290698650000,"readable":true,"remoteCandidateId":"Uwar","selected":true,"state":"succeeded","transportId":"transport_0","writable":true}],["GS7h",{"id":"GS7h","timestamp":1553887032896,"type":"local-candidate","address":"172.17.0.5","candidateType":"host","port":36270,"priority":2122187007,"protocol":"udp"}],["okyc",{"id":"okyc","timestamp":1553887032896,"type":"local-candidate","address":"fd15:4ba5:5a2b:100a:0:242:ac11:5","candidateType":"host","port":56195,"priority":2122252543,"protocol":"udp"}],["rbD0",{"id":"rbD0","timestamp":1553887032896,"type":"local-candidate","address":"172.17.0.5","candidateType":"host","port":51316,"priority":2105442559,"protocol":"tcp"}],["Ouam",{"id":"Ouam","timestamp":1553887032896,"type":"local-candidate","address":"172.17.0.5","candidateType":"host","port":56569,"priority":2105458943,"protocol":"tcp"}],["Pcuq",{"id":"Pcuq","timestamp":1553887032896,"type":"local-candidate","address":"fd15:4ba5:5a2b:100a:0:242:ac11:5","candidateType":"host","port":59782,"priority":2105508095,"protocol":"tcp"}],["vncU",{"id":"vncU","timestamp":1553887032896,"type":"local-candidate","address":"fd15:4ba5:5a2b:100a:0:242:ac11:5","candidateType":"host","port":62540,"priority":2105524479,"protocol":"tcp"}],["Uwar",{"id":"Uwar","timestamp":1553887032896,"type":"remote-candidate","address":"172.17.0.5","candidateType":"prflx","port":37652,"priority":1853751551,"protocol":"udp"}]] for video track {15799d4c-151f-46c2-a03e-b21e69f35ceb}retry number 0
[task 2019-03-29T19:17:25.994Z] 19:17:25 INFO - Should have RTP stats for track {15799d4c-151f-46c2-a03e-b21e69f35ceb}
[task 2019-03-29T19:17:26.003Z] 19:17:26 INFO - RTP stats: {"id":"outbound_rtp_video_0","timestamp":1553887032896,"type":"outbound-rtp","kind":"video","mediaType":"video","ssrc":193514254,"bytesSent":33529,"packetsSent":441,"bitrateMean":8050.352941176471,"bitrateStdDev":3156.2481077455013,"droppedFrames":68,"firCount":0,"framerateMean":23.176470588235297,"framerateStdDev":9.008574346960005,"framesEncoded":427,"nackCount":0,"pliCount":0,"qpSum":1904,"remoteId":"outbound_rtcp_video_0"}
[task 2019-03-29T19:17:26.007Z] 19:17:26 INFO - Track {15799d4c-151f-46c2-a03e-b21e69f35ceb} has 441 outbound-rtp RTP packets.
[task 2019-03-29T19:17:26.009Z] 19:17:26 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | RTP flowing for video track {15799d4c-151f-46c2-a03e-b21e69f35ceb}
[task 2019-03-29T19:17:26.017Z] 19:17:26 INFO - Buffered messages finished
[task 2019-03-29T19:17:26.060Z] 19:17:26 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStreamsCombined.html | Test timed out.
[task 2019-03-29T19:17:26.063Z] 19:17:26 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-03-29T19:17:26.065Z] 19:17:26 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-03-29T19:17:26.067Z] 19:17:26 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-03-29T19:17:26.068Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.070Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.072Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.075Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.076Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.078Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.080Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.082Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.083Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.086Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.088Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.089Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.090Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.092Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.094Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.096Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.097Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.099Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.101Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.102Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.104Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.106Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.108Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.109Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.111Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.113Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.115Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.117Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.118Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.120Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.121Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.123Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.124Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.127Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.128Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.130Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.132Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.133Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.135Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.137Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.139Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.140Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.142Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.144Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.146Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.146Z] 19:17:26 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-29T19:17:26.146Z] 19:17:26 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - hookup@SimpleTest/setup.js:253:5
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - GECKO(1808) | MEMORY STAT | vsize 20974329MB | residentFast 1726MB
[task 2019-03-29T19:17:26.147Z] 19:17:26 INFO - GECKO(1808) | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2019-03-29T19:17:26.148Z] 19:17:26 INFO - GECKO(1808) | (ice/INFO) ICE(PC:1553886729903352 (id=4294967897 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStr)
/STREAM(PC:1553886729903352 (id=4294967897 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStr transport-id=transport_0 - 8fa6a65e:4e4b82aa8b1c290becb88fe8b26a79f7)/COMP(1): Consent refreshed
[task 2019-03-29T19:17:26.148Z] 19:17:26 INFO - GECKO(1808) | (ice/INFO) ICE(PC:1553886729887465 (id=4294967897 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStr): peer (PC:1553886729887465 (id=4294967897 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_peerConnection_twoAudioVideoStr:default) Trickle grace period is over; marking every component with only failed pairs as failed.

So I looked at a couple of recent occurrences, and they seem to still be exhibiting bug 1441563. However, I did see one that had an additional large delay in PC_LOCAL_CHECK_TRACK_STATS. I don't know whether this too is caused by bug 1441563, or if there's something else going on.

I wonder if bug 1441563 would go away if we used the same sort of fake audio streams that the web-platform-tests do; those tests aren't having this kind of intermittent timeout problem.

Bug 1441563 is a PulseAudio issue and it does not exist without it. So expect to see it only on Linux and when loopback device is on. You should not have it if you force to use the fake streams in mochitests. Are the fake streams on mochitest the same as the ones used in web platform test?

I doubt they're exactly the same, but they're probably similar. I'm assuming the loopback devices improve our testing coverage somewhat, right?

The benefit of the loopback device is that they are "actual" devices so we exercise the code all the way down to cubeb. Otherwise we don't call cubeb at all. I haven't seen the coverage report to confirm the numbers but any improvement is rather limited since we have it only on Linux.

Do you think bug 1441563 is something that might affect real audio devices, or is this something that is strictly loopback related?

It is loopback related. At least it did not repro with my real devices. Also, it is intermittent and it did not repro locally unless I was forcing to execute everything in one core [1].

https://bugzilla.mozilla.org/show_bug.cgi?id=1441563#c6

In my experience it affects all devices. Try opening multiple tabs on linux with microphone and remoting of audio enabled and it shows pretty quickly.

Can you get stack traces for this? If this might be a real bug too, this seems pretty important.

It's a pretty well-known issue with pulse and/or the way we use it. It's not as simple as a deadlock, but like Alex said it's tied to thread priorities and since we're in very hot paths, some sort of starvation issue comes into play.

We just don't have enough resources to dig deep enough into this to fix it. Nils, FYI, this is another consequence of pulse slowness.

Are these mochitests really putting that much strain on pulse?

It's not that pulse cannot keep up, but when you open or close an input stream pulse hits a bug and locks up the output stream for some time. This is fine on the first stream. It's often fine on the second stream. But the lock-up-time seems to grow exponentially with the number of open streams. It can quickly get real bad, but it typically depend on how powerful the machine is and whether we use AudioIPC (the cubeb sandbox).

This test sometimes times out because opening the second stream sometimes takes too long. Or so is my understanding.

What's even worse is that the duration of time that we locked up for gets added to the pulse output stream buffer, so a user hitting this now has a nasty delay on his hands. Sometimes it seems like audio stops completely, but you close Firefox and the audio plays -- because it was stuck behind a long empty pulse output buffer.

I've been telling Nils at length that we need some resources for this problem, or to disable cubeb sandboxing on linux since it's making it considerably worse. Feel free to be another voice in that choir.

I was working with PulseAudio dev about it for some time. I created a PulseAudio patch that made the tests green. In the same time we did an experiment with realtime priority thread. In PA the audio thread is not real time by default. I forced it to be real time locally (used linux command - sudo access required) and that made also the test green. That made them result in that the priority was the issue and we should change that. I hope that Paul's priority bumper will be in place soon to verify or not that theory. I believe my patch was also in the correct direction and we can try that next if the priority raise do not help.

(In reply to Alex Chronopoulos [:achronop] from comment #48)

I was working with PulseAudio dev about it for some time. I created a PulseAudio patch that made the tests green. In the same time we did an experiment with realtime priority thread. In PA the audio thread is not real time by default. I forced it to be real time locally (used linux command - sudo access required) and that made also the test green. That made them result in that the priority was the issue and we should change that. I hope that Paul's priority bumper will be in place soon to verify or not that theory. I believe my patch was also in the correct direction and we can try that next if the priority raise do not help.

The pulse server has realtime prio AIUI, but not the thread in the client's "threaded main loop" [1] that we're using, correct?

[1] https://freedesktop.org/software/pulseaudio/doxygen/threaded_mainloop.html

The pulse server must have a priority thread because it talks to the device. However, a client talks to PulseAudio client libraries which uses that threaded main loop and that's not real time. So correct.

This has 45 failures in the last 7 days, all on linux64 asan: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-07&endday=2019-04-14&tree=trunk&bug=1480942

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=240166745&repo=mozilla-inbound&lineNumber=46374

There are 63 failures in the last 7 days. All on linux64 asan.

:achronop , :pehrsons , do you have some updates on the issue, or should we disable the test (on linux64 asan) until there will be a fix?

I think we need to disable that test. Fixing that properly is not easy.

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

I might be able to reenable this test on linux asan once bug 1560636 lands; I think this test was having the same problem as in bug 1482521.

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

Ugh, bug 1541424 has made that try push useless. I'll just have to run the whole mochitest suite.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=24690577284758db2e04dd63fd91a392c89ea09a&selectedJob=256776860

Try looks good.

Retriggering the linux asan mochitests, check back later today.

Yeah, looks like we're still timing out sometimes, on the non-spi tests at least. I think this platform is simply too slow to run this test case.