1275814 - Intermittent test_peerConnection_callbacks.html | application timed out after 330 seconds with no output

Status: RESOLVED DUPLICATE of bug 1276156

(Core :: WebRTC, defect, P3)

Description

[Phil Ringnalda (:philor)]

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

Comment 1

[Andreas Pehrson [:pehrsons]]

This is a bit confusing. The log shows all the steps of the test passing, but the test doesn't finish.

P3 for now. Let's re-evaluate if the frequency is high.

Comment 2

[Nils Ohlmeier [:drno]]

I'm not sure if this crash in the log:

19:45:02  WARNING -  PROCESS-CRASH | dom/media/tests/mochitest/test_peerConnection_callbacks.html | application crashed [@ libc.so + 0x1c3dc]

A) was the reason why the test never finished, but the framework failed to detect the crash at runtime?
B) shutting down everything after the test timeout caused this crashed?

Comment 3

[Phil Ringnalda (:philor)]

After the harness detects a hang ("330 seconds without output"), it attempts to crash the browser in the vain hope (I can't remember the last time it was actually useful) of producing a stack which will make you say "oh, of course, we were deadlocked in foo::barBaz, I can fix that!"

While it is certainly imaginable to crash, have the crash be undetected, and seem hung as a result, there will be either a "crash" or signs of attempting to produce one after 100% of hangs, so it shouldn't be the first assumption.

Comment 4

[Nils Ohlmeier [:drno]]

Thanks Phil.

I just noticed that to my surprise the Android raw log files actually contain the real time stamps way down at the end of the log. And that surely looks like what you are saying: Firefox gets crashed after a log timeout :-)

19:46:10     INFO -  05-25 19:36:55.750 I/GeckoDump( 2096): ⰲ겿{"action":"log","time":1464230215756,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Calling getStats","js_source":"TestRunner.js"}ⰲ겿
19:46:10     INFO -  05-25 19:36:58.200 I/GeckoDump( 2096): ⰲ겿{"action":"test_status","time":1464230218143,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_callbacks.html","subtest":"pc2 has stats","status":"PASS","js_source":"TestRunner.js"}ⰲ겿
19:46:10     INFO -  05-25 19:36:58.740 I/GeckoDump( 2096): MEMORY STAT | vsize 676MB | residentFast 192MB | heapAllocated 78MB
19:46:10     INFO -  05-25 19:36:59.480 D/AudioFocusAgent( 2096): NotifyStoppedPlaying
19:46:10     INFO -  05-25 19:36:59.480 D/AudioFocusAgent( 2096): Abandon AudioFocus
19:46:10     INFO -  05-25 19:36:59.500 I/AudioService(  279):  AudioFocus  abandonAudioFocus() from [e-mail]$1@4197e948
19:46:10     INFO -  05-25 19:37:01.200 D/GeckoTabs( 2096): handleMessage: Tab:AudioPlayingChange
19:46:10     INFO -  05-25 19:37:01.210 D/GeckoToolbar( 2096): onTabChanged: AUDIO_PLAYING_CHANGE
19:46:10     INFO -  05-25 19:37:01.220 D/GeckoBrowserApp( 2096): BrowserApp.onTabChanged: 0: AUDIO_PLAYING_CHANGE
19:46:10     INFO -  05-25 19:37:03.270 I/GeckoDump( 2096): ⰲ겿{"action":"test_end","time":1464230223258,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_callbacks.html","status":"OK","message":"Finished in 31362ms","stack":{"runtime":31362},"js_source":"TestRunner.js"}ⰲ겿
19:46:10     INFO -  05-25 19:44:43.190 I/dalvikvm( 2096): threadid=3: reacting to signal 3
19:46:10     INFO -  05-25 19:44:43.389 I/dalvikvm( 2096): Wrote stack traces to '/data/anr/traces.txt'
19:46:10     INFO -  05-25 19:44:46.640 W/google-breakpad( 2096): ExceptionHandler::GenerateDump cloned child
19:46:10     INFO -  05-25 19:44:46.640 W/google-breakpad( 2096): 3221�68*���]��������������]��
19:46:10     INFO -  05-25 19:44:46.640 W/google-breakpad( 2096):
19:46:10     INFO -  05-25 19:44:46.640 W/google-breakpad( 2096): ExceptionHandler::SendContinueSignalToChild sent continue signal to child
19:46:10     INFO -  05-25 19:44:46.640 W/google-breakpad( 3221): ExceptionHandler::WaitForContinueSignal waiting for continue signal...

But it make me wonder what these Audio Playing Change messages are about...

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

Similar deadlock to bug 1276156