Closed Bug 1402358 Opened 7 years ago Closed 7 years ago

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

Categories

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

Product:
Firefox for Android Graveyard
Component:
Testing
Type:
defect

Tracking

(firefox60 fixed)

Status:
RESOLVED INCOMPLETE
Milestone:
Firefox 60
Tracking Flags:
Tracking Status
firefox60 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

remove emulator verification on shutdown
1.25 KB, patch
jmaher
: review+
Details | Diff | Splinter Review
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
See Also: → 1319196
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: 7 years ago
status-firefox60: --- → fixed
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: 7 years ago → 7 years ago
Resolution: --- → INCOMPLETE
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: