Open Bug 1757875 Opened 3 years ago Updated 3 years ago

Intermittent browser/components/newtab/test/browser/browser_aboutwelcome_multistage_languageSwitcher.js | Uncaught exception in test - Should render [data-l10n-id*="onboarding-live-language"] in Live language switching (waiting for languages) - timed o

Categories

(Firefox :: New Tab Page, defect, P5)

defect

Tracking

()

Tracking Status
firefox-esr91 --- unaffected
firefox97 --- unaffected
firefox98 --- unaffected
firefox99 --- wontfix
firefox100 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [stockwell disabled])

Attachments

(2 files, 1 obsolete file)

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


INFO - TEST-START | browser/components/newtab/test/browser/browser_aboutwelcome_multistage_languageSwitcher.js
[task 2022-03-02T22:52:55.570Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeChild:
[task 2022-03-02T22:52:55.570Z] 22:52:55     INFO - GECKO(6588) |   Received page event DOMDocElementInserted
[task 2022-03-02T22:52:55.588Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.600Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:GET_ATTRIBUTION_DATA
[task 2022-03-02T22:52:55.604Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeChild:
[task 2022-03-02T22:52:55.604Z] 22:52:55     INFO - GECKO(6588) |   Loading about:welcome with aboutwelcome-experiment-0.2884548459717762 experiment
[task 2022-03-02T22:52:55.606Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.607Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:NEED_DEFAULT
[task 2022-03-02T22:52:55.607Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.608Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:DOES_APP_NEED_PIN
[task 2022-03-02T22:52:55.609Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.609Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:GET_APP_AND_SYSTEM_LOCALE_INFO
[task 2022-03-02T22:52:55.623Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.632Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:FXA_METRICS_FLOW_URI
[task 2022-03-02T22:52:55.632Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.633Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:TELEMETRY_EVENT
[task 2022-03-02T22:52:55.634Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.635Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:SET_WELCOME_MESSAGE_SEEN
[task 2022-03-02T22:52:55.635Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.636Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:TELEMETRY_EVENT
[task 2022-03-02T22:52:55.637Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.637Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:GET_REGION
[task 2022-03-02T22:52:55.637Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.638Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:GET_SELECTED_THEME
[task 2022-03-02T22:52:55.638Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.639Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:NEGOTIATE_LANGPACK
[task 2022-03-02T22:52:55.639Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.640Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:TELEMETRY_EVENT
[task 2022-03-02T22:52:55.986Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.990Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:TELEMETRY_EVENT
[task 2022-03-02T22:52:55.995Z] 22:52:55     INFO - GECKO(6588) | console.debug: AboutWelcomeParent:
[task 2022-03-02T22:52:55.996Z] 22:52:55     INFO - GECKO(6588) |   Received content event: AWPage:TELEMETRY_EVENT
[task 2022-03-02T22:53:01.258Z] 22:53:01     INFO - TEST-INFO | started process screenshot
[task 2022-03-02T22:53:01.358Z] 22:53:01     INFO - TEST-INFO | screenshot: exit 0
[task 2022-03-02T22:53:01.362Z] 22:53:01     INFO - Buffered messages logged at 22:52:55
INFO - Entering test bound initSandbox
[task 2022-03-02T22:53:01.363Z] 22:53:01     INFO - Leaving test bound initSandbox
[task 2022-03-02T22:53:01.363Z] 22:53:01     INFO - Entering test bound test_aboutwelcome_languageSwitcher_accept
[task 2022-03-02T22:53:01.363Z] 22:53:01     INFO - Mocking LangPackMatcher.jsm APIs
[task 2022-03-02T22:53:01.364Z] 22:53:01     INFO - Opening about:welcome
[task 2022-03-02T22:53:01.364Z] 22:53:01     INFO - Requesting which langpacks are available for download
[task 2022-03-02T22:53:01.365Z] 22:53:01     INFO - Clicking the primary button to start the onboarding process.
[task 2022-03-02T22:53:01.365Z] 22:53:01     INFO - Buffered messages finished
[task 2022-03-02T22:53:01.366Z] 22:53:01     INFO - TEST-UNEXPECTED-FAIL | browser/components/newtab/test/browser/browser_aboutwelcome_multistage_languageSwitcher.js | Uncaught exception in test - Should render [data-l10n-id*="onboarding-live-language"] in Live language switching (waiting for languages) - timed out after 50 tries.
[task 2022-03-02T22:53:01.367Z] 22:53:01     INFO - Leaving test bound test_aboutwelcome_languageSwitcher_accept
[task 2022-03-02T22:53:01.367Z] 22:53:01     INFO - Entering test bound test_aboutwelcome_languageSwitcher_accept
[task 2022-03-02T22:53:01.368Z] 22:53:01     INFO - Mocking LangPackMatcher.jsm APIs
[task 2022-03-02T22:53:01.368Z] 22:53:01     INFO - Opening about:welcome
[task 2022-03-02T22:53:01.368Z] 22:53:01     INFO - GECKO(6588) | console.debug: AboutWelcomeChild:

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

Has Regression Range: --- → yes

:gregtatum, since you are the author of the regressor, bug 1755519, could you take a look?
For more information, please visit auto_nag documentation.

Flags: needinfo?(gtatum)

I'll go ahead and assign it to myself. This code is working similar to the other tests here, and it's failing on a non-deterministic wait. The solution here seems like it would be to either increase the time to wait, or to split this test up. I'm not sure from the log if it's an actual failure. I will keep an eye on its frequency.

Assignee: nobody → gtatum
Flags: needinfo?(gtatum)

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

Update:
There has been a total of 41 failures within the last 7 days, on:

  • 2 failures on Windows 10 x64 2004 WebRender Shippable opt
  • 4 failures on Windows 10 x64 2004 WebRender opt
  • 5 failures on Linux 18.04 x64 WebRender Shippable opt
  • 24 failures on Linux 18.04 x64 WebRender debug/opt
  • 6 failures on Linux 18.04 x64 WebRender asan opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=370430512&repo=autoland&lineNumber=4477

Flags: needinfo?(gtatum)

I instrumented the failing function, and will try to trigger the failure manually:

And increased the timeout here:

My initial evaluation is that this function is not waiting long enough, but there could also be a race condition. If the tests above are inconclusive, I will increase the timeout length, and see what happens.

Flags: needinfo?(gtatum)

I haven't gotten to this yet, but I plan on looking into it more.

There have been 46 failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-03-17&endday=2022-03-24&tree=trunk&bug=1757875

Happens on:
-linux1804-64-asan-qr opt
-linux1804-64-qr opt and debug
-linux1804-64-shippable-qr
-windows10-64-2004-qr opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=372123699&repo=autoland&lineNumber=7275

Whiteboard: [stockwell needswork:owner]

Hi Greg, please re-enable the test in your fix. Thank you!

Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/177f6f692764 disable browser_aboutwelcome_multistage_languageSwitcher.js on Linux_64 for frequent failures. r=intermittent-reviewers,MasterWayZ DONTBUILD
Attachment #9270163 - Attachment description: WIP: Bug 1757875 - Speed up intermittent test and make the timeout longer; r?#platform-i18n-reviewers → Bug 1757875 - Speed up intermittent test and make the timeout longer; r?#platform-i18n-reviewers
Attachment #9272885 - Attachment is obsolete: true
Pushed by gtatum@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/a1e623c4d988 Speed up intermittent test and make the timeout longer; r=platform-i18n-reviewers,dminor
Assignee: gtatum → nobody
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: