Intermittent mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ps'

RESOLVED INCOMPLETE

Status

()

defect
P5
normal
RESOLVED INCOMPLETE
2 years ago
Last year

People

(Reporter: intermittent-bug-filer, Unassigned)

Tracking

({intermittent-failure})

unspecified
Firefox 60
Points:
---

Firefox Tracking Flags

(firefox60 fixed)

Details

Attachments

(1 attachment)

Filed by: archaeopteryx [at] coole-files.de

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

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

[task 2017-09-22T11:04:53.382Z] 11:04:53     INFO -  GECKO | EventExpecter: no longer listening for TestHomeBanner:MessageDismissed
[task 2017-09-22T11:04:53.382Z] 11:04:53     INFO -  TEST-OK | testHomeBanner | took 220710ms
[task 2017-09-22T11:04:53.383Z] 11:04:53     INFO -  TEST-START | Shutdown
[task 2017-09-22T11:04:53.383Z] 11:04:53     INFO -  Passed: 90
[task 2017-09-22T11:04:53.383Z] 11:04:53     INFO -  Failed: 0
[task 2017-09-22T11:04:53.384Z] 11:04:53     INFO -  Todo: 0
[task 2017-09-22T11:04:53.384Z] 11:04:53     INFO -  SimpleTest FINISHED
[task 2017-09-22T11:05:14.607Z] 11:05:14     INFO -  INFO | automation.py | Application ran for: 0:04:08.755398
[task 2017-09-22T11:05:14.607Z] 11:05:14     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpq3Exfzpidlog
[task 2017-09-22T11:05:15.200Z] 11:05:15     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2017-09-22T11:10:37.624Z] 11:10:37     INFO -  mozdevice ERROR | Timeout exceeded for _checkCmd call 'adb shell am instrument -w -e quit_and_finish 1 -e deviceroot /storage/sdcard/tests -e class org.mozilla.gecko.tests.testIdnSupport org.mozilla.roboexample.test/org.mozilla.gecko.FennecInstrumentationTestRunner'
[task 2017-09-22T11:11:08.673Z] 11:11:08 CRITICAL -  mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ps'
[task 2017-09-22T11:11:08.686Z] 11:11:08     INFO -  INFO | automation.py | Application pid: 0
[task 2017-09-22T11:11:38.729Z] 11:11:38 CRITICAL -  mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /storage/sdcard/tests/logs/mochitest.log'
[task 2017-09-22T11:12:48.803Z] 11:12:48     INFO -  mozdevice ERROR | Timeout exceeded for shell call 'adb shell dumpsys window windows; echo $?'
[task 2017-09-22T11:13:18.851Z] 11:13:18 CRITICAL -  mozdevice ERROR | Timeout exceeded for _runCmd call 'adb shell ls -a /storage/sdcard/tests/logs/mochitest.log'
[task 2017-09-22T11:14:18.893Z] 11:14:18     INFO -  mozdevice ERROR | Timeout exceeded for shell call 'adb shell dumpsys window windows; echo $?'
[task 2017-09-22T11:14:18.901Z] 11:14:18     INFO -  INFO | automation.py | Application ran for: 0:09:01.316033
It looks like RETRY is attempted, but the task times out first, because of excessive cleanup:

[task 2018-01-19T01:24:04.602Z] 01:24:04 CRITICAL - # TBPL RETRY #
[task 2018-01-19T01:24:04.603Z] 01:24:04  WARNING - setting return code to 4
[task 2018-01-19T01:24:04.603Z] 01:24:04 CRITICAL - The mochitest suite: mochitest ran with return status: RETRY
[task 2018-01-19T01:24:04.603Z] 01:24:04     INFO - Running post-action listener: _resource_record_post_action
[task 2018-01-19T01:24:04.603Z] 01:24:04     INFO - Running post-action listener: stop_emulator
[task 2018-01-19T01:24:04.603Z] 01:24:04     INFO - Verifying adb connectivity
[task 2018-01-19T01:24:04.603Z] 01:24:04     INFO - Running timeout 180 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb wait-for-device
[task 2018-01-19T01:24:04.606Z] 01:24:04     INFO - >> Verify emulator visible to adb: Attempt #1 of 4
[task 2018-01-19T01:24:04.606Z] 01:24:04     INFO - Running timeout 30 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb devices
[task 2018-01-19T01:24:04.611Z] 01:24:04     INFO - List of devices attached
[task 2018-01-19T01:24:04.611Z] 01:24:04     INFO - emulator-5554	device
[task 2018-01-19T01:24:04.612Z] 01:24:04     INFO - Running timeout 30 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb kill-server
[task 2018-01-19T01:24:04.616Z] 01:24:04     INFO - Running timeout 30 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb root
[task 2018-01-19T01:24:07.623Z] 01:24:07     INFO - * daemon not running. starting it now at tcp:5037 *
[task 2018-01-19T01:24:07.623Z] 01:24:07     INFO - * daemon started successfully *
[task 2018-01-19T01:24:07.623Z] 01:24:07     INFO - stderr: adb: unable to connect for root: device offline
[task 2018-01-19T01:24:07.624Z] 01:24:07     INFO - >> Verify Android boot completed: Attempt #1 of 30
[task 2018-01-19T01:24:07.625Z] 01:24:07     INFO - Running timeout 30 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb -s emulator-5554 shell getprop sys.boot_completed
[task 2018-01-19T01:24:07.631Z] 01:24:07     INFO - stderr: error: device offline
[task 2018-01-19T01:24:07.631Z] 01:24:07     INFO - Sleeping 10 seconds
[task 2018-01-19T01:24:17.641Z] 01:24:17     INFO - >> Verify Android boot completed: Attempt #2 of 30
[task 2018-01-19T01:24:17.642Z] 01:24:17     INFO - Running timeout 30 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb -s emulator-5554 shell getprop sys.boot_completed
[task 2018-01-19T01:24:17.649Z] 01:24:17     INFO - stderr: error: device offline
[task 2018-01-19T01:24:17.650Z] 01:24:17     INFO - Sleeping 10 seconds
[task 2018-01-19T01:24:27.657Z] 01:24:27     INFO - >> Verify Android boot completed: Attempt #3 of 30
[task 2018-01-19T01:24:27.658Z] 01:24:27     INFO - Running timeout 30 /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb -s emulator-5554 shell getprop sys.boot_completed


Why is stop_emulator() checking boot_completed??
Assignee: nobody → gbrown
When the emulator is hung, trying to verify it can take a long time, resulting in a task timeout where we would otherwise have simply retried the task. Verification on shutdown is really low value anyway, so I'm just taking it out.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1a7dce4342576ab129aa04584d2011149a738ebb
Attachment #8946314 - Flags: review?(jmaher)
Comment on attachment 8946314 [details] [diff] [review]
remove emulator verification on shutdown

Review of attachment 8946314 [details] [diff] [review]:
-----------------------------------------------------------------

this seems like a good move
Attachment #8946314 - Flags: review?(jmaher) → review+
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8a2a602d8550
In Android emulator tests, shutdown faster; r=jmaher
https://hg.mozilla.org/mozilla-central/rev/8a2a602d8550
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 60
This looks like a "perfect storm" of conditions bringing about the failure -- I don't expect it to recur much at all. Also, work like bug 1440714 will change a lot of the related code...hopefully for the better!

I am a little surprised to see us using a 3600 second max-run-time for mochitest-chrome; I might increase that so that the task doesn't time out in a case like this and an automatic retry is more reliably triggered.

Otherwise, I don't intend to make changes here, but we can keep this bug open to monitor failure frequency.
Flags: needinfo?(gbrown)
Assignee: gbrown → nobody
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 2 years agoLast year
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.