Intermittent ValueError: invalid literal for int() with base 10: '' for adb_android.py

RESOLVED FIXED in Firefox 67

Status

defect
P2
normal
RESOLVED FIXED
7 months ago
5 months ago

People

(Reporter: intermittent-bug-filer, Assigned: gbrown)

Tracking

({intermittent-failure})

Version 3
mozilla67
Points:
---

Firefox Tracking Flags

(firefox67 fixed)

Details

Attachments

(1 attachment)

Reporter

Description

7 months ago
treeherder
Filed by: aiakab [at] mozilla.com

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

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

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/Ko5CafqgT1mUbNxYeDwa7Q/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2018-11-21T22:31:41.781Z] 22:31:41     INFO - root      2143  2141  9864   1988           0 73c9b7dc7507 R ps
[task 2018-11-21T22:31:41.781Z] 22:31:41     INFO - Running post-action listener: _resource_record_post_action
[task 2018-11-21T22:31:41.781Z] 22:31:41     INFO - [mozharness: 2018-11-21 22:31:41.781698Z] Finished verify-device step (success)
[task 2018-11-21T22:31:41.781Z] 22:31:41     INFO - [mozharness: 2018-11-21 22:31:41.781808Z] Running install step.
[task 2018-11-21T22:31:41.781Z] 22:31:41     INFO - Running pre-action listener: _resource_record_pre_action
[task 2018-11-21T22:31:41.781Z] 22:31:41     INFO - Running main action method: install
[task 2018-11-21T22:31:43.787Z] 22:31:43     INFO - Finished installing apps for emulator-5554
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - Running post-action listener: _resource_record_post_action
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - [mozharness: 2018-11-21 22:31:43.787874Z] Finished install step (success)
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - [mozharness: 2018-11-21 22:31:43.787974Z] Running run-tests step.
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - Running pre-action listener: _resource_record_pre_action
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - Running pre-action listener: _set_gcov_prefix
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - Running pre-action listener: timed_screenshots
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - Running main action method: run_tests
[task 2018-11-21T22:31:43.788Z] 22:31:43     INFO - Running the command /builds/worker/workspace/build/venv/bin/python -u /builds/worker/workspace/build/tests/reftest/remotereftest.py --app=org.mozilla.geckoview.test --ignore-window-size --remote-webserver=10.0.2.2 --xre-path=/builds/worker/workspace/build/hostutils/host-utils-61.0a1.en-US.linux-x86_64 --utility-path=/builds/worker/workspace/build/hostutils/host-utils-61.0a1.en-US.linux-x86_64 --http-port=8854 --ssl-port=4454 --httpd-path /builds/worker/workspace/build/tests/modules --symbols-path=https://queue.taskcluster.net/v1/task/T3gBrpAfTEerWOzLxLS-6A/artifacts/public/build/target.crashreporter-symbols.zip --suite=crashtest --log-tbpl-level=info --deviceSerial=emulator-5554 -- tests/testing/crashtest/crashtests.list
[task 2018-11-21T22:31:43.789Z] 22:31:43     INFO - ##### crashtest log begins
[task 2018-11-21T22:31:43.789Z] 22:31:43     INFO - Running command: ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/reftest/remotereftest.py', '--app=org.mozilla.geckoview.test', '--ignore-window-size', '--remote-webserver=10.0.2.2', '--xre-path=/builds/worker/workspace/build/hostutils/host-utils-61.0a1.en-US.linux-x86_64', '--utility-path=/builds/worker/workspace/build/hostutils/host-utils-61.0a1.en-US.linux-x86_64', '--http-port=8854', '--ssl-port=4454', '--httpd-path', '/builds/worker/workspace/build/tests/modules', '--symbols-path=https://queue.taskcluster.net/v1/task/T3gBrpAfTEerWOzLxLS-6A/artifacts/public/build/target.crashreporter-symbols.zip', '--suite=crashtest', '--log-tbpl-level=info', '--deviceSerial=emulator-5554', '--', 'tests/testing/crashtest/crashtests.list'] in /builds/worker/workspace/build/tests/reftest
[task 2018-11-21T22:31:43.789Z] 22:31:43     INFO - Copy/paste: /builds/worker/workspace/build/venv/bin/python -u /builds/worker/workspace/build/tests/reftest/remotereftest.py --app=org.mozilla.geckoview.test --ignore-window-size --remote-webserver=10.0.2.2 --xre-path=/builds/worker/workspace/build/hostutils/host-utils-61.0a1.en-US.linux-x86_64 --utility-path=/builds/worker/workspace/build/hostutils/host-utils-61.0a1.en-US.linux-x86_64 --http-port=8854 --ssl-port=4454 --httpd-path /builds/worker/workspace/build/tests/modules --symbols-path=https://queue.taskcluster.net/v1/task/T3gBrpAfTEerWOzLxLS-6A/artifacts/public/build/target.crashreporter-symbols.zip --suite=crashtest --log-tbpl-level=info --deviceSerial=emulator-5554 -- tests/testing/crashtest/crashtests.list
[task 2018-11-21T22:31:43.789Z] 22:31:43     INFO - Using env: (same as previous command)
[task 2018-11-21T22:31:45.386Z] 22:31:45     INFO -  Using adb 1.0.40
[task 2018-11-21T22:31:45.489Z] 22:31:45     INFO -  adbd running as root
[task 2018-11-21T22:31:45.694Z] 22:31:45     INFO -  su 0 supported
[task 2018-11-21T22:31:45.899Z] 22:31:45     INFO -  /system/bin/ls -1A supported
[task 2018-11-21T22:31:46.002Z] 22:31:46     INFO -  Native cp support: True
[task 2018-11-21T22:31:46.103Z] 22:31:46     INFO -  Native chmod -R support: True
[task 2018-11-21T22:31:46.206Z] 22:31:46     INFO -  Native chown -R support: True
[task 2018-11-21T22:31:51.593Z] 22:31:51     INFO -  Setting SELinux Permissive
[task 2018-11-21T22:31:51.799Z] 22:31:51     INFO -  Traceback (most recent call last):
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -    File "/builds/worker/workspace/build/tests/reftest/remotereftest.py", line 440, in <module>
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -      sys.exit(run_test_harness(parser, options))
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -    File "/builds/worker/workspace/build/tests/reftest/remotereftest.py", line 391, in run_test_harness
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -      reftest = RemoteReftest(options, SCRIPT_DIRECTORY)
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -    File "/builds/worker/workspace/build/tests/reftest/remotereftest.py", line 155, in __init__
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -      verbose=verbose)
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb_android.py", line 100, in __init__
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -      timeout=timeout))
[task 2018-11-21T22:31:51.800Z] 22:31:51     INFO -  ValueError: invalid literal for int() with base 10: ''
[task 2018-11-21T22:31:51.810Z] 22:31:51    ERROR - Return code: 1
[task 2018-11-21T22:31:51.811Z] 22:31:51    ERROR - No tests run or test summary not found
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - TinderboxPrint: crashtest<br/><em class="testfail">T-FAIL</em>
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - ##### crashtest log ends
[task 2018-11-21T22:31:51.811Z] 22:31:51  WARNING - # TBPL WARNING #
[task 2018-11-21T22:31:51.811Z] 22:31:51  WARNING - setting return code to 1
[task 2018-11-21T22:31:51.811Z] 22:31:51  WARNING - The crashtest suite: crashtest ran with return status: WARNING
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - Running post-action listener: _package_coverage_data
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - Running post-action listener: _resource_record_post_action
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - Running post-action listener: process_java_coverage_data
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - Running post-action listener: stop_device
[task 2018-11-21T22:31:51.811Z] 22:31:51     INFO - Killing logcat pid 982.
[task 2018-11-21T22:31:51.812Z] 22:31:51     INFO - Killing every process called emulator64-x86
[task 2018-11-21T22:31:51.817Z] 22:31:51     INFO - Killing pid 489.
[task 2018-11-21T22:31:51.817Z] 22:31:51     INFO - [mozharness: 2018-11-21 22:31:51.817830Z] Finished run-tests step (success)
[task 2018-11-21T22:31:51.818Z] 22:31:51     INFO - Running post-run listener: _resource_record_post_run
[task 2018-11-21T22:31:51.856Z] 22:31:51     INFO - Total resource usage - Wall time: 15s; CPU: 24.0%; Read bytes: 27590656; Write bytes: 15370553344; Read time: 5624; Write time: 3167812
[task 2018-11-21T22:31:51.856Z] 22:31:51     INFO - TinderboxPrint: CPU usage<br/>23.7%
[task 2018-11-21T22:31:51.856Z] 22:31:51     INFO - TinderboxPrint: I/O read bytes / time<br/>27,590,656 / 5,624
[task 2018-11-21T22:31:51.856Z] 22:31:51     INFO - TinderboxPrint: I/O write bytes / time<br/>15,370,553,344 / 3,167,812
[task 2018-11-21T22:31:51.856Z] 22:31:51     INFO - TinderboxPrint: CPU guest<br/>2.0 (1.7%)
[task 2018-11-21T22:31:51.857Z] 22:31:51     INFO - TinderboxPrint: CPU idle<br/>63.3 (52.3%)
[task 2018-11-21T22:31:51.857Z] 22:31:51     INFO - TinderboxPrint: CPU iowait<br/>27.4 (22.7%)
[task 2018-11-21T22:31:51.858Z] 22:31:51     INFO - TinderboxPrint: CPU system<br/>5.6 (4.7%)
[task 2018-11-21T22:31:51.858Z] 22:31:51     INFO - TinderboxPrint: CPU user<br/>22.5 (18.6%)
[task 2018-11-21T22:31:51.859Z] 22:31:51     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2018-11-21T22:31:51.859Z] 22:31:51     INFO - verify-device - Wall time: 5s; CPU: 22.0%; Read bytes: 212992; Write bytes: 4447344640; Read time: 704; Write time: 926636
[task 2018-11-21T22:31:51.859Z] 22:31:51     INFO - install - Wall time: 2s; CPU: 31.0%; Read bytes: 335872; Write bytes: 575684608; Read time: 1072; Write time: 201640
[task 2018-11-21T22:31:51.859Z] 22:31:51     INFO - run-tests - Wall time: 8s; CPU: 23.0%; Read bytes: 27033600; Write bytes: 8567091200; Read time: 3768; Write time: 1615740
[task 2018-11-21T22:31:51.864Z] 22:31:51  WARNING - returning nonzero exit status 1
[task 2018-11-21T22:31:51.875Z] cleanup
[task 2018-11-21T22:31:51.875Z] + cleanup
[task 2018-11-21T22:31:51.875Z] + local rv=1
[task 2018-11-21T22:31:51.875Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2018-11-21T22:31:51.875Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2018-11-21T22:31:51.876Z] + true
[task 2018-11-21T22:31:51.876Z] + cleanup_xvfb
[task 2018-11-21T22:31:51.877Z] pidof Xvfb
[task 2018-11-21T22:31:51.877Z] ++ pidof Xvfb
[task 2018-11-21T22:31:51.879Z] + local xvfb_pid=25
[task 2018-11-21T22:31:51.879Z] + local vnc=false
[task 2018-11-21T22:31:51.879Z] + local interactive=false
[task 2018-11-21T22:31:51.879Z] + '[' -n 25 ']'
[task 2018-11-21T22:31:51.879Z] + [[ false == false ]]
[task 2018-11-21T22:31:51.879Z] + [[ false == false ]]
[task 2018-11-21T22:31:51.879Z] + kill 25
[task 2018-11-21T22:31:51.879Z] + screen -XS xvfb quit
[task 2018-11-21T22:31:51.886Z] XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
[task 2018-11-21T22:31:51.887Z]       after 1246 requests (1246 known processed) with 0 events remaining.
[task 2018-11-21T22:31:51.887Z] compizconfig - Info: Backend     : ini
[task 2018-11-21T22:31:51.887Z] compizconfig - Info: Integration : true
[task 2018-11-21T22:31:51.887Z] compizconfig - Info: Profile     : default
[task 2018-11-21T22:31:51.972Z] No screen session found.
[task 2018-11-21T22:31:51.972Z] + true
[task 2018-11-21T22:31:51.973Z] + exit 1
[taskcluster 2018-11-21 22:31:52.271Z] === Task Finished ===
[taskcluster 2018-11-21 22:31:57.635Z] Unsuccessful task run with exit code: 1 completed in 97.719 seconds
Why should this be firefox ui tests? Moving it to the correct component.
Component: Firefox UI Tests → Reftest
QA Contact: hskupin
Summary: Intermittent ValueError: invalid literal for int() with base 10: '' → Intermittent ValueError: invalid literal for int() with base 10: '' for adb_android.py
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)

:gbrown, should this be an auto retry? from an unfamiliar point of view this looks like we cannot connect to the emulator.

Component: Reftest → General
Flags: needinfo?(gbrown)
Assignee

Comment 10

5 months ago

We have connected to the emulator and run adb commands earlier, but requesting the api level fails ("getprop ro.build.version.sdk" returns ''). Maybe boot hasn't fully completed, somehow? Let's catch the ValueError, maybe retry in adb.py, and fail with an ADBError if the condition persists. I'll put together a simple patch.

Assignee: nobody → gbrown
Flags: needinfo?(gbrown)
Priority: P5 → P2
Assignee

Comment 11

5 months ago

I do not know if this will be effective, but I think it is worth a try.

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=ed2c9a03710fdd8c28ce97e239e7f99cdf6fbbee

(This version of the patch has corrected for the f8 error in the try push.)

Attachment #9040756 - Flags: review?(bob)

Comment 12

5 months ago
Comment on attachment 9040756 [details] [diff] [review]
wait and retry for valid android version

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

r+

::: testing/mozbase/mozdevice/mozdevice/adb.py
@@ +735,5 @@
> +            except ValueError:
> +                self._logger.info("unexpected ro.build.version.sdk: '%s'" % version)
> +                time.sleep(2)
> +        if self.version < 1:
> +            raise ADBTimeoutError("ADBDevice: unable to determine ro.build.version.sdk.")

Not sure how I feel about overloading ADBTimeoutError in this way.

It has pretty specific semantics now in that it means an adb command didn't return within the specified timeout period, but this doesn't quite fit that. But, the way we use ADBTimeoutError as an unrecoverable exception does fit with what you want here. Otherwise it might require modifying all the different ADBError except blocks in callers.

Can you add a comment here explaining the rationale for breaking the convention?
Attachment #9040756 - Flags: review?(bob) → review+
Assignee

Comment 13

5 months ago

I am open to adding a comment or using a different error, if you prefer.

There is an existing use of ADBTimeoutError just a little earlier, at

https://searchfox.org/mozilla-central/rev/e62b311b2e0e02633afda2004ba4056b09fbcaa4/testing/mozbase/mozdevice/mozdevice/adb.py#685

which was my inspiration.

Comment 14

5 months ago

Good point. I missed that. /nick Roseanne Roseannadanna: Never mind.

Comment 15

5 months ago
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0f6e106e3efd
In android tests, wait for valid ro.build.version.sdk; r=bc

Comment 16

5 months ago
bugherder
Status: NEW → RESOLVED
Closed: 5 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.