Closed Bug 1311139 Opened 8 years ago Closed 8 years ago

Intermittent dom/media/tests/mochitest/test_peerConnection_basicAudioRequireEOC.html | PeerConnectionWrapper (pcRemote): legal ICE state transition from connected to failed

Categories

(Core :: WebRTC, defect, P3)

Product:
Core
Component:
WebRTC
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1313397

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Rank: 35
Priority: -- → P3
I have this perma fail on OpenSL ES full duplex backend testing:

https://treeherder.mozilla.org/#/jobs?repo=try&author=achronop@gmail.com&fromchange=c8dbaefde4b3a6f4de28b396c214c9f1759aa1f5&selectedJob=29773664

I do not see something obvious from backend point of view. Can you please provide directions how to approach the problem?
Hi, this bug turns to a perma fail with the new OpenSL ES back end. I cannot find an obvious failure in the backend but I know that it does change the scheduling between threads. Can you please collaborate with me to track this issue. It blocks my landing.
Flags: needinfo?(drno)
Looking at the logcat emulator log from this run https://treeherder.mozilla.org/logviewer.html#?job_id=29773664&repo=try#L2337

It looks like it sits and waits for good 30 seconds for remote RTCP feedback to show up when the ICE connection state flips.

I fear the only "solution" I can think of is to patch the mochitests to exclude all media related test steps of our mochitests on the Android emulator, because it just look like the emulator is overloaded. Obviously the other option is to simply disable yet another test.

@Randell: I think you have opinions on this? :-)

10-24 03:21:10.418   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304470107,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Run step 42: PC_REMOTE_WAIT_FOR_MEDIA_FLOW","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:10.418   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304470425,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Checking data flow to element: pcRemote_local_{5a99e2b4-896b-4f18-bbc9-9ddefde4aa8c}","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:10.908   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304470690,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Checking data flow to element: pcRemote_remote_{0eac2090-cb15-4c30-9332-5ca13a4b823b}","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:11.157   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304470917,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Checking RTP packet flow for track {878bf2e8-2137-4800-bd5c-9e7c92bee044}","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:12.198   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304471951,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Checking RTP packet flow for track {519b3b25-83bc-4b16-94ed-3f0db11d622e}","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:13.458   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304473460,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Element pcRemote_local_{5a99e2b4-896b-4f18-bbc9-9ddefde4aa8c} saw 'timeupdate', currentTime=12.469115646258503s, readyState=4","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:13.658   769   789 I GeckoDump: ⰲ겿{"action":"test_status","time":1477304473657,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_basicAudioRequireEOC.html","subtest":"Media flowing for element: pcRemote_local_{5a99e2b4-896b-4f18-bbc9-9ddefde4aa8c}","status":"PASS","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:14.047   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304473817,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Element pcRemote_remote_{0eac2090-cb15-4c30-9332-5ca13a4b823b} saw 'timeupdate', currentTime=10.843718820861678s, readyState=4","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:14.047   769   789 I GeckoDump: ⰲ겿{"action":"test_status","time":1477304474055,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_basicAudioRequireEOC.html","subtest":"Media flowing for element: pcRemote_remote_{0eac2090-cb15-4c30-9332-5ca13a4b823b}","status":"PASS","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:25.188   769   789 I GeckoDump: ⰲ겿{"action":"test_status","time":1477304485196,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_basicAudioRequireEOC.html","subtest":"Should have RTP stats for track {878bf2e8-2137-4800-bd5c-9e7c92bee044}","status":"PASS","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:25.798   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304485799,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Track {878bf2e8-2137-4800-bd5c-9e7c92bee044} has 414 outboundrtp RTP packets.","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:25.888   769   789 I GeckoDump: ⰲ겿{"action":"test_status","time":1477304485889,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_basicAudioRequireEOC.html","subtest":"RTP flowing for track {878bf2e8-2137-4800-bd5c-9e7c92bee044}","status":"PASS","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:32.208   769   789 E GeckoConsole: [JavaScript Error: "ICE failed, see about:webrtc for more details"]
10-24 03:21:32.648   769   789 I GeckoDump: ⰲ겿{"action":"test_status","time":1477304492653,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_basicAudioRequireEOC.html","subtest":"iceConnectionState should not be undefined","status":"PASS","js_source":"TestRunner.js"}ⰲ겿
10-24 03:21:32.988   769   789 I GeckoDump: ⰲ겿{"action":"log","time":1477304492989,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: failed","js_source":"TestRunner.js"}ⰲ겿
Flags: needinfo?(drno) → needinfo?(rjesup)
Dan who would be a good Android expert to ask if these log messages are causing load issues on the emulator:

10-24 03:40:41.728   769   789 I GeckoConsole: ReferenceError: Utils is not defined
10-24 03:40:41.728   769   789 I GeckoConsole: ReferenceError: Utils is not defined
10-24 03:40:41.738   769   789 I GeckoConsole: ReferenceError: Utils is not defined
10-24 03:40:41.738   769   789 I GeckoConsole: ReferenceError: Utils is not defined
10-24 03:40:41.748   769   789 I GeckoConsole: ReferenceError: Utils is not defined
10-24 03:40:41.748   769   789 I GeckoConsole: ReferenceError: Utils is not defined
Flags: needinfo?(dave)
gbrown?  See comments 4 and 5.  Also, note that the log messages in logcat in message 4 are coming in VERY slowly (1/2 or 1 second apart, or more), when these tests typically are close together in JS (see dom/media/tests/mochitest/pc.js)

We could try turning on more logging (mtransport/packet level?) to try to see why we don't appear to be receiving RTCP and don't appear to be receiving 'consent' responses.  Of course that might break it even more.   Or we can just continue disabling all tests... :-(
Flags: needinfo?(rjesup) → needinfo?(gbrown)
Depends on: 1313397
See Also: → 1311140
The "Utils is not defined" is certainly annoying and cannot be helping load, but I don't know if that is causing load issues. Other than a slight increase in test startup crashes, Android tests on treeherder seem to be in good shape. I'll try to get the Utils logging sorted out asap in bug 1313397.

If you think there's a chance of getting more insight with additional logging, I'd encourage that too!
Flags: needinfo?(gbrown)
No failures since resolution of the Utils spam.
Status: NEW → RESOLVED
Closed: 8 years ago
Flags: needinfo?(dave)
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.