1190464 - Android emulator sometimes left running

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown]]

In http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android-api-11/1438422878/mozilla-inbound_ubuntu64_vm_armv7_mobile_test-mochitest-12-bm51-tests1-linux64-build117.txt.gz, a non-responsive emulator correctly triggers a fatal error in android_emulator_unittest.py, but the emulator is still running (so 'adb logcat' is still running) when the blobber upload task runs. I suspect the blobber upload cleanup step hung waiting for the logcat file to be completed.

android_emulator_unittest.py should be more careful about shutting down the emulator before proceeding to blobber upload.

Comment 1

[Geoff Brown [:gbrown]]

03:27:18     INFO - >> Install Fennec APK: Attempt #1 of 3
03:27:18     INFO - Running timeout 300 /builds/slave/test/build/android-sdk18/platform-tools/adb -s emulator-5554 install -r /builds/slave/test/build/fennec-42.0a1.en-US.android-arm.apk
error: device not found
- waiting for device -
03:32:18     INFO - Sleeping 30 seconds
03:32:48     INFO - >> Install Fennec APK: Attempt #2 of 3
03:32:48     INFO - Running timeout 300 /builds/slave/test/build/android-sdk18/platform-tools/adb -s emulator-5554 install -r /builds/slave/test/build/fennec-42.0a1.en-US.android-arm.apk
error: device not found
- waiting for device -
03:37:48     INFO - Sleeping 30 seconds
03:38:18     INFO - >> Install Fennec APK: Attempt #3 of 3
03:38:18     INFO - Running timeout 300 /builds/slave/test/build/android-sdk18/platform-tools/adb -s emulator-5554 install -r /builds/slave/test/build/fennec-42.0a1.en-US.android-arm.apk
error: device not found
- waiting for device -
03:43:18    FATAL - Failed to install /builds/slave/test/build/fennec-42.0a1.en-US.android-arm.apk on test-1
03:43:18    FATAL - Running post_fatal callback...
03:43:18    FATAL - Exiting -1
03:43:18     INFO - Running post-action listener: _resource_record_post_action
03:43:18     INFO - Running post-run listener: _post_script
03:43:18     INFO - Let's kill every process called emulator64-arm
03:43:18     INFO - Killing pid 1736.
03:43:18     INFO - Running post-run listener: _resource_record_post_run
03:43:19     INFO - Total resource usage - Wall time: 1003s; CPU: 5.0%; Read bytes: 7036928; Write bytes: 57556992; Read time: 476; Write time: 49240
03:43:19     INFO - verify-emulator - Wall time: 43s; CPU: 100.0%; Read bytes: 5144576; Write bytes: 4878336; Read time: 364; Write time: 988
03:43:19     INFO - install - Wall time: 961s; CPU: 0.0%; Read bytes: 1794048; Write bytes: 52678656; Read time: 108; Write time: 48252
03:43:19     INFO - Running post-run listener: _upload_blobber_files
03:43:19     INFO - Blob upload gear active.
03:43:19     INFO - Preparing to upload files from /builds/slave/test/build/blobber_upload_dir.
03:43:19     INFO - Files from /builds/slave/test/build/blobber_upload_dir are to be uploaded with <mozilla-inbound> branch at the following location(s): https://blobupload.elasticbeanstalk.com
03:43:19     INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/venv/bin/blobberc.py', '-u', 'https://blobupload.elasticbeanstalk.com', '-a', '/builds/slave/test/oauth.txt', '-b', 'mozilla-inbound', '-d', '/builds/slave/test/build/blobber_upload_dir', '--output-manifest', '/builds/slave/test/build/uploaded_files.json']
03:43:19     INFO - Copy/paste: /builds/slave/test/build/venv/bin/python /builds/slave/test/build/venv/bin/blobberc.py -u https://blobupload.elasticbeanstalk.com -a /builds/slave/test/oauth.txt -b mozilla-inbound -d /builds/slave/test/build/blobber_upload_dir --output-manifest /builds/slave/test/build/uploaded_files.json
03:43:20     INFO -  (blobuploader) - INFO - Open directory for files ...
03:43:20     INFO -  (blobuploader) - INFO - Uploading /builds/slave/test/build/blobber_upload_dir/logcat-emulator-5554.log ...
03:43:20     INFO -  (blobuploader) - INFO - Using https://blobupload.elasticbeanstalk.com
03:43:20     INFO -  (blobuploader) - INFO - Uploading, attempt #1.
03:43:20     INFO -  (blobuploader) - INFO - TinderboxPrint: <a href='http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/cd6569f646d10f26d0266db3cfa3fbbd56cadbf79c1809c66a799cb2cc3137bb24e774deba0f9810706aa2b7299827b1abb423a3c1aaf4ad46a5a227dca864fd'>logcat-emulator-5554.log</a>: uploaded
03:43:20     INFO -  (blobuploader) - INFO - Blobserver returned 202. File uploaded!
03:43:20     INFO -  (blobuploader) - INFO - Done attempting.
03:43:20     INFO -  (blobuploader) - INFO - Uploading /builds/slave/test/build/blobber_upload_dir/emulator-startup-screenshot-soXZfN.png ...
03:43:20     INFO -  (blobuploader) - INFO - Using https://blobupload.elasticbeanstalk.com
03:43:20     INFO -  (blobuploader) - INFO - Uploading, attempt #1.
03:43:21     INFO -  (blobuploader) - INFO - TinderboxPrint: <a href='http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/4066ae95b32386df2139c7411e732230eec03e8af3e714c202706926544f4d501bda229b35d82875377b2671fa283f69fff9b5b65e4702110be5f2fa761011e0'>emulator-startup-screenshot-soXZfN.png</a>: uploaded
03:43:21     INFO -  (blobuploader) - INFO - Blobserver returned 202. File uploaded!
03:43:21     INFO -  (blobuploader) - INFO - Done attempting.
03:43:21     INFO -  (blobuploader) - INFO - Iteration through files over.
03:43:21     INFO - Return code: 0
03:43:21     INFO - rmtree: /builds/slave/test/build/uploaded_files.json
03:43:21     INFO - retry: Calling remove with args: ('/builds/slave/test/build/uploaded_files.json',), kwargs: {}, attempt #1
03:43:21     INFO - Setting buildbot property blobber_files to {"logcat-emulator-5554.log": "http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/cd6569f646d10f26d0266db3cfa3fbbd56cadbf79c1809c66a799cb2cc3137bb24e774deba0f9810706aa2b7299827b1abb423a3c1aaf4ad46a5a227dca864fd", "emulator-startup-screenshot-soXZfN.png": "http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/4066ae95b32386df2139c7411e732230eec03e8af3e714c202706926544f4d501bda229b35d82875377b2671fa283f69fff9b5b65e4702110be5f2fa761011e0"}
03:43:21     INFO - Writing buildbot properties ['blobber_files'] to /builds/slave/test/properties/blobber_files
03:43:21     INFO - Writing to file /builds/slave/test/properties/blobber_files
03:43:21     INFO - Contents:
03:43:21     INFO -  blobber_files:{"logcat-emulator-5554.log": "http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/cd6569f646d10f26d0266db3cfa3fbbd56cadbf79c1809c66a799cb2cc3137bb24e774deba0f9810706aa2b7299827b1abb423a3c1aaf4ad46a5a227dca864fd", "emulator-startup-screenshot-soXZfN.png": "http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/4066ae95b32386df2139c7411e732230eec03e8af3e714c202706926544f4d501bda229b35d82875377b2671fa283f69fff9b5b65e4702110be5f2fa761011e0"}

command timed out: 2400 seconds without output running ['/tools/buildbot/bin/python', 'scripts/scripts/android_emulator_unittest.py', '--cfg', 'android/androidarm_4_3.py', '--test-suite', 'mochitest-12', '--blob-upload-branch', 'mozilla-inbound', '--download-symbols', 'ondemand'], attempting to kill
program finished with exit code 255
elapsedTime=3593.772119

Comment 2

[Geoff Brown [:gbrown]]

Attachment: move emulator cleanup to upload_blobber_files override

The script was already killing the emulator in a @PostScriptRun function. Unfortunately, blobber uploads are also triggered via @PostScriptRun -- http://hg.mozilla.org/mozilla-central/annotate/cdf53a4dee21/testing/mozharness/mozharness/mozilla/blob_upload.py#l107 -- and that seems to be called before the emulator cleanup postscript.

I don't know of a way to ensure that one @PostScriptRun function is called before another, so I have moved the cleanup to an override of the blobber upload function: kill the emulator, then proceed with blobber uploads.

It works: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c3e39fd47cf3 (I force an installer failure in the robocop job here -- the emulator is killed, blobber upload proceeds, and a retry is triggered).

Comment 3

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b79dc959cde0

Comment 4

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b79dc959cde0