1808231 - Frequent fenix browsertime [taskcluster:error] Aborting task...

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=401127404&repo=fenix
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KZQ3t02DTxKlJaFfHkI0Yg/runs/0/artifacts/public/logs/live_backing.log

---

~40% of browsertime tasks for fenix hit the run time limit. This issue started on 2022-12-31.

[task 2023-01-02T06:46:45.575Z] 06:46:37     INFO -  raptor-browsertime Info: Starting a browsertime pageload
[task 2023-01-02T06:46:45.576Z] 06:46:37     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2023-01-02T06:46:45.576Z] 06:46:38     INFO -  raptor-browsertime Info: Navigating to about:blank, count: 0
[task 2023-01-02T06:46:45.576Z] 06:46:38     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 14
[task 2023-01-02T06:46:45.576Z] 06:46:44     INFO -  raptor-browsertime Info: Navigating to primary url:https://www.allrecipes.com/
[task 2023-01-02T06:46:45.576Z] 06:46:44     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2023-01-02T06:46:45.576Z] 06:46:45     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2023-01-02T06:46:45.576Z] 06:46:45     INFO -  raptor-browsertime Info: Testing url https://www.allrecipes.com/ iteration 14
[taskcluster:error] Aborting task...

There was an infrastructure change related to HTTP/3, potentially 1-2 days earlier. Please reach out to :jlorenzo if you need more information.

Comment 1

[Greg Mierzwinski [:sparky]]

:aryx, could you trigger a couple backfill runs for a handful of tests on the following two commits? I'm unable to trigger them:
(1) https://treeherder.mozilla.org/jobs?repo=fenix&tier=1%2C2%2C3&searchStr=browsertime&revision=4946c2795c357521e1c03c9368c4dc4526d2c9a6
(2) https://treeherder.mozilla.org/jobs?repo=fenix&tier=1%2C2%2C3&searchStr=browsertime&revision=bdf6432abce70c5c9633390edb2fd7a74392cafd

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

I don't see backfills in the custom actions, and adding the task to these pushes fails. Maybe Johan can add/run the browsertime allrecipes task to the two pushes which don't have it yet?

Comment 3

[Greg Mierzwinski [:sparky]]

Ok, :jlorenzo, would you be able to add new tasks for browsertime to the two pushes below? :aryx, and I are having issues triggering them.
(1) https://treeherder.mozilla.org/jobs?repo=fenix&tier=1%2C2%2C3&searchStr=browsertime&revision=4946c2795c357521e1c03c9368c4dc4526d2c9a6
(2) https://treeherder.mozilla.org/jobs?repo=fenix&tier=1%2C2%2C3&searchStr=browsertime&revision=bdf6432abce70c5c9633390edb2fd7a74392cafd

Comment 4

[Johan Lorenzo [:jlorenzo]]

Attachment: Bug 1808231 - Allow browsertime tasks to be scheduled by an Action task r=jcristau

Comment 5

[Johan Lorenzo [:jlorenzo]]

Hi there! Crap, I'm facing the same scope issue. It'll be fixed by the patch I just attached.

Comment 6

[Phabricator Automation]

Comment on attachment 9310502 [details]
Bug 1808231 - Allow browsertime tasks to be scheduled by an Action task r=jcristau

Revision D165870 was moved to bug 1808334. Setting attachment 9310502 [details] to obsolete.

Comment 7

[Johan Lorenzo [:jlorenzo]]

(In reply to Johan Lorenzo [:jlorenzo] from comment #5)

It'll be fixed by the patch I just attached.

Update: It'll be fixed in bug 1808334

Comment 8

[Greg Mierzwinski [:sparky]]

Excellent, thanks :jlorenzo!

Comment 9

[Johan Lorenzo [:jlorenzo]]

(In reply to Greg Mierzwinski [:sparky] from comment #3)

Ok, :jlorenzo, would you be able to add new tasks for browsertime to the two pushes below? :aryx, and I are having issues triggering them.
(1) https://treeherder.mozilla.org/jobs?repo=fenix&tier=1%2C2%2C3&searchStr=browsertime&revision=4946c2795c357521e1c03c9368c4dc4526d2c9a6
(2) https://treeherder.mozilla.org/jobs?repo=fenix&tier=1%2C2%2C3&searchStr=browsertime&revision=bdf6432abce70c5c9633390edb2fd7a74392cafd

New tasks added! You guys should be able to schedule them next time. Let me know if that's not the case 🙂

Comment 10

[Greg Mierzwinski [:sparky]]

Will do, thanks for the quick fix Johan!

So far based on the backfill, it looks like the failure started on this top commit: https://treeherder.mozilla.org/jobs?repo=fenix&tochange=4946c2795c357521e1c03c9368c4dc4526d2c9a6&fromchange=d07de1e028350bfb2b28cd2ad2e92b735c2ac88c

Which is from bug 1807716.

Comment 11

[Greg Mierzwinski [:sparky]]

:zmckenney, would you know what might be happening here? Here's a logcat log if that helps (it seems to fail on browser startup): https://firefoxci.taskcluster-artifacts.net/DcDeZLjkQSyHjMRBbGPQew/0/public/test_info/logcat-R58R36P8E0D.log

We also start the app a bit differently which involves glean. Here's a list of extra arguments we pass when we start the app:

--firefox.android.activity mozilla.telemetry.glean.debug.GleanDebugActivity 
--firefox.android.intentArgument=-a
--firefox.android.intentArgument android.intent.action.VIEW
--firefox.android.intentArgument=--es
--firefox.android.intentArgument=startNext
--firefox.android.intentArgument=org.mozilla.fenix.IntentReceiverActivity
--firefox.android.intentArgument=--esa
--firefox.android.intentArgument=sourceTags
--firefox.android.intentArgument=automation
--firefox.android.intentArgument=--ez
--firefox.android.intentArgument=performancetest
--firefox.android.intentArgument=true
--firefox.android.intentArgument=-d
--firefox.android.intentArgument about:blank

This was taken from this log: https://firefoxci.taskcluster-artifacts.net/cyDNKHuTSkKhq_6JRhl-nw/0/public/logs/live_backing.log
You can find more tests here: https://treeherder.mozilla.org/jobs?repo=fenix&tochange=4946c2795c357521e1c03c9368c4dc4526d2c9a6&fromchange=d07de1e028350bfb2b28cd2ad2e92b735c2ac88c

Let me know if you need anything else from me.

Comment 12

[Zac McKenney [:zmckenney]]

[:sparky] thanks for adding the startup of the app since this pointed me to where to look. This is failing because of an existing race condition here that checks whether Glean is initialized. Because Glean is initialized asynchronously this was never guaranteed to return true and because of the change in initialization order it now returns false and finishes.

The change to the order of application initialization is still proper since we want to warm up the engine before initializing Glean. I'm not sure how the test harness is setup but waiting for Glean to be initialized will solve this issue. A temporary fix for this might be adding a wait or repeating retry with timeout in GleanDebugActivity. A better fix would probably be in observing whether Glean has been initialized inside GleanDebugActivity before running the tests.

Hope this helps!

Comment 13

[Greg Mierzwinski [:sparky]]

That's very helpful, thanks! Regarding how our test harness is setup, we don't do any explicit waiting for the GleanDebugActivity to be initialized.

I see two ideas for how we can resolve this: (1) increase the wait time after browser initialization (flaky), and (2) resolve the race condition in Fenix.

I'll start on option (1) with an additional 5 second wait and see how it goes.

:zmckenney, would you know if Glean is exposed in JS in a way that would allow us to wait for it to exist? This would be a better solution versus waiting a hard-coded amount of time.

Comment 14

[Greg Mierzwinski [:sparky]]

Try run with an increased settle time for Fenix (5s): https://treeherder.mozilla.org/jobs?repo=try&revision=13bdbb1df23401a170304ce9560c6a57619033a2

Comment 15

[Zac McKenney [:zmckenney]]

:sparky I don't know about the JS visibility of Glean but I think we're going to need to check the java API initialization. I've created bug 1808586 for waiting on the initialization of Glean before proceeding with the tests which I don't think will be too difficult.

Comment 16

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1807716

Comment 17

[Greg Mierzwinski [:sparky]]

Ok that would be great thanks! I should note that the waiting I tried didn't work because we're failing before that code:

[task 2023-01-05T01:06:34.928Z] 00:57:33     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2023-01-05T01:06:34.928Z] 01:00:33     INFO -  raptor-browsertime Info: firefox failed to start, trying 2 more time(s): Failed to start firefox in 180 seconds.
[task 2023-01-05T01:06:34.928Z] 01:00:33     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2023-01-05T01:06:34.928Z] 01:03:33     INFO -  raptor-browsertime Info: firefox failed to start, trying 1 more time(s): Failed to start firefox in 180 seconds.
[task 2023-01-05T01:06:34.928Z] 01:03:33     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2023-01-05T01:06:34.928Z] 01:06:33     INFO -  raptor-browsertime Info: firefox failed to start, trying 0 more time(s): Failed to start firefox in 180 seconds.
[task 2023-01-05T01:06:34.928Z] 01:06:33    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2023-01-05T01:06:34.928Z] 01:06:33     INFO -  raptor-browsertime Info:     at SeleniumRunner.start (/builds/task_167287963545905/fetches/browsertime/node_modules/browsertime/lib/core/seleniumRunner.js:91:13)
[task 2023-01-05T01:06:34.928Z] 01:06:33     INFO -  raptor-browsertime Info:     at async Iteration.run (/builds/task_167287963545905/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:118:7)
[task 2023-01-05T01:06:34.929Z] 01:06:33     INFO -  raptor-browsertime Info:     at async Engine.runByScript (/builds/task_167287963545905/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:274:20)
[task 2023-01-05T01:06:34.929Z] 01:06:33     INFO -  raptor-browsertime Info:     at async run (/builds/task_167287963545905/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:104:22)
[task 2023-01-05T01:06:34.929Z] 01:06:33    ERROR -  raptor-browsertime Error: Browsertime failed to run

Comment 18

[Intermittent Failures Robot]

29 failures in 539 pushes (0.054 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 29

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 29
  • opt: 29

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-04&endday=2023-01-04&tree=all

Comment 19

[Intermittent Failures Robot]

27 failures in 542 pushes (0.05 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 27

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 27
  • opt: 27

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-05&endday=2023-01-05&tree=all

Comment 20

[Greg Mierzwinski [:sparky]]

:zmckenny, do you know when bug 1808586 might get resolved? I'm wondering if I should disable all the Fenix performance tests as they are failing far too often but I'm not sure how long the fix may take.

Comment 21

[Intermittent Failures Robot]

29 failures in 565 pushes (0.051 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 29

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 29
  • opt: 29

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-06&endday=2023-01-06&tree=all

Comment 22

[Intermittent Failures Robot]

85 failures in 2607 pushes (0.033 failures/push) were associated with this bug in the last 7 days.

This is the #7 most frequent failure this week.

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

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

Repository breakdown:

• fenix: 85

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 85
  • opt: 85

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-02&endday=2023-01-08&tree=all

Comment 23

[Zac McKenney [:zmckenney]]

:sparky I don't know but I did talk with the Glean team today and they are aware of it. Sounds like they'll probably triage or look at it this week.

Comment 24

[Intermittent Failures Robot]

27 failures in 645 pushes (0.042 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• fenix: 27

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 27
  • opt: 27

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-10&endday=2023-01-10&tree=all

Comment 25

[Chris Peterson [:cpeterson]]

Tracking for Fenix 111 because Dave Hunt says Glean bug 1808586 is causing a high number of failures (~50%) in Fenix performance tests in CI.

Comment 26

[Intermittent Failures Robot]

25 failures in 664 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 25

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 25
  • opt: 25

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-11&endday=2023-01-11&tree=all

Comment 27

[Intermittent Failures Robot]

27 failures in 648 pushes (0.042 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 27

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 27
  • opt: 27

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-12&endday=2023-01-12&tree=all

Comment 28

[Chris Peterson [:cpeterson]]

Assigning to Zac because he will verify that Jan-Erik's fix for Glean bug 1808586 fixes these test failures.

Comment 29

[Zac McKenney [:zmckenney]]

I will still test this to verify the fix but adding STR below.

Note: Because we only care about the race condition for fixing this failure this STR for local builds is likely not suitable for other bugs due to it allowing a device that is not used for normal perf tests (on an emulator no less).

STR on local emulator

• Create an emulated device such as a Pixel 6 (I used API 30 without Google Play)
• Set ADB to root by running adb root
• Run device
• add raptorEnabled to local.properties in Fenix project
• Install nightly variant of Fenix to device
• Navigate to Gecko project root
• edit <root of Gecko project>/testing/raptor/raptor/power.py
  • In the function get_device_type add an elif for the device you are using with a pass
  • My example was elif device_type == "sdk_gphone_arm64": pass
• Use the failing Amazon test to determine if race condition is resolved by running ./mach raptor --test amazon --app fenix --binary org.mozilla.fenix

I've confirmed that this test fails if Glean is initialized after engine warmup in FenixApplication and succeeds if Glean is initialized first.

Comment 30

[Intermittent Failures Robot]

25 failures in 677 pushes (0.037 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 25

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 25
  • opt: 25

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-13&endday=2023-01-13&tree=all

Comment 31

[Intermittent Failures Robot]

126 failures in 3530 pushes (0.036 failures/push) were associated with this bug in the last 7 days.

This is the #1 most frequent failure this week.

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

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

Repository breakdown:

• fenix: 126

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 126
  • opt: 126

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-09&endday=2023-01-15&tree=all

Comment 32

[Intermittent Failures Robot]

26 failures in 601 pushes (0.043 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 26

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 26
  • opt: 26

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-16&endday=2023-01-16&tree=all

Comment 33

[Intermittent Failures Robot]

31 failures in 820 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• fenix: 31

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 31
  • opt: 31

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-17&endday=2023-01-17&tree=all

Comment 34

[Intermittent Failures Robot]

57 failures in 3717 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

This is the #17 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• fenix: 57

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 57
  • opt: 57

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1808231&startday=2023-01-16&endday=2023-01-22&tree=all

Comment 35

[Greg Mierzwinski [:sparky]]

It looks like the issue is resolved with yesterday's push! https://treeherder.mozilla.org/jobs?repo=fenix&revision=d8cd52189cdb8a784e2e123ce605266ddcede7d7

Thank you for the help everyone!

Comment 36

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:zmckenney, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox110 to wontfix.

For more information, please visit auto_nag documentation.