1471080 - Intermittent TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds

Status: RESOLVED FIXED

(Testing :: Mochitest, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: csabou [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/QvR4FqRYQCS-Pe6SGe8K7g/runs/0/artifacts/public/logs/live_backing.log

[task 2018-06-25T22:19:59.652Z] 22:19:59     INFO -  TEST-START | org.mozilla.geckoview.test.AccessibilityTest.testAccessibilityFocus
[task 2018-06-25T22:59:48.272Z] 22:59:48  WARNING -  TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds
[task 2018-06-25T22:59:48.272Z] 22:59:48     INFO -  Passed: 0
[task 2018-06-25T22:59:48.272Z] 22:59:48     INFO -  Failed: 0
[task 2018-06-25T22:59:48.272Z] 22:59:48     INFO -  Todo: 0
[task 2018-06-25T22:59:48.272Z] 22:59:48     INFO -  SUITE-END | took 2400s
[task 2018-06-25T22:59:48.886Z] 22:59:48     INFO -  Stopping web server
[task 2018-06-25T22:59:48.894Z] 22:59:48     INFO -  Stopping web socket server
[task 2018-06-25T22:59:48.914Z] 22:59:48     INFO -  Stopping ssltunnel
[task 2018-06-25T22:59:50.665Z] 22:59:50     INFO - Return code: 0
[task 2018-06-25T22:59:50.665Z] 22:59:50    ERROR - No tests run or test summary not found
[task 2018-06-25T22:59:50.665Z] 22:59:50     INFO - TinderboxPrint: geckoview-junit<br/><em class="testfail">T-FAIL</em>
[task 2018-06-25T22:59:50.666Z] 22:59:50     INFO - ##### geckoview-junit log ends
[task 2018-06-25T22:59:50.666Z] 22:59:50  WARNING - # TBPL WARNING #
[task 2018-06-25T22:59:50.667Z] 22:59:50  WARNING - setting return code to 1
[task 2018-06-25T22:59:50.667Z] 22:59:50  WARNING - The geckoview-junit suite: geckoview-junit ran with return status: WARNING
[task 2018-06-25T22:59:50.667Z] 22:59:50     INFO - Running post-action listener: _package_coverage_data
[task 2018-06-25T22:59:50.667Z] 22:59:50     INFO - Running post-action listener: _resource_record_post_action
[task 2018-06-25T22:59:50.668Z] 22:59:50     INFO - Running post-action listener: stop_emulator
[task 2018-06-25T22:59:50.675Z] 22:59:50     INFO - Killing every process called emulator64-arm
[task 2018-06-25T22:59:50.675Z] 22:59:50     INFO - Killing pid 493.
[task 2018-06-25T22:59:50.676Z] 22:59:50     INFO - [mozharness: 2018-06-25 22:59:50.675900Z] Finished run-tests step (success)
[task 2018-06-25T22:59:50.676Z] 22:59:50     INFO - Running post-run listener: _resource_record_post_run
[task 2018-06-25T22:59:50.842Z] 22:59:50     INFO - Total resource usage - Wall time: 2446s; CPU: 3.0%; Read bytes: 5414912; Write bytes: 884326400; Read time: 932; Write time: 182604
[task 2018-06-25T22:59:50.842Z] 22:59:50     INFO - TinderboxPrint: CPU usage<br/>2.6%
[task 2018-06-25T22:59:50.843Z] 22:59:50     INFO - TinderboxPrint: I/O read bytes / time<br/>5,414,912 / 932
[task 2018-06-25T22:59:50.843Z] 22:59:50     INFO - TinderboxPrint: I/O write bytes / time<br/>884,326,400 / 182,604
[task 2018-06-25T22:59:50.843Z] 22:59:50     INFO - TinderboxPrint: CPU idle<br/>9,378.7 (97.3%)
[task 2018-06-25T22:59:50.844Z] 22:59:50     INFO - TinderboxPrint: CPU user<br/>243.1 (2.5%)
[task 2018-06-25T22:59:50.844Z] 22:59:50     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2018-06-25T22:59:50.845Z] 22:59:50     INFO - verify-emulator - Wall time: 3s; CPU: 2.0%; Read bytes: 0; Write bytes: 378601472; Read time: 0; Write time: 83088
[task 2018-06-25T22:59:50.847Z] 22:59:50     INFO - install - Wall time: 35s; CPU: 25.0%; Read bytes: 4096; Write bytes: 226963456; Read time: 0; Write time: 57832
[task 2018-06-25T22:59:50.871Z] 22:59:50     INFO - run-tests - Wall time: 2408s; CPU: 2.0%; Read bytes: 4861952; Write bytes: 278761472; Read time: 916; Write time: 41684
[task 2018-06-25T22:59:51.572Z] 22:59:51     INFO - Running post-run listener: copy_logs_to_upload_dir
[task 2018-06-25T22:59:51.572Z] 22:59:51     INFO - Copying logs to upload dir...
[task 2018-06-25T22:59:51.572Z] 22:59:51     INFO - mkdir: /builds/worker/workspace/build/upload/logs
[task 2018-06-25T22:59:51.574Z] 22:59:51     INFO - Copying logs to upload dir...
[task 2018-06-25T22:59:51.576Z] 22:59:51  WARNING - returning nonzero exit status 1

Comment 1

[Geoff Brown [:gbrown]]

This error message was introduced in bug 1470177. Earlier failures of this type were reported as task timeouts in bug 1411358.

Comment 2

[Geoff Brown [:gbrown]]

I don't know when this timeout actually started. Because geckoview-junit timeouts were not being handled correctly (bug 1470177), these were being reported as task timeouts, with incomplete logs.

So far, all of the failures reported here are right at the beginning of a run, with only the start of testAccessibilityFocus reported:

https://treeherder.mozilla.org/logviewer.html#?job_id=184940652&repo=autoland&lineNumber=1183

[task 2018-06-26T15:16:59.149Z] 15:16:59     INFO -  SUITE-START | Running 1 tests
[task 2018-06-26T15:16:59.150Z] 15:16:59     INFO -  launching am instrument -w -r -e args '-profile /sdcard/tests/junit-profile' -e use_multiprocess true -e env0 MOZ_CRASHREPORTER=1 -e env1 XPCOM_DEBUG_BREAK=stack -e env2 R_LOG_VERBOSE=1 -e env3 DISABLE_UNSAFE_CPOW_WARNINGS=1 -e env4 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 -e env5 MOZ_IN_AUTOMATION=1 -e env6 MOZ_CRASHREPORTER_SHUTDOWN=1 -e env7 R_LOG_DESTINATION=stderr -e env8 MOZ_CRASHREPORTER_NO_REPORT=1 -e env9 R_LOG_LEVEL=6 org.mozilla.geckoview.test/android.support.test.runner.AndroidJUnitRunner
[task 2018-06-26T15:17:10.980Z] 15:17:10     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2018-06-26T15:17:11.082Z] 15:17:11     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=1
[task 2018-06-26T15:17:11.082Z] 15:17:11     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.AccessibilityTest
[task 2018-06-26T15:17:11.082Z] 15:17:11     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2018-06-26T15:17:11.083Z] 15:17:11     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.AccessibilityTest:
[task 2018-06-26T15:17:11.084Z] 15:17:11     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=265
[task 2018-06-26T15:17:11.084Z] 15:17:11     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=testAccessibilityFocus
[task 2018-06-26T15:17:11.084Z] 15:17:11     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2018-06-26T15:17:11.085Z] 15:17:11     INFO -  TEST-START | org.mozilla.geckoview.test.AccessibilityTest.testAccessibilityFocus
[task 2018-06-26T15:56:59.247Z] 15:56:59  WARNING -  TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds

Logcat ends like this:

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

06-26 08:17:39.008   749   763 W GeckoEventDispatcher: No listener for GeckoView:AccessibilityEnabled
06-26 08:17:39.039   749   752 D dalvikvm: GC_CONCURRENT freed 340K, 15% free 4018K/4724K, paused 25ms+35ms, total 174ms
06-26 08:17:39.209   749   763 I Gecko   : [AccessFu] INFO AccessFu:Enabled
06-26 08:17:39.479   797   810 I Gecko   : [AccessFuContent] INFO content-script.js about:blank
06-26 08:17:40.078   797   810 I Gecko   : [AccessFuContent] WARNING AccessibilityEventObserver.observe: no accessible document: reorder accessible: [ app root | Nightly ]
06-26 08:18:23.958   749   833 I GeckoConsole: PAC file installed from data: URI
06-26 08:25:51.728   276   278 D dalvikvm: GC_CONCURRENT freed 460K, 13% free 4705K/5404K, paused 6ms+6ms, total 76ms


:snorp - Do you know what's happening here?

Comment 3

[Intermittent Failures Robot]

15 failures in 148 pushes (0.101 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 9
* autoland: 4
* try: 1
* mozilla-central: 1

Platform breakdown:
* android-em-4-3-armv7-api16: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1471080&startday=2018-06-27&endday=2018-06-27&tree=trunk

Comment 4

[Intermittent Failures Robot]

18 failures in 120 pushes (0.15 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 9
* autoland: 5
* mozilla-central: 4

Platform breakdown:
* android-em-4-3-armv7-api16: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1471080&startday=2018-06-29&endday=2018-06-29&tree=trunk

Comment 5

[Intermittent Failures Robot]

56 failures in 718 pushes (0.078 failures/push) were associated with this bug in the last 7 days. 

This is the #10 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 27
* autoland: 21
* mozilla-central: 6
* try: 2

Platform breakdown:
* android-em-4-3-armv7-api16: 56

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1471080&startday=2018-06-25&endday=2018-07-01&tree=trunk

Comment 6

[Bogdan Tara[:bogdan_tara | bogdant]]

There are 60 failures in the past week occurring on android-em-4-3-armv7-api16, debug and opt.

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

[task 2018-07-03T15:07:14.744Z]     INFO -  SUITE-START | Running 1 tests
[task 2018-07-03T15:07:14.746Z]     INFO -  launching am instrument -w -r -e args '-profile /sdcard/tests/junit-profile' -e use_multiprocess true -e numShards 3 -e shardIndex 1 -e env0 MOZ_CRASHREPORTER=1 -e env1 XPCOM_DEBUG_BREAK=stack -e env2 R_LOG_VERBOSE=1 -e env3 DISABLE_UNSAFE_CPOW_WARNINGS=1 -e env4 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 -e env5 MOZ_IN_AUTOMATION=1 -e env6 MOZ_CRASHREPORTER_SHUTDOWN=1 -e env7 R_LOG_DESTINATION=stderr -e env8 MOZ_CRASHREPORTER_NO_REPORT=1 -e env9 R_LOG_LEVEL=6 org.mozilla.geckoview.test/android.support.test.runner.AndroidJUnitRunner
[task 2018-07-03T15:07:26.979Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2018-07-03T15:07:26.980Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=1
[task 2018-07-03T15:07:26.980Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.AccessibilityTest
[task 2018-07-03T15:07:26.981Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2018-07-03T15:07:26.981Z]     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.AccessibilityTest:
[task 2018-07-03T15:07:26.982Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=96
[task 2018-07-03T15:07:26.983Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=testAccessibilityFocus
[task 2018-07-03T15:07:26.983Z]     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2018-07-03T15:07:26.984Z]     INFO -  TEST-START | org.mozilla.geckoview.test.AccessibilityTest.testAccessibilityFocus
[task 2018-07-03T15:47:14.768Z]  WARNING -  TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds
[task 2018-07-03T15:47:14.768Z]     INFO -  Passed: 0
[task 2018-07-03T15:47:14.768Z]     INFO -  Failed: 0
[task 2018-07-03T15:47:14.768Z]     INFO -  Todo: 0
[task 2018-07-03T15:47:14.769Z]     INFO -  SUITE-END | took 2400s
[task 2018-07-03T15:47:15.491Z]     INFO -  Stopping web server
[task 2018-07-03T15:47:15.498Z]     INFO -  Stopping web socket server
[task 2018-07-03T15:47:15.518Z]     INFO -  Stopping ssltunnel
[task 2018-07-03T15:47:17.373Z]     INFO - Return code: 0
[task 2018-07-03T15:47:17.374Z]    ERROR - No tests run or test summary not found
[task 2018-07-03T15:47:17.374Z]     INFO - TinderboxPrint: geckoview-junit<br/><em class="testfail">T-FAIL</em>
[task 2018-07-03T15:47:17.374Z]     INFO - ##### geckoview-junit log ends
[task 2018-07-03T15:47:17.374Z]  WARNING - # TBPL WARNING #
[task 2018-07-03T15:47:17.374Z]  WARNING - setting return code to 1
[task 2018-07-03T15:47:17.375Z]  WARNING - The geckoview-junit suite: geckoview-junit ran with return status: WARNING
[task 2018-07-03T15:47:17.375Z]     INFO - Running post-action listener: _package_coverage_data
[task 2018-07-03T15:47:17.375Z]     INFO - Running post-action listener: _resource_record_post_action
[task 2018-07-03T15:47:17.376Z]     INFO - Running post-action listener: stop_emulator
[task 2018-07-03T15:47:17.384Z]     INFO - Killing every process called emulator64-arm
[task 2018-07-03T15:47:17.384Z]     INFO - Killing pid 462.
[task 2018-07-03T15:47:17.384Z]     INFO - [mozharness: 2018-07-03 15:47:17.384720Z] Finished run-tests step (success)
[task 2018-07-03T15:47:17.384Z]     INFO - Running post-run listener: _resource_record_post_run
[task 2018-07-03T15:47:17.542Z]     INFO - Total resource usage - Wall time: 2458s; CPU: 4.0%; Read bytes: 7290880; Write bytes: 882831360; Read time: 136; Write time: 334784
[task 2018-07-03T15:47:17.542Z]     INFO - TinderboxPrint: CPU usage<br/>3.5%
[task 2018-07-03T15:47:17.542Z]     INFO - TinderboxPrint: I/O read bytes / time<br/>7,290,880 / 136
[task 2018-07-03T15:47:17.542Z]     INFO - TinderboxPrint: I/O write bytes / time<br/>882,831,360 / 334,784
[task 2018-07-03T15:47:17.542Z]     INFO - TinderboxPrint: CPU idle<br/>9,367.6 (96.4%)
[task 2018-07-03T15:47:17.542Z]     INFO - TinderboxPrint: CPU user<br/>327.4 (3.4%)
[task 2018-07-03T15:47:17.543Z]     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2018-07-03T15:47:17.544Z]     INFO - verify-emulator - Wall time: 3s; CPU: 3.0%; Read bytes: 0; Write bytes: 272859136; Read time: 0; Write time: 195936
[task 2018-07-03T15:47:17.546Z]     INFO - install - Wall time: 44s; CPU: 25.0%; Read bytes: 8192; Write bytes: 134770688; Read time: 0; Write time: 56576
[task 2018-07-03T15:47:17.570Z]     INFO - run-tests - Wall time: 2410s; CPU: 3.0%; Read bytes: 7028736; Write bytes: 475201536; Read time: 136; Write time: 82272
[task 2018-07-03T15:47:18.321Z]     INFO - Running post-run listener: copy_logs_to_upload_dir
[task 2018-07-03T15:47:18.322Z]     INFO - Copying logs to upload dir...
[task 2018-07-03T15:47:18.322Z]     INFO - mkdir: /builds/worker/workspace/build/upload/logs
[task 2018-07-03T15:47:18.324Z]     INFO - Copying logs to upload dir...
[task 2018-07-03T15:47:18.326Z]  WARNING - returning nonzero exit status 1
[task 2018-07-03T15:47:18.347Z] cleanup

Comment 7

[Intermittent Failures Robot]

14 failures in 622 pushes (0.023 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 9
* mozilla-inbound: 4
* mozilla-central: 1

Platform breakdown:
* android-em-4-3-armv7-api16: 14

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1471080&startday=2018-07-02&endday=2018-07-08&tree=trunk

Comment 8

[James Willcox (:snorp) ([e-mail]) (he/him)]

Hopefully I fixed this in bug 1472832.

Comment 9

[Geoff Brown [:gbrown]]

Yes, failure frequency is way down since bug 1472832 - awesome!

There are a couple of infrequent cases still which I may be able to eliminate...

Comment 10

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/logviewer.html#?job_id=186743568&repo=autoland&lineNumber=2677-2686

The emulator died, but since it took 2400 s to time-out, there wasn't enough time to complete cleanly and trigger a retry (probably...might also be related to bug 1457694).

Comment 11

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/logviewer.html#?job_id=187228864&repo=mozilla-inbound&lineNumber=2863-2864

Slow emulator/host (bug 1321605) and the task ran out of time. Increase time-out, more chunks?

Comment 12

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/logviewer.html#?job_id=187390230&repo=autoland&lineNumber=3072

Slow emulator/host (bug 1321605) and the task ran out of time. Increase time-out, more chunks?

Comment 13

[Geoff Brown [:gbrown]]

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

Slow emulator/host (bug 1321605) and the task ran out of time. Increase time-out, more chunks?

Comment 14

[Geoff Brown [:gbrown]]

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

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4c9aa8e48d61
Increase test chunks for geckoview-junit; r=me,a=test-only

Comment 16

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/4c9aa8e48d61

Comment 17

[Intermittent Failures Robot]

3 failures in 623 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2
* autoland: 1

Platform breakdown:
* android-em-4-3-armv7-api16: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1471080&startday=2018-07-09&endday=2018-07-15&tree=trunk

Comment 18

[Intermittent Failures Robot]

1 failures in 653 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* android-em-4-3-armv7-api16: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1471080&startday=2018-07-16&endday=2018-07-22&tree=trunk