Closed Bug 1634909 Opened 5 months ago Closed 4 months ago

Intermittent raptor-perftest Critical: Failed to run <test_name>: tab is undefined

Categories

(Testing :: Raptor, defect, P1)

Version 3
defect

Tracking

(firefox78 fixed)

RESOLVED FIXED
mozilla78
Tracking Status
firefox78 --- fixed

People

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

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

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


[task 2020-05-02T05:10:09.149Z] 05:09:54 INFO - raptor-webext-android Info: starting fennec
[task 2020-05-02T05:10:09.149Z] 05:09:55 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell am force-stop org.mozilla.firefox, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:09:55 INFO - adb Granting important runtime permissions to org.mozilla.firefox
[task 2020-05-02T05:10:09.149Z] 05:09:56 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pm grant org.mozilla.firefox android.permission.WRITE_EXTERNAL_STORAGE, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:09:57 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pm grant org.mozilla.firefox android.permission.READ_EXTERNAL_STORAGE, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:09:58 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pm grant org.mozilla.firefox android.permission.ACCESS_COARSE_LOCATION, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:09:59 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pm grant org.mozilla.firefox android.permission.ACCESS_FINE_LOCATION, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:00 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pm grant org.mozilla.firefox android.permission.CAMERA, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:01 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pm grant org.mozilla.firefox android.permission.RECORD_AUDIO, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:01 INFO - adb launch_application: am start -W -n org.mozilla.firefox/org.mozilla.gecko.BrowserApp -a android.intent.action.VIEW --es args "-profile /data/local/tmp/tests/raptor/profile --allow-downgrade --es env0 LOG_VERBOSE=1 --es env1 R_LOG_LEVEL=6 --es env2 MOZ_WEBRENDER=0 --es env3 MOZ_CRASHREPORTER_SHUTDOWN=1" -d about:blank
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell am start -W -n org.mozilla.firefox/org.mozilla.gecko.BrowserApp -a android.intent.action.VIEW --es args "-profile /data/local/tmp/tests/raptor/profile --allow-downgrade --es env0 LOG_VERBOSE=1 --es env1 R_LOG_LEVEL=6 --es env2 MOZ_WEBRENDER=0 --es env3 MOZ_CRASHREPORTER_SHUTDOWN=1" -d about:blank, timeout: None, root: False, timedout: None, exitcode: 0, output: Starting: Intent { act=android.intent.action.VIEW dat=about:blank cmp=org.mozilla.firefox/org.mozilla.gecko.BrowserApp (has extras) }
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - Status: ok
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - Activity: org.mozilla.firefox/org.mozilla.gecko.BrowserApp
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - ThisTime: 1140
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - TotalTime: 1140
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - WaitTime: 1151
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - Complete
[task 2020-05-02T05:10:09.149Z] 05:10:03 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pidof org.mozilla.firefox, timeout: None, root: False, timedout: None, exitcode: 0, output: 11207
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pidof org.mozilla.firefox, timeout: None, root: False, timedout: None, exitcode: 0, output: 11207
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - raptor-control-server Info: received webext_loaded: raptor runner.js is loaded!
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - raptor-control-server Info: received webext_status: test name is: raptor-tp6m-instagram-fennec68-cold
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - raptor-control-server Info: received webext_status: test settings url is: http://127.0.0.1:36279/json/raptor-tp6m-instagram-fennec68-cold.json
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - raptor-control-server Info: received webext_status: starting raptorRunner
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - raptor-control-server Info: reading test settings from json/raptor-tp6m-instagram-fennec68-cold.json
[task 2020-05-02T05:10:09.149Z] 05:10:04 INFO - raptor-control-server Info: sent test settings to webext runner
[task 2020-05-02T05:10:09.149Z] 05:10:05 INFO - raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-05-02T05:10:09.149Z] 05:10:05 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell pidof org.mozilla.firefox, timeout: None, root: False, timedout: None, exitcode: 0, output: 11207
[task 2020-05-02T05:10:09.149Z] 05:10:06 INFO - raptor-control-server Info: received webext_status: openinig new tab
[task 2020-05-02T05:10:09.149Z] 05:10:06 INFO - raptor-control-server Info: received webext_error: tab is undefined
[task 2020-05-02T05:10:09.149Z] 05:10:06 INFO - raptor-control-server Info: received request to shutdown the browser
[task 2020-05-02T05:10:09.149Z] 05:10:06 INFO - raptor-control-server Info: shutting down android app org.mozilla.firefox
[task 2020-05-02T05:10:09.149Z] 05:10:07 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell am force-stop org.mozilla.firefox, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:07 INFO - adb shell_bool: adb -s ZY3223F52J wait-for-device shell test -d /data/local/tmp/tests/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:07 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:08 INFO - adb shell_bool: adb -s ZY3223F52J wait-for-device shell test -d /data/local/tmp/tests/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:08 INFO - adb chmod: path=/data/local/tmp/tests/raptor/profile/minidumps, recursive=True, mask=777, root=True
[task 2020-05-02T05:10:09.149Z] 05:10:09 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell su -c "chmod -R 777 /data/local/tmp/tests/raptor/profile/minidumps", timeout: None, root: True, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:09.149Z] 05:10:09 INFO - adb command_output: adb -s ZY3223F52J wait-for-device pull /data/local/tmp/tests/raptor/profile/minidumps /tmp/tmpG8t76x/minidumps, timeout: None, timedout: None, exitcode: 0, output: /data/local/tmp/tests/raptor/profile/minidumps/: 0 files pulled, 0 skipped.
[task 2020-05-02T05:10:09.149Z] 05:10:09 CRITICAL - raptor-perftest Critical: Failed to run raptor-tp6m-instagram-fennec68-cold: tab is undefined
[task 2020-05-02T05:10:09.149Z] 05:10:09 INFO - Stack:
[task 2020-05-02T05:10:09.149Z] 05:10:09 INFO - openTab@moz-extension://8932c408-bcac-439e-9e06-225ecd1bf28e/runner.js:273:64
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - raptor-webext-android Info: removing reverse socket connections
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - adb command_output: adb -s ZY3223F52J wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - raptor-webext-android Info: skipping check_for_crashes: application has not been launched
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 858
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - raptor-mitmproxy Info: Reading confidence values from: /builds/task_1588395849/workspace/build/blobber_upload_dir/mitm_netlocs_mitm4-pixel2-fennec-instagram.json
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - perftest-results-handler Info: RaptorResultsHandler.add_supporting_data received mozproxy-replay data
[task 2020-05-02T05:10:39.057Z] 05:10:09 INFO - raptor-webext Info: removing webext /builds/task_1588395849/workspace/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-05-02T05:10:39.058Z] 05:10:09 INFO - raptor-webext-android Info: removing test folder for raptor: /data/local/tmp/tests/raptor
[task 2020-05-02T05:10:39.058Z] 05:10:09 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:39.058Z] 05:10:10 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell su -c "rm -r /data/local/tmp/tests/raptor", timeout: None, root: True, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:39.058Z] 05:10:10 INFO - adb shell_output: adb -s ZY3223F52J wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - adb shell_bool: adb -s ZY3223F52J wait-for-device shell su -c "test -e /data/local/tmp/tests/raptor", timeout: None, root: True, timedout: None, exitcode: 1, output:
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpSfKIKJ
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpGEW6In
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpyHn9gx
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpYi9k3Q
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmp8z0H2o
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmp4SX0fT
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmp0f5uMO
[task 2020-05-02T05:10:39.058Z] 05:10:11 INFO - raptor-control-server Info: shutting down control server
[task 2020-05-02T05:10:39.058Z] 05:10:12 INFO - raptor-webext Info: finished
[task 2020-05-02T05:10:39.058Z] 05:10:12 ERROR - Return code: 1
[task 2020-05-02T05:10:39.058Z] 05:10:12 WARNING - setting return code to 1
[task 2020-05-02T05:10:39.058Z] 05:10:12 INFO - Killing logcat pid 621.
[task 2020-05-02T05:10:39.058Z] 05:10:12 INFO - Copying Raptor results to upload dir:
[task 2020-05-02T05:10:39.058Z] 05:10:12 INFO - /builds/task_1588395849/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2020-05-02T05:10:39.058Z] 05:10:12 INFO - Copying raptor results from /builds/task_1588395849/workspace/build/raptor.json to /builds/task_1588395849/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2020-05-02T05:10:39.058Z] 05:10:12 CRITICAL - Error copying results /builds/task_1588395849/workspace/build/raptor.json to upload dir /builds/task_1588395849/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2020-05-02T05:10:39.058Z] 05:10:12 INFO - [Errno 2] No such file or directory: u'/builds/task_1588395849/workspace/build/raptor.json'

Summary: Intermittent raptor-perftest Critical: Failed to run raptor-tp6m-instagram-fennec68-cold: tab is undefined → Intermittent raptor-perftest Critical: Failed to run <test_name>: tab is undefined

As the Javascript stack shows this comes from:

[task 2020-05-02T05:10:09.149Z] 05:10:09     INFO -  Stack:
[task 2020-05-02T05:10:09.149Z] 05:10:09     INFO -  openTab@moz-extension://8932c408-bcac-439e-9e06-225ecd1bf28e/runner.js:273:64
[task 2020-05-02T05:10:39.057Z] 05:10:09     INFO -  raptor-webext-android Info: removing reverse socket connections

From the adb logcat it fails right after:

05-02 05:10:05.212 11207 11228 I Gecko   : console.info: "[raptor-runnerjs] pageload test start"

Which means it's caused by this code:
https://searchfox.org/mozilla-central/rev/3262e013550a0db7c1840a78a3878a929801fe40/testing/raptor/webext/raptor/runner.js#742-745

With bug 1634371 fixed a new tab will only be opened if requested by the test. And that's not happening here.

Depends on: 1634371

Andrew or Rob, does one of you have an idea why creating a new tab in Fennec via the tabs.create() method can return undefined?

https://searchfox.org/mozilla-central/rev/fa52bedc4b401c12251513fa1c9df1753a29abb2/testing/raptor/webext/raptor/runner.js#264-273

Flags: needinfo?(rob)
Flags: needinfo?(andrew.swan)

I don't see how tabs.create could be succesful and return undefined. However, it could be that the call wasn't actually succesful:

From logcat ( https://firefoxci.taskcluster-artifacts.net/Catv8yMmSMe7nJUK1oZxnw/0/public/test_info/logcat-ZY3223F52J.log ):

05-02 05:10:04.898 11207 11228 I Gecko   : console.info: "[raptor-runnerjs] testing on undefined"
05-02 05:10:04.903 11207 11228 I Gecko   : console.info: "[raptor-runnerjs] getting test settings from control server"
05-02 05:10:05.020 11207 11228 I Gecko   : console.info: "[raptor-runnerjs] test settings received: {\"raptor-options\": {\"expected_browser_cycles\": 15, \"subtest_unit\": \"ms\", \"alert_threshold\": 2.0, \"type\": \"pageload\", \"page_cycles\": 1, \"subtest_lower_is_better\": true, \"alert_on\": [\"loadtime\"], \"test_url\": \"https://www.instagram.com\", \"page_timeout\": 60000, \"host\": \"127.0.0.1\", \"measure\": {\"dcf\": true, \"fnbpaint\": true, \"loadtime\": true}, \"cold\": true, \"lower_is_better\": true, \"unit\": \"ms\"}}"
05-02 05:10:05.021 11207 11228 I Gecko   : console.info: "[raptor-runnerjs] test URL: https://www.instagram.com"
05-02 05:10:05.022 11207 11228 I Gecko   : console.info: "[raptor-runnerjs] using page timeout: 60000ms"

The "testing on " message is from https://searchfox.org/mozilla-central/rev/fa52bedc4b401c12251513fa1c9df1753a29abb2/testing/raptor/webext/raptor/runner.js#207,212,218. Line 207 would always yield a non-undefined value, so this suggests that the first branch is not taken, i.e. isGecko is falsey.

If isGecko is falsey, tab from openTab isn't the return value of tabs.create, but potentially an ignored error from the callback version of tabs.create. On error, the callback is be called withundefinedand extensions are then supposed to checkext.runtime.lastError` (this doesn't happen in https://searchfox.org/mozilla-central/rev/fa52bedc4b401c12251513fa1c9df1753a29abb2/testing/raptor/webext/raptor/runner.js#268-270 ).

tabs.create could fail if the given url is invalid, but that doesn't seem to apply here. That leaves unexpected runtime errors. Could it be that the browser hasn't finished initializing when the extension is called? In that case I could imagine the window / topWindow being null, and already fail early at https://searchfox.org/mozilla-esr68/rev/61544ef9f3c99d5679ce4c26a5b1ae36dc075ae9/mobile/android/components/extensions/ext-tabs.js#293-298

The test runner does have a time-based wait (introduced in bug 1461414), which looks suspicious.

[task 2020-05-02T05:10:09.149Z] 05:10:05     INFO -  raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-05-02T05:10:09.149Z] 05:10:05     INFO -  adb shell_output: adb -s ZY3223F52J wait-for-device shell pidof org.mozilla.firefox, timeout: None, root: False, timedout: None, exitcode: 0, output: 11207
[task 2020-05-02T05:10:09.149Z] 05:10:06     INFO -  raptor-control-server Info: received webext_status: openinig new tab
[task 2020-05-02T05:10:09.149Z] 05:10:06     INFO -  raptor-control-server Info: received webext_error: tab is undefined

To fix the isGecko check, I suggest to add "fennec" to the list of GECKO_BROWSERS. Note that unlike Python, JS doesn't concatenate arrays with +, so replace the existing + with .concat. The code currently works because strings also have a .includes method (substring check). Fixing isGecko will probably not fix this bug itself (but there is a very slim chance that the extra delay from the async getBrowserInfo call may change the observed behavior), but the error condition should be more clear.

Flags: needinfo?(rob)
Flags: needinfo?(andrew.swan)

Oh wow, a lot to distill here. Great investigation Rob! Once I got my build system running I will have a look.

I feel we shouldn't do the browser selection based on some hard-coded values. Instead we should use the webext API to at least figure out if the current browser is Gecko-based or Chrome. That would solve the above problem partially.

I wonder if there is a special flag for GeckoView based browsers so we can differentiate those from Fennec on Android. It seems like it's not part of the browser info:

https://developer.mozilla.org/en-US/docs/Mozilla/Add-ons/WebExtensions/API/runtime/getBrowserInfo

Rob, any idea how to do that? Specifically which also works for the WebExt from the esr68 branch?

Flags: needinfo?(rob)

The getBrowserInfo method doesn't exist in Chrome (https://crbug.com/1047907).

Fennec support ends at esr68.
Initial WebExtension support in GeckoView landed in 67 (loading temporary add-ons), but the management of installed add-ons were only added in GV 73.

If you don't care about GV 67 and GV 68, you could consider treating <= 68.x as Fennec and >= 69 as GV.

Flags: needinfo?(rob)

Thanks for all your help Rob! I think I have something working fine. Lets see how it looks like in this try build:

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

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a4421710edc8
[raptor] Improved Gecko/Chrome browser detection for web extension. r=perftest-reviewers,sparky
https://hg.mozilla.org/integration/autoland/rev/5d7e631388fa
[raptor] Remove deprecated browser name from webextension config. r=perftest-reviewers,sparky
Status: ASSIGNED → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla78
Priority: P5 → P1
You need to log in before you can comment on or make changes to this bug.