1632391 - Intermittent Android raptor-perftest Critical: Process has been unexpectedly closed

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: aiakab [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=298959283&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YZ_--I88RriqAm8u8Irrdg/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell am start -W -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -a android.intent.action.MAIN -d about:blank, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.MAIN dat=about:blank cmp=org.mozilla.geckoview_example/.GeckoViewActivity }
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - Status: ok
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - Activity: org.mozilla.geckoview_example/.GeckoViewActivity
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - ThisTime: 387
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - TotalTime: 387
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - WaitTime: 390
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - Complete
[task 2020-04-23T02:51:46.628Z] 02:51:44 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 9408
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: received webext_loaded: raptor runner.js is loaded!
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: received webext_status: test name is: raptor-tp6m-bbc-geckoview-cold
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: received webext_status: test settings url is: http://127.0.0.1:57525/json/raptor-tp6m-bbc-geckoview-cold.json
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: received webext_status: starting raptorRunner
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: reading test settings from json/raptor-tp6m-bbc-geckoview-cold.json
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: sent test settings to webext runner
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-04-23T02:51:46.628Z] 02:51:45 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 9408
[task 2020-04-23T02:51:59.818Z] 02:51:46 INFO - raptor-control-server Info: received webext_status: running 1 pagecycles of https://www.bbc.com/news/business-47245877
[task 2020-04-23T02:51:59.818Z] 02:51:46 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 9408
[task 2020-04-23T02:51:59.818Z] 02:51:47 INFO - raptor-control-server Info: received webext_status: begin page cycle 1
[task 2020-04-23T02:51:59.818Z] 02:51:47 INFO - raptor-control-server Info: received webext_status: found active tab with id 10001
[task 2020-04-23T02:51:59.818Z] 02:51:47 INFO - raptor-control-server Info: received webext_status: update tab 10001 for https://www.bbc.com/news/business-47245877
[task 2020-04-23T02:51:59.818Z] 02:51:47 INFO - raptor-control-server Info: received webext_status: tab 10001 updated
[task 2020-04-23T02:51:59.818Z] 02:51:47 INFO - raptor-control-server Info: received webext_status: ended page cycle 1
[task 2020-04-23T02:51:59.818Z] 02:51:48 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 9408
[task 2020-04-23T02:51:59.818Z] 02:51:49 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell pidof org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output: 9408
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: received webext_status: results received
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 15, u'subtest_unit': u'ms', u'name': u'raptor-tp6m-bbc-geckoview-cold', u'lower_is_better': True, u'measurements': {u'dcf': [1484], u'fcp': [1134], u'fnbpaint': [1064], u'loadtime': [2222]}, u'browser_cycle': u'9', u'subtest_lower_is_better': True, u'cold': True, u'browser': u'GeckoView Example 77.0a1 20200423005435', u'type': u'pageload', u'page': u'https://www.bbc.com/news/business-47245877', u'unit': u'ms', u'alert_threshold': 2}
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - perftest-results-handler Info: received results in RaptorResultsHandler.add
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: received webext_status: Not closing last Tab: 10001
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: received request to shutdown the browser
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: shutting down android app org.mozilla.geckoview_example
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - adb shell_bool: adb -s FA7A51A00163 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - adb shell_bool: adb -s FA7A51A00163 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - adb command_output: adb -s FA7A51A00163 wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmpWS3h7O/minidumps, timeout: None, timedout: None, exitcode: 0, output: /sdcard/raptor/profile/minidumps/: 0 files pulled, 0 skipped.
[task 2020-04-23T02:51:59.818Z] 02:51:50 CRITICAL - raptor-perftest Critical: Process has been unexpectedly closed
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-webext-android Info: removing reverse socket connections
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - adb command_output: adb -s FA7A51A00163 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-webext-android Info: skipping check_for_crashes: application has not been launched
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 794
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-mitmproxy Info: Reading confidence values from: /builds/task_1587610071/workspace/build/blobber_upload_dir/mitm_netlocs_mitm4-pixel2-fennec-bbc.json
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - perftest-results-handler Info: RaptorResultsHandler.add_supporting_data received mozproxy-replay data
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-webext Info: removing webext /builds/task_1587610071/workspace/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-webext-android Info: removing test folder for raptor: /sdcard/raptor
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell rm -r /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - adb shell_output: adb -s FA7A51A00163 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - adb shell_bool: adb -s FA7A51A00163 wait-for-device shell test -e /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 1, output:
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpPvMnW4
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpfr9Qiq
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpnXcaKe
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpfxEydg
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpb2q1cz
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpO7vFs0
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpM9qkt3
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpZJ4l2s
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpZS5eIz
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-control-server Info: shutting down control server
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - raptor-webext Info: finished
[task 2020-04-23T02:51:59.818Z] 02:51:51 ERROR - Return code: 1
[task 2020-04-23T02:51:59.818Z] 02:51:51 WARNING - setting return code to 1
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Killing logcat pid 601.
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Copying Raptor results to upload dir:
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - /builds/task_1587610071/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Copying raptor results from /builds/task_1587610071/workspace/build/raptor.json to /builds/task_1587610071/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2020-04-23T02:51:59.818Z] 02:51:51 CRITICAL - Error copying results /builds/task_1587610071/workspace/build/raptor.json to upload dir /builds/task_1587610071/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - [Errno 2] No such file or directory: u'/builds/task_1587610071/workspace/build/raptor.json'
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Running post-action listener: _package_coverage_data
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Running post-action listener: process_java_coverage_data
[task 2020-04-23T02:51:59.818Z] 02:51:51 INFO - Running post-action listener: stop_device
[task 2020-04-23T02:51:59.818Z] 02:51:54 INFO - Killing logcat pid 601.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

So this is actually an expected shutdown:

[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: received request to shutdown the browser
[task 2020-04-23T02:51:59.818Z] 02:51:50 INFO - raptor-control-server Info: shutting down android app org.mozilla.geckoview_example
...
[task 2020-04-23T02:51:59.818Z] 02:51:50 CRITICAL - raptor-perftest Critical: Process has been unexpectedly closed

And I assume it's a race given that the process check happens at the exact same time as the control server is shutting down the app. Means the _is_shutting_down flag might not have been recognized by the other thread yet.

This is a regression from bug 1630037, which I thought would have already been fixed, given that my try build was green for that other bug. But as it looks like it's only affecting P2 devices, which are faster.

I will have a look.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

While investigating I just found that, which is not something how timeout calculation should be done:
https://searchfox.org/mozilla-central/source/testing/raptor/raptor/webextension/base.py#102,113,117-118

I will fix it along the lines.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Bug 1632391 - [raptor] Fix timeout handling when shutting down the application.

Sleeping a second and increasing the elapsed time by 1,
doesn't mean that exactly a second has been passed-by.

For a better timeout handling the end time has to be
calculated first, and then checked against.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Bug 1632391 - [raptor] Give enough time to sync the shutdown flags.

Depends on D72132

Comment 5

[Intermittent Failures Robot]

15 failures in 230 pushes (0.065 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 12
• try: 2
• mozilla-central: 1

Platform breakdown:

• android-hw-p2-8-0-android-aarch64: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1632391&startday=2020-04-25&endday=2020-04-25&tree=all

Comment 6

[Intermittent Failures Robot]

43 failures in 5582 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #47 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 34
• mozilla-central: 7
• try: 2

Platform breakdown:

• android-hw-p2-8-0-android-aarch64: 43

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1632391&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Note that failures on this bug are all happening for Pixel2 for aarch64 only. I just pushed a new try build with some updates:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3c097b405e5542b94d1d3a7310af9a633b997c1

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/64937ae65eeb
[raptor] Fix timeout handling when shutting down the application. r=perftest-reviewers,sparky
https://hg.mozilla.org/integration/autoland/rev/1fd9c358e893
[raptor] Give enough time to sync the shutdown flags. r=perftest-reviewers,sparky

Comment 9

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/64937ae65eeb
https://hg.mozilla.org/mozilla-central/rev/1fd9c358e893

Comment 10

[Intermittent Failures Robot]

23 failures in 5423 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 20
• mozilla-central: 3

Platform breakdown:

• android-hw-p2-8-0-android-aarch64: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1632391&startday=2020-04-27&endday=2020-05-03&tree=all