Closed Bug 1502092 Opened 6 years ago Closed 5 years ago

Intermittent http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html | application timed out after 370 seconds with no output

Categories

(GeckoView :: Media, defect, P5)

defect

Tracking

(geckoview64 wontfix, firefox64 wontfix, firefox65 fixed)

RESOLVED FIXED
mozilla65
Tracking Status
geckoview64 --- wontfix
firefox64 --- wontfix
firefox65 --- fixed

People

(Reporter: gbrown, Assigned: jchen)

References

Details

Attachments

(1 file)

This is a frequent intermittent seen only on the Android 7.0 x86 test platform:

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

[task 2018-10-25T09:18:24.010Z] 09:18:24     INFO -  REFTEST TEST-START | http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html
[task 2018-10-25T09:18:24.010Z] 09:18:24     INFO -  REFTEST INFO | RESTORE PREFERENCE pref(dom.disable_open_during_load,true)
[task 2018-10-25T09:18:24.010Z] 09:18:24     INFO -  REFTEST INFO | RESTORE PREFERENCE pref(media.navigator.permission.disabled,false)
[task 2018-10-25T09:18:24.010Z] 09:18:24     INFO -  REFTEST INFO | SET PREFERENCE pref(media.navigator.permission.disabled,true)
[task 2018-10-25T09:18:24.010Z] 09:18:24     INFO -  REFTEST INFO | SET PREFERENCE pref(dom.disable_open_during_load,false)
[task 2018-10-25T09:18:24.011Z] 09:18:24     INFO -  REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html | 643 / 3618 (17%)
[task 2018-10-25T09:18:24.011Z] 09:18:24     INFO -  REFTEST TEST-PASS | http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html | (LOAD ONLY)
[task 2018-10-25T09:18:24.011Z] 09:18:24     INFO -  REFTEST TEST-END | http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html
[task 2018-10-25T09:24:56.011Z] 09:24:56     INFO -  wait for org.mozilla.geckoview.test complete; top activity=org.mozilla.geckoview.test
[task 2018-10-25T09:24:56.115Z] 09:24:56     INFO -  Browser unexpectedly found running. Killing...
[task 2018-10-25T09:24:56.116Z] 09:24:56     INFO -  REFTEST TEST-INFO | started process screentopng
[task 2018-10-25T09:24:56.445Z] 09:24:56     INFO -  REFTEST TEST-INFO | screentopng: exit 0
[task 2018-10-25T09:25:10.387Z] 09:25:10  WARNING -  TEST-UNEXPECTED-FAIL | http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html | application timed out after 370 seconds with no output
[task 2018-10-25T09:25:10.388Z] 09:25:10     INFO -  INFO | automation.py | Application ran for: 0:08:11.694749


https://taskcluster-artifacts.net/Jdxeqx4bQwCsI71qZ2hcLQ/0/public/test_info//logcat-emulator-5554.log

10-25 10:18:14.530  2365  2380 I Gecko   : REFTEST TEST-LOAD | http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html | 643 / 3618 (17%)
10-25 10:18:14.530  2365  2380 I Gecko   : 
10-25 10:18:14.530  2365  2380 I Gecko   : {"action":"log","time":1540459094530,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"START http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html"}
10-25 10:18:14.540  2365  2380 E GeckoConsole: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html" line: 0}]
10-25 10:18:14.550  2365  2740 I libOpenSLES: Emulating old channel mask behavior (ignoring positional mask 0x3, using default mask 0x3 based on channel count of 2)
10-25 10:18:14.550  2365  2740 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by server; frameCount 4096
10-25 10:18:14.550  2365  2740 D AudioTrack: Client defaulted notificationFrames to 2048 for frameCount 4096
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] OnDocumentLoad triggering AfterOnLoadScripts"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Initializing canvas snapshot"}
10-25 10:18:14.550  2365  2380 W GeckoConsole: [JavaScript Warning: "Use of Mutation Events is deprecated. Use MutationObserver instead." {file: "resource://reftest/reftest-content.js" line: 772}]
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] WaitForTestEnd: Adding listeners"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Initializing canvas snapshot"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: dispatching MozReftestInvalidate"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_FOR_SPELL_CHECKS"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_FOR_APZ_FLUSH"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: APZ flush not required"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: STATE_WAITING_TO_FINISH"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] MakeProgress: Completed"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] RecordResult fired"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"RecordResult fired"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"test_status","time":1540459094550,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html","subtest":"(LOAD ONLY)","status":"PASS"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"test_end","time":1540459094550,"thread":null,"pid":null,"source":"reftest","test":"http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html","status":"OK"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"Loading a blank page"}
10-25 10:18:14.550  2365  2380 W GeckoConsole: [JavaScript Warning: "Navigation to toplevel data: URI not allowed (Blocked loading of: “data:text/html,2â€)"]
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] AfterPaintListener in http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html"}
10-25 10:18:14.550  2365  2380 I Gecko   : 
10-25 10:18:14.550  2365  2380 I Gecko   : {"action":"log","time":1540459094550,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] AfterPaintListener in http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html"}
10-25 10:18:14.570  2365  2380 I Gecko   : 
10-25 10:18:14.570  2365  2380 I Gecko   : {"action":"log","time":1540459094570,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] AfterPaintListener in http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html"}
10-25 10:18:14.570  2365  2380 I Gecko   : 
10-25 10:18:14.570  2365  2380 I Gecko   : {"action":"log","time":1540459094570,"thread":null,"pid":null,"source":"reftest","level":"DEBUG","message":"[CONTENT] AfterPaintListener in http://10.0.2.2:8854/tests/dom/media/tests/crashtests/1185191.html"}
10-25 10:18:20.640  1053  1053 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1140 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1443 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1053 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1140 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1443 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  2625  2710 W System.err: java.lang.IllegalStateException
10-25 10:18:20.640  2625  2710 W System.err: 	at android.media.MediaCodec.native_flush(Native Method)
10-25 10:18:20.640  2625  2710 W System.err: 	at android.media.MediaCodec.flush(MediaCodec.java:2052)
10-25 10:18:20.640  2625  2710 W System.err: 	at org.mozilla.gecko.media.LollipopAsyncCodec.flush(LollipopAsyncCodec.java:178)
10-25 10:18:20.640  2625  2710 W System.err: 	at org.mozilla.gecko.media.Codec.flush(Codec.java:537)
10-25 10:18:20.640  2625  2710 W System.err: 	at org.mozilla.gecko.media.ICodec$Stub.onTransact(ICodec.java:121)
10-25 10:18:20.640  2625  2710 W System.err: 	at android.os.Binder.execTransact(Binder.java:565)
10-25 10:18:20.640  2625  2638 W System.err: java.lang.IllegalStateException
10-25 10:18:20.640  2625  2638 W System.err: 	at android.media.MediaCodec.native_stop(Native Method)
10-25 10:18:20.640  2625  2638 W System.err: 	at android.media.MediaCodec.stop(MediaCodec.java:2005)
10-25 10:18:20.640  2625  2638 W System.err: 	at org.mozilla.gecko.media.LollipopAsyncCodec.stop(LollipopAsyncCodec.java:173)
10-25 10:18:20.640  2625  2638 W System.err: 	at org.mozilla.gecko.media.Codec.stop(Codec.java:524)
10-25 10:18:20.640  2625  2638 W System.err: 	at org.mozilla.gecko.media.ICodec$Stub.onTransact(ICodec.java:114)
10-25 10:18:20.640  2625  2638 W System.err: 	at android.os.Binder.execTransact(Binder.java:565)
10-25 10:18:20.640  1053  1053 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1140 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1443 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1053 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  1053  1140 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.640  2625  2638 W System.err: java.lang.IllegalStateException
10-25 10:18:20.640  2625  2638 W System.err: 	at android.media.MediaCodec.native_flush(Native Method)
10-25 10:18:20.640  2625  2638 W System.err: 	at android.media.MediaCodec.flush(MediaCodec.java:2052)
10-25 10:18:20.640  2625  2638 W System.err: 	at org.mozilla.gecko.media.LollipopAsyncCodec.flush(LollipopAsyncCodec.java:178)
10-25 10:18:20.640  2625  2638 W System.err: 	at org.mozilla.gecko.media.Codec.flush(Codec.java:537)
10-25 10:18:20.640  2625  2638 W System.err: 	at org.mozilla.gecko.media.ICodec$Stub.onTransact(ICodec.java:121)
10-25 10:18:20.640  2625  2638 W System.err: 	at android.os.Binder.execTransact(Binder.java:565)
10-25 10:18:20.640  2625  2710 W System.err: java.lang.IllegalStateException
10-25 10:18:20.640  2625  2710 W System.err: 	at android.media.MediaCodec.native_stop(Native Method)
10-25 10:18:20.640  2625  2710 W System.err: 	at android.media.MediaCodec.stop(MediaCodec.java:2005)
10-25 10:18:20.640  2625  2710 W System.err: 	at org.mozilla.gecko.media.LollipopAsyncCodec.stop(LollipopAsyncCodec.java:173)
10-25 10:18:20.640  2625  2710 W System.err: 	at org.mozilla.gecko.media.Codec.stop(Codec.java:524)
10-25 10:18:20.640  2625  2710 W System.err: 	at org.mozilla.gecko.media.ICodec$Stub.onTransact(ICodec.java:114)
10-25 10:18:20.640  2625  2710 W System.err: 	at android.os.Binder.execTransact(Binder.java:565)
10-25 10:18:20.650  1053  1443 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.650  1053  1053 E ResourceManagerService: Rejected removeResource call with invalid pid.
10-25 10:18:20.650  2625  2625 I GeckoMediaManager: Media service has been unbound. Stopping.
10-25 10:18:20.650  2625  2625 I Process : Sending signal. PID: 2625 SIG: 9
10-25 10:18:20.670  1319  1861 I ActivityManager: Process org.mozilla.geckoview.test:media (pid 2625) has died
10-25 10:18:20.670  1319  1861 D ActivityManager: cleanUpApplicationRecord -- 2625
10-25 10:24:34.950  2365  2371 I art     : Thread[3,tid=2371,WaitingInMainSignalCatcherLoop,Thread*=0xe199fc00,peer=0x12c00310,"Signal Catcher"]: reacting to signal 3
:davidb - Can you find someone to look at this? It is the main intermittent failure preventing us from moving Android 7.0 x86 crashtests to tier 1.
Flags: needinfo?(dbolter)
Jim any thoughts?
Flags: needinfo?(dbolter) → needinfo?(nchen)
Priority: -- → P5
Seems like this hasn't happened in the last few days?
Status: NEW → RESOLVED
Closed: 6 years ago
Flags: needinfo?(nchen)
Resolution: --- → WORKSFORME
Sorry, but it is still happening.

https://treeherder.mozilla.org/logviewer.html#?job_id=210818078&repo=autoland&lineNumber=4090
https://treeherder.mozilla.org/logviewer.html#?job_id=210755215&repo=autoland&lineNumber=4090

(Remember that since this task is tier 3, it is hidden and not sheriffed; most failures will not be classified and will not show in the intermittent failures view / reports.)
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
1185191.html loads a URI on finishing the test, which can race with the
crashtest framework loading another URI on test finish. This patch fixes
that race.
Assignee: nobody → nchen
Pushed by nchen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b02a1825a239
Fix finish race in 1185191.html; r=gbrown
https://hg.mozilla.org/mozilla-central/rev/b02a1825a239
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 65
64=wontfix because we don't need to uplift this test fix.
status-geckoview64=wontfix
Product: Firefox for Android → GeckoView
Target Milestone: Firefox 65 → mozilla65

Moving some media bugs to the new GeckoView::Media component.

Component: General → Media
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: