1284980 - Android mochitest shutdown hang may be reported as time-out on final test

Status: RESOLVED WONTFIX

(Firefox for Android Graveyard :: Testing, defect, P2)

Description

[Geoff Brown [:gbrown]]

Just noticed this curious test time-out in a try push for something else...

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b7c20ea7aebd&selectedJob=23443083

https://public-artifacts.taskcluster.net/VMQ_C5h5TvaJcvMs5ldCqg/0/public/logs/live_backing.log

18:07:57     INFO -  7 INFO TEST-START | dom/bindings/test/test_sequence_wrapping.html
18:08:09     INFO -  8 INFO TEST-OK | dom/bindings/test/test_sequence_wrapping.html | took 13961ms
18:08:09     INFO -  9 INFO TEST-START | dom/canvas/test/crossorigin/test_video_crossorigin.html
18:08:47     INFO -  10 INFO TEST-OK | dom/canvas/test/crossorigin/test_video_crossorigin.html | took 30730ms
18:08:47     INFO -  11 INFO TEST-START | dom/canvas/test/crossorigin/test_webgl_crossorigin_textures.html
18:08:59     INFO -  12 INFO TEST-OK | dom/canvas/test/crossorigin/test_webgl_crossorigin_textures.html | took 12486ms
18:09:11     INFO -  13 INFO TEST-START | dom/canvas/test/test_bug1215072.html
18:09:11     INFO -  14 INFO TEST-OK | dom/canvas/test/test_bug1215072.html | took 9278ms
18:09:23     INFO -  15 INFO TEST-START | gfx/tests/mochitest/test_acceleration.html
18:09:23     INFO -  16 INFO TEST-OK | gfx/tests/mochitest/test_acceleration.html | took 6413ms
18:15:45     INFO -  org.mozilla.fennec still alive after SIGABRT: waiting...
18:15:51  WARNING -  TEST-UNEXPECTED-FAIL | gfx/tests/mochitest/test_acceleration.html | application timed out after 330 seconds with no output
18:15:51     INFO -  INFO | automation.py | Application ran for: 0:10:04.872651

18:18:32     INFO -  07-06 11:09:12.924 I/GeckoDump( 2128): ⰲ겿{"action":"test_end","time":1467828552913,"thread":null,"pid":null,"source":"mochitest","test":"/tests/gfx/tests/mochitest/test_acceleration.html","status":"OK","message":"Finished in 6415ms","stack":{"runtime":6415},"js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.184 W/GeckoConsole( 2128): [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html" line: 0}]
18:18:32     INFO -  07-06 11:09:14.844 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554823,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"TEST-START | Shutdown","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.875 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554850,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Passed:  161","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.894 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554881,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Failed:  0","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.914 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554898,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Todo:    0","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.934 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554919,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Mode:    non-e10s","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.934 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554936,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Slowest: 30619ms - /tests/dom/canvas/test/crossorigin/test_video_crossorigin.html","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.954 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554946,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"SimpleTest FINISHED","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:14.954 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554958,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"TEST-INFO | Ran 1 Loops","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:15.014 I/GeckoDump( 2128): ⰲ겿{"action":"log","time":1467828554968,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"SimpleTest FINISHED","js_source":"TestRunner.js"}ⰲ겿
18:18:32     INFO -  07-06 11:09:16.714 I/GeckoPushService( 2128): Handling event: PushServiceAndroidGCM:Uninitialized
18:18:32     INFO -  07-06 11:09:17.824 D/GeckoNetworkManager( 2128): Incoming event disableNotifications for state OnWithListeners -> OnNoListeners
18:18:32     INFO -  07-06 11:15:41.244 I/dalvikvm( 2128): threadid=3: reacting to signal 3
18:18:32     INFO -  07-06 11:15:41.474 I/dalvikvm( 2128): Wrote stack traces to '/data/anr/traces.txt'
18:18:32     INFO -  07-06 11:15:44.794 W/google-breakpad( 2128): ExceptionHandler::GenerateDump cloned child

There is an OK for test_acceleration but the time-out is still attributed to test_acceleration. Logcat shows that all tests completed and a summary was generated, but there's no sign of that in the main log and the time-out is not reported as a shutdown hang.

Comment 1

[Geoff Brown [:gbrown]]

Haven't seen any more like this...not important enough to pursue.