993146 - Intermittent Android 2.3 install step hang

Status: RESOLVED DUPLICATE of bug 1123828

(Release Engineering :: General, defect)

Description

[Geoff Brown [:gbrown]]

Bug 663657 collects Android "2400 seconds without output" failures. Several of the recent failures there occur on Android 2.3 during the install step.

I recently asked if this might be related to bug 991020 and :aki said:

> I don't think so, unless it's happening every time.  We could add an 
> output timeout to the install if it's ongoing.


https://tbpl.mozilla.org/php/getParsedLog.php?id=37400287&full=1&branch=mozilla-inbound#error0

14:18:34     INFO - ##### Running install step.
14:18:34     INFO - #####
14:18:34     INFO - Running pre-action listener: _resource_record_pre_action
14:18:34     INFO - Running main action method: install

  ...

14:19:25     INFO - Running command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date', '1396905565.82']
14:19:25     INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date 1396905565.82
14:19:26     INFO -  time 1396905565.82 -> 1396905565.0
14:19:26     INFO -  settimeofday failed Invalid argument
14:19:26     INFO - Return code: 0
14:19:26     INFO - Getting output from command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date']
14:19:26     INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date

command timed out: 2400 seconds without output, attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=2762.501045
========= Finished '/tools/buildbot/bin/python scripts/scripts/android_emulator_unittest.py ...' failed (results: 2, elapsed: 46 mins, 12 secs) (at 2014-04-07 14:59:36.217802) =========

Comment 1

[Geoff Brown [:gbrown]]

More examples:

https://tbpl.mozilla.org/php/getParsedLog.php?id=37365092&tree=Mozilla-Central#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=37311733&tree=Fx-Team#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=37285616&tree=Mozilla-Inbound#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=37267809&tree=Mozilla-Inbound#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=37240158&tree=Mozilla-Central#error0

Comment 2

[Geoff Brown [:gbrown]]

This is still contributing to the failures in bug 663657.

https://tbpl.mozilla.org/php/getParsedLog.php?id=37757694&full=1&branch=mozilla-inbound#error0

07:33:09     INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stderr',), kwargs: {}, attempt #1
07:33:09     INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stdout',), kwargs: {}, attempt #1
07:33:09     INFO - Running command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install', '-r', '/builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk']
07:33:09     INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 install -r /builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk
07:33:26     INFO -  1902 KB/s (32594347 bytes in 16.732s)
07:33:27     INFO -  	pkg: /data/local/tmp/fennec-31.0a1.en-US.android-arm.apk

command timed out: 2400 seconds without output, attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=2725.257721
========= Finished '/tools/buildbot/bin/python scripts/scripts/android_emulator_unittest.py ...' failed (results: 2, elapsed: 45 mins, 25 secs) (at 2014-04-14 08:13:27.164241) =========

Comment 3

[Geoff Brown [:gbrown]]

(In reply to Geoff Brown [:gbrown] from comment #0)
> I recently asked if this might be related to bug 991020 and :aki said:
> 
> > I don't think so, unless it's happening every time.  We could add an 
> > output timeout to the install if it's ongoing.

:aki -- I don't see how to do that. What did you have in mind?

Comment 4

[Aki Sasaki (not active)]

This run_command() http://hg.mozilla.org/build/mozharness/file/7e6cd8e32e89/mozharness/mozilla/testing/device.py#l387
could have an output_timeout, which is described here: http://hg.mozilla.org/build/mozharness/file/7e6cd8e32e89/mozharness/base/script.py#l608

We now have mozprocess in the mozharness repo, so no need to do anything special.

Since the command is timing out in buildbot after 2400 seconds, an output_timeout in mozharness of less than 2400 seconds should let the script get further, at least.  I'm not sure if a retry is best, since the apk might be installed and error out on the next try... maybe an uninstall/install loop with a max_retries.

Comment 5

[Geoff Brown [:gbrown]]

Attachment: add output_timeout for install

Thanks.

I tried this out on ash to verify it did no harm, but didn't reproduce the failure. I'd like to put it in production...see if it helps.

Comment 6

[Aki Sasaki (not active)]

Comment on attachment 8407638 [details] [diff] [review]
add output_timeout for install

300 might be low... 5 minutes to install.  Please keep an eye on this.

... Now that I'm looking at this, can you add

    halt_on_failure=True, fatal_exit_code=3

to the call?
http://hg.mozilla.org/build/mozharness/file/cef6c7ae2c39/mozharness/base/script.py#l601

halt_on_failure will kill the test run if it fails to install (non-zero exit code).

3 will make it turn purple (exception):
http://hg.mozilla.org/build/mozharness/file/cef6c7ae2c39/mozharness/mozilla/buildbot.py#l44

You probably want to re-test on ash or retrigger some Cypress test runs after this lands on default.

Comment 7

[Geoff Brown [:gbrown]]

Attachment: add output_timeout for install

Thanks for the extra tips. Like this then?

Comment 8

[Geoff Brown [:gbrown]]

Re-tested on ash.

https://hg.mozilla.org/build/mozharness/rev/d9601a43d376

Comment 9

[Justin Wood (:Callek)]

In production

Comment 10

[Geoff Brown [:gbrown]]

I don't see any install step failures since this went into production. Will keep watching...

Comment 11

[Phil Ringnalda (:philor)]

bug 663657 comment 4873, first one I've seen since.

Comment 12

[Geoff Brown [:gbrown]]

Thanks.

There is bug 663657 comment 4874 now too.

I don't understand how/why we are hitting "2400 seconds without output" still.

16:04:19     INFO - Calling ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install', '-r', '/builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk'] with output_timeout 300
16:04:40     INFO -  1555 KB/s (32408625 bytes in 20.341s)
16:04:41     INFO -  	pkg: /data/local/tmp/fennec-31.0a1.en-US.android-arm.apk
16:09:41     INFO - Automation Error: mozprocess timed out after 300 seconds running ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install', '-r', '/builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk']
16:09:41    ERROR - timed out after 300 seconds of no output
16:09:41    ERROR - Return code: -9
16:09:41    ERROR - -9 not in success codes: [0]
16:09:41    FATAL - Halting on failure while running ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install', '-r', '/builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk']
16:09:41    FATAL - Running post_fatal callback...
16:09:41    FATAL - Exiting 3
16:09:41     INFO - Running post-action listener: _resource_record_post_action
16:09:41     INFO - Running post-run listener: _resource_record_post_run
16:09:42     INFO - Total resource usage - Wall time: 322s; CPU: 15.0%; Read bytes: 61440; Write bytes: 167534592; Read time: 176; Write time: 637448
16:09:42     INFO - install - Wall time: 323s; CPU: 15.0%; Read bytes: 61440; Write bytes: 167534592; Read time: 176; Write time: 637448
16:09:42     INFO - Running post-run listener: _upload_blobber_files
16:09:42     INFO - Blob upload gear active.
16:09:42     INFO - Preparing to upload files from /builds/slave/test/build/blobber_upload_dir.
16:09:42     INFO - Files from /builds/slave/test/build/blobber_upload_dir are to be uploaded with <fx-team> branch at the following location(s): https://blobupload.elasticbeanstalk.com
16:09:42     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', 'fx-team', '-d', '/builds/slave/test/build/blobber_upload_dir']
16:09:42     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 fx-team -d /builds/slave/test/build/blobber_upload_dir
16:09:42     INFO -  (blobuploader) - INFO - Open directory for files ...
16:09:42     INFO -  (blobuploader) - INFO - Uploading /builds/slave/test/build/blobber_upload_dir/logcat-emulator-5554.log ...
16:09:42     INFO -  (blobuploader) - INFO - Using https://blobupload.elasticbeanstalk.com
16:09:42     INFO -  (blobuploader) - INFO - Uploading, attempt #1.
16:09:43     INFO -  (blobuploader) - INFO - TinderboxPrint: Uploaded logcat-emulator-5554.log to http://mozilla-releng-blobs.s3.amazonaws.com/blobs/fx-team/sha512/4708a7524df3c637967e0ca7a489bbbb8945a0fd57be7aa8f020fb2dcebe566046d24895c46cab854473328868470780c24df4865aa1766825232adc0fd1061d
16:09:43     INFO -  (blobuploader) - INFO - Blobserver returned 202. File uploaded!
16:09:43     INFO -  (blobuploader) - INFO - Done attempting.
16:09:43     INFO -  (blobuploader) - INFO - Iteration through files over.
16:09:43     INFO - Return code: 0

command timed out: 2400 seconds without output, attempting to kill
program finished with exit code 3
elapsedTime=3072.960227
========= Finished '/tools/buildbot/bin/python scripts/scripts/android_emulator_unittest.py ...' exception (results: 4, elapsed: 51 mins, 12 secs) (at 2014-04-18 16:49:43.941490) =========

Comment 13

[Geoff Brown [:gbrown]]

Sometimes the 2400 seconds without output seems to occur before we get to the actual adb install part:

https://tbpl.mozilla.org/php/getParsedLog.php?id=38603234&full=1&branch=mozilla-inbound#error0

19:31:19     INFO - #####
19:31:19     INFO - ##### Running install step.
19:31:19     INFO - #####
19:31:19     INFO - Running pre-action listener: _resource_record_pre_action
19:31:19     INFO - Running main action method: install
19:31:19     INFO - Running command: ['unzip', '-q', '-o', '/builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk'] in /builds/slave/test/build
19:31:19     INFO - Copy/paste: unzip -q -o /builds/slave/test/build/fennec-31.0a1.en-US.android-arm.apk
19:31:20     INFO - Return code: 0
19:31:20     INFO - Reading from file /builds/slave/test/build/package-name.txt
19:31:20     INFO - Contents:
19:31:20     INFO -  org.mozilla.fennec
19:31:20     INFO - Creating ADBDevicHandler for test-1 with config {'log_to_console': True, 'host_utils_url': 'http://bm-remote.build.mozilla.org/tegra/tegra-host-utils.Linux.742597.zip', 'blob_uploader_auth_file': '/builds/slave/test/oauth.txt', 'append_to_log': False, 'virtualenv_path': 'venv', 'tooltool_cache_path': '/builds/slave/talos-slave/cached', 'enable_automation': True, 'default_blob_upload_servers': ('https://blobupload.elasticbeanstalk.com',), 'blob_upload_branch': 'mozilla-inbound', 'device_package_name': 'org.mozilla.fennec', 'tooltool_url': 'http://tooltool.pvt.build.mozilla.org/build/sha512', 'volatile_config': {'no_actions': None, 'add_actions': None, 'actions': None}, 'in_tree_config': 'config/mozharness/android_arm_config.py', 'env': {'PATH': '%(PATH)s:/tools/android-sdk18/tools:/tools/android-sdk18/platform-tools', 'DISPLAY': ':0.0', 'MINIDUMP_SAVEPATH': '%(abs_work_dir)s/../minidumps'}, 'emulator_process_name': 'emulator64-arm', 'default_sut_port1': '20701', 'download_symbols': 'ondemand', 'virtualenv_modules': (), 'default_sut_port2': '20700', 'test_suite_definitions': {'crashtest-5': {'category': 'reftest', 'extra_args': ('--total-chunks', '5', '--this-chunk', '5', 'tests/testing/crashtest/crashtests.list')}, 'crashtest-4': {'category': 'reftest', 'extra_args': ('--total-chunks', '5', '--this-chunk', '4', 'tests/testing/crashtest/crashtests.list')}, 'mochitest-10': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '10', '--run-only-tests', 'android23.json')}, 'mochitest-11': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '11', '--run-only-tests', 'android23.json')}, 'mochitest-12': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '12', '--run-only-tests', 'android23.json')}, 'crashtest-2': {'category': 'reftest', 'extra_args': ('--total-chunks', '5', '--this-chunk', '2', 'tests/testing/crashtest/crashtests.list')}, 'xpcshell-2': {'category': 'xpcshell', 'extra_args': ('--total-chunks', '3', '--this-chunk', '2', '--manifest', 'tests/xpcshell_android.ini')}, 'reftest-10': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '10', 'tests/layout/reftests/reftest.list')}, 'xpcshell-1': {'category': 'xpcshell', 'extra_args': ('--total-chunks', '3', '--this-chunk', '1', '--manifest', 'tests/xpcshell_android.ini')}, 'crashtest-1': {'category': 'reftest', 'extra_args': ('--total-chunks', '5', '--this-chunk', '1', 'tests/testing/crashtest/crashtests.list')}, 'mochitest-gl': {'category': 'mochitest', 'extra_args': ('--test-path', 'content/canvas/test/webgl')}, 'crashtest-3': {'category': 'reftest', 'extra_args': ('--total-chunks', '5', '--this-chunk', '3', 'tests/testing/crashtest/crashtests.list')}, 'xpcshell-3': {'category': 'xpcshell', 'extra_args': ('--total-chunks', '3', '--this-chunk', '3', '--manifest', 'tests/xpcshell_android.ini')}, 'robocop-4': {'category': 'mochitest', 'extra_args': ('--total-chunks', '4', '--this-chunk', '4', '--robocop-path=../..', '--robocop-ids=fennec_ids.txt', '--robocop=robocop.ini')}, 'robocop-1': {'category': 'mochitest', 'extra_args': ('--total-chunks', '4', '--this-chunk', '1', '--robocop-path=../..', '--robocop-ids=fennec_ids.txt', '--robocop=robocop.ini')}, 'robocop-2': {'category': 'mochitest', 'extra_args': ('--total-chunks', '4', '--this-chunk', '2', '--robocop-path=../..', '--robocop-ids=fennec_ids.txt', '--robocop=robocop.ini')}, 'robocop-3': {'category': 'mochitest', 'extra_args': ('--total-chunks', '4', '--this-chunk', '3', '--robocop-path=../..', '--robocop-ids=fennec_ids.txt', '--robocop=robocop.ini')}, 'reftest-9': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '9', 'tests/layout/reftests/reftest.list')}, 'reftest-8': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '8', 'tests/layout/reftests/reftest.list')}, 'reftest-1': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '1', 'tests/layout/reftests/reftest.list')}, 'reftest-3': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '3', 'tests/layout/reftests/reftest.list')}, 'reftest-2': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '2', 'tests/layout/reftests/reftest.list')}, 'reftest-5': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '5', 'tests/layout/reftests/reftest.list')}, 'reftest-4': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '4', 'tests/layout/reftests/reftest.list')}, 'reftest-7': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '7', 'tests/layout/reftests/reftest.list')}, 'reftest-6': {'category': 'reftest', 'extra_args': ('--total-chunks', '10', '--this-chunk', '6', 'tests/layout/reftests/reftest.list')}, 'mochitest-2': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '2', '--run-only-tests', 'android23.json')}, 'mochitest-3': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '3', '--run-only-tests', 'android23.json')}, 'mochitest-1': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '1', '--run-only-tests', 'android23.json')}, 'mochitest-6': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '6', '--run-only-tests', 'android23.json')}, 'mochitest-7': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '7', '--run-only-tests', 'android23.json')}, 'mochitest-4': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '4', '--run-only-tests', 'android23.json')}, 'mochitest-5': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '5', '--run-only-tests', 'android23.json')}, 'mochitest-8': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '8', '--run-only-tests', 'android23.json')}, 'mochitest-9': {'category': 'mochitest', 'extra_args': ('--total-chunks', '12', '--this-chunk', '9', '--run-only-tests', 'android23.json')}, 'jsreftest-1': {'category': 'reftest', 'extra_args': ('../jsreftest/tests/jstests.list', '--total-chunks', '6', '--this-chunk', '1', '--extra-profile-file=jsreftest/tests/user.js')}, 'jsreftest-2': {'category': 'reftest', 'extra_args': ('../jsreftest/tests/jstests.list', '--total-chunks', '6', '--this-chunk', '2', '--extra-profile-file=jsreftest/tests/user.js')}, 'jsreftest-3': {'category': 'reftest', 'extra_args': ('../jsreftest/tests/jstests.list', '--total-chunks', '6', '--this-chunk', '3', '--extra-profile-file=jsreftest/tests/user.js')}, 'jsreftest-4': {'category': 'reftest', 'extra_args': ('../jsreftest/tests/jstests.list', '--total-chunks', '6', '--this-chunk', '4', '--extra-profile-file=jsreftest/tests/user.js')}, 'jsreftest-5': {'category': 'reftest', 'extra_args': ('../jsreftest/tests/jstests.list', '--total-chunks', '6', '--this-chunk', '5', '--extra-profile-file=jsreftest/tests/user.js')}, 'jsreftest-6': {'category': 'reftest', 'extra_args': ('../jsreftest/tests/jstests.list', '--total-chunks', '6', '--this-chunk', '6', '--extra-profile-file=jsreftest/tests/user.js')}}, 'robocop_package_name': 'org.mozilla.roboexample.test', 'device-id': 'emulator-5554', 'device_ip': '127.0.0.1', 'emulators': ({'http_port': '8854', 'ssl_port': '4454', 'name': 'test-1', 'sut_port1': 20701, 'sut_port2': 20700, 'emulator_port': 5554, 'device_id': 'emulator-5554'}, {'http_port': '8856', 'ssl_port': '4456', 'name': 'test-2', 'sut_port1': 20703, 'sut_port2': 20702, 'emulator_port': 5556, 'device_id': 'emulator-5556'}, {'http_port': '8858', 'ssl_port': '4458', 'name': 'test-3', 'sut_port1': 20705, 'sut_port2': 20704, 'emulator_port': 5558, 'device_id': 'emulator-5558'}, {'http_port': '8860', 'ssl_port': '4460', 'name': 'test-4', 'sut_port1': 20707, 'sut_port2': 20706, 'emulator_port': 5560, 'device_id': 'emulator-5560'}), 'tooltool_cacheable_artifacts': {'avd_tar_ball': ('AVDs-armv7a-gingerbread-build-2014-01-23-ubuntu.tar.gz', '7140e026b7b747236545dc30e377a959b0bdf91bb4d70efd7f97f92fce12a9196042503124b8df8d30c2d97b7eb5f9df9556afdffa0b5d9625008aead305c32b')}, 'remote_webserver': '10.0.2.2', 'config_files': ('android/androidarm.py',), 'test_suites': ('mochitest-3',), 'exes': {'python': '/tools/buildbot/bin/python', 'virtualenv': ('/tools/buildbot/bin/python', '/tools/misc-python/virtualenv.py'), 'adb': '/tools/android-sdk18/platform-tools/adb'}, 'log_level': 'info', 'emulator_cpu': 'cortex-a9', 'opt_config_files': (), 'default_actions': ('clobber', 'read-buildbot-config', 'download-cacheable-artifacts', 'setup-avds', 'start-emulators', 'download-and-extract', 'create-virtualenv', 'install', 'run-tests', 'stop-emulators'), 'base_work_dir': '/builds/slave/test', 'download_minidump_stackwalk': True, 'work_dir': 'build', '.avds_dir': '/home/cltbld/.android', 'require_test_zip': True, 'pip_index': True, 'buildbot_json_path': 'buildprops.json', 'virtualenv_requirements': ()}
19:31:20     INFO - Installing Fennec for test-1
19:31:20     INFO - Getting output from command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date']
19:31:20     INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date
19:31:20     INFO - Reading from file tmpfile_stdout
19:31:20     INFO - Output received:
19:31:20     INFO -  Sun Apr 27 19:31:19 PDT 2014
19:31:20     INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stderr',), kwargs: {}, attempt #1
19:31:20     INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stdout',), kwargs: {}, attempt #1
19:31:20     INFO - Sun Apr 27 19:31:19 PDT 2014
19:31:20     INFO - Running command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date', '1398652280.28']
19:31:20     INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date 1398652280.28
19:31:20     INFO -  time 1398652280.28 -> 1398652280.0
19:31:20     INFO -  settimeofday failed Invalid argument
19:31:20     INFO - Return code: 0
19:31:20     INFO - Getting output from command: ['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'shell', 'date']
19:31:20     INFO - Copy/paste: /tools/android-sdk18/platform-tools/adb -s emulator-5554 shell date

command timed out: 2400 seconds without output, attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=2869.968596
========= Finished '/tools/buildbot/bin/python scripts/scripts/android_emulator_unittest.py ...' failed (results: 2, elapsed: 47 mins, 49 secs) (at 2014-04-27 20:11:20.557096) =========

Comment 14

[Geoff Brown [:gbrown]]

Bug 1003239 did not help:


https://tbpl.mozilla.org/php/getParsedLog.php?id=38935074&tree=Mozilla-Central
Android 2.3 Emulator mozilla-central opt test mochitest-5 on 2014-05-02
06:29:43
revision: 66ea09d0c951
slave: tst-linux64-spot-843

Automation Error: mozprocess timed out after 300 seconds running
['/tools/android-sdk18/platform-tools/adb', '-s', 'emulator-5554', 'install',
'-r', '/builds/slave/test/build/fennec-32.0a1.en-US.android-arm.apk']
timed out after 300 seconds of no output
Return code: -9
-9 not in success codes: [0]
Halting on failure while running ['/tools/android-sdk18/platform-tools/adb',
'-s', 'emulator-5554', 'install', '-r',
'/builds/slave/test/build/fennec-32.0a1.en-US.android-arm.apk']
Running post_fatal callback...
Exiting 3
command timed out: 2400 seconds without output, attempting to kill

Comment 15

[Geoff Brown [:gbrown]]

:bc -- You mentioned you were experiencing adb timeout/hang issues recently. Can you offer any insight?

Comment 16

[Bob Clary [:bc] (inactive)]

I found that on my nexus one's and nexus s's particularly (both are Android 2.3.x) that I would experience a situation where devicemanagerADB's command to execute shell commands on the device would simply not terminate. The adb process would appear in the process tree but I could not identify the cause for why the process didn't terminate.

DM commands that retrieved the output of the shell command via DM._runCmd(...).stdout.read() would block and stop the script from proceeding. The inability to terminate an adb process after a timeout period prevented me from recovering in my case.

In addition, devicemanager appears to sometimes not indicate device related failures.

I am working on a local replacement for devicemanager in bug 990601 and hope to uplift some of the lessons I have learned back to devicemanager. I should have a patch attached to the bug later today that you can look over. The lessons basically come down to always provide the ability to timeout an adb command and always make certain you are detecting error conditions on the device.

Hope that helps.

Comment 17

[Geoff Brown [:gbrown]]

Thanks :bc.

I speculate that adb is intermittently not terminating and that is not being handled well by the mozprocess ProcessHandler...or maybe the output parser?

I'm not sure how to proceed and am not finding much time for this -- unassigning myself in hopes that someone else would like to sort it out...

Comment 18

[Geoff Brown [:gbrown]]

The output timeout I added in this bug was over-written by my changes in bug 1137320, which may have contributed to on-going problems for android 2.3 and 4.3 (bug 1051908). I have a new solution on the way in bug 1123828.

Comment 19

[Geoff Brown [:gbrown]]

Bug 1123828 effectively eliminated install-time hangs by running adb with a timeout and re-trying on failure. So far the only new install-time hangs I have seen happened on machines that were not running x-session-manager -- https://bugzilla.mozilla.org/show_bug.cgi?id=1167830#c5 ... hopefully a rare event.

Hangs continue to be reported in bug 1051908, but they seem to be run-time (while tests are running).