1835796 - Perma [tier 2] remote/shared/test/xpcshell/test_Navigate.js | Test timed out

Status: RESOLVED FIXED

(Remote Protocol :: Agent, defect, P1)

Description

[Treeherder Bug Filer]

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

---

[task 2023-05-30T10:38:58.506Z] 10:38:58     INFO -  TEST-START | remote/shared/test/xpcshell/test_Navigate.js
[task 2023-05-30T10:43:58.507Z] 10:43:58  WARNING -  TEST-UNEXPECTED-TIMEOUT | remote/shared/test/xpcshell/test_Navigate.js | Test timed out
[task 2023-05-30T10:43:58.509Z] 10:43:58     INFO -  TEST-INFO took 300000ms
[task 2023-05-30T10:43:58.513Z] 10:43:58     INFO -  >>>>>>>
[task 2023-05-30T10:43:58.513Z] 10:43:58     INFO -  PID 2605 | [CodeCoverage] Setting handlers for process 2605.
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  running event loop
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  remote/shared/test/xpcshell/test_Navigate.js | Starting test_waitForInitialNavigation_initialDocumentNoWindowGlobal
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentNoWindowGlobal pending (2)
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNoWindowGlobal - [test_waitForInitialNavigation_initialDocumentNoWindowGlobal : 156] Document is not loading - true == true
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  } pending (3)
[task 2023-05-30T10:43:58.514Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (3)
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNoWindowGlobal - [test_waitForInitialNavigation_initialDocumentNoWindowGlobal : 161] waitForInitialNavigationCompleted has not resolved yet - true == true
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  } pending (2)
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.515Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNoWindowGlobal - [test_waitForInitialNavigation_initialDocumentNoWindowGlobal : 169] Document is not loading - true == true
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNoWindowGlobal - [test_waitForInitialNavigation_initialDocumentNoWindowGlobal : 170] Is initial document - true == true
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNoWindowGlobal - [test_waitForInitialNavigation_initialDocumentNoWindowGlobal : 174] Expected current URI has been set - "about:blank" == "about:blank"
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNoWindowGlobal - [test_waitForInitialNavigation_initialDocumentNoWindowGlobal : 179] Expected target URI has been set - "about:blank" == "about:blank"
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentNoWindowGlobal finished (2)
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  remote/shared/test/xpcshell/test_Navigate.js | Starting test_waitForInitialNavigation_initialDocumentNotLoaded
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentNotLoaded pending (2)
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNotLoaded - [test_waitForInitialNavigation_initialDocumentNotLoaded : 188] Document is not loading - true == true
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.516Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  } pending (3)
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (3)
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNotLoaded - [test_waitForInitialNavigation_initialDocumentNotLoaded : 194] waitForInitialNavigationCompleted has not resolved yet - true == true
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  } pending (2)
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.517Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNotLoaded - [test_waitForInitialNavigation_initialDocumentNotLoaded : 202] Document is not loading - true == true
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNotLoaded - [test_waitForInitialNavigation_initialDocumentNotLoaded : 203] Is initial document - true == true
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNotLoaded - [test_waitForInitialNavigation_initialDocumentNotLoaded : 207] Expected current URI has been set - "about:blank" == "about:blank"
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentNotLoaded - [test_waitForInitialNavigation_initialDocumentNotLoaded : 212] Expected target URI has been set - "about:blank" == "about:blank"
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentNotLoaded finished (2)
[task 2023-05-30T10:43:58.518Z] 10:43:58     INFO -  remote/shared/test/xpcshell/test_Navigate.js | Starting test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad pending (2)
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -  } pending (3)
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (3)
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.519Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad : 222] Document is loading - true == true
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad : 226] waitForInitialNavigationCompleted has not resolved yet - true == true
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  } pending (2)
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.520Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad : 234] Document is not loading - true == true
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad : 235] Is initial document - true == true
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad : 239] Expected current URI has been set - "about:blank" == "about:blank"
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad : 244] Expected target URI has been set - "about:blank" == "about:blank"
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentLoadingAndNoAdditionalLoad finished (2)
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  remote/shared/test/xpcshell/test_Navigate.js | Starting test_waitForInitialNavigation_initialDocumentFinishedLoadingNoAdditionalLoad
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  (xpcshell/head.js) | test test_waitForInitialNavigation_initialDocumentFinishedLoadingNoAdditionalLoad pending (2)
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.521Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  } pending (3)
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (3)
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  } pending (2)
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  (xpcshell/head.js) | test function () {
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -      [native code]
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  } finished (2)
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentFinishedLoadingNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentFinishedLoadingNoAdditionalLoad : 256] Document is not loading - true == true
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  TEST-PASS | remote/shared/test/xpcshell/test_Navigate.js | test_waitForInitialNavigation_initialDocumentFinishedLoadingNoAdditionalLoad - [test_waitForInitialNavigation_initialDocumentFinishedLoadingNoAdditionalLoad : 260] waitForInitialNavigationCompleted has not resolved yet - true == true
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  <<<<<<<
[task 2023-05-30T10:43:58.522Z] 10:43:58     INFO -  xpcshell return code: None
[task 2023-05-30T10:43:58.523Z] 10:43:58     INFO -  remote/shared/test/xpcshell/test_Navigate.js | Process still running after test!
[task 2023-05-30T10:43:58.523Z] 10:43:58     INFO -  TEST-START | toolkit/crashreporter/test/unit_ipc/test_content_memory_list.js

Comment 1

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

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

:jdescottes, since you are the author of the regressor, bug 1816538, could you take a look?

For more information, please visit BugBot documentation.

Comment 2

[Julian Descottes [:jdescottes]]

Thanks for the ping.

The xpcshell tests for waitForInitialNavigation actually only pass thanks to the "no navigation detected" timeout today (which is an overlook from the initial implementation I believe).

Since on ccov we get a x16 multiplier for the timeout, it means the test takes a really long time. My patch over at https://phabricator.services.mozilla.com/D178817 was rewriting the tests to stop relying on that I will port that here.

Comment 3

[Julian Descottes [:jdescottes]]

Attachment: Bug 1835796 - [remote] Do not rely on navigation timeouts in test_Navigate for waitForInitialNavigation

Comment 4

[Julian Descottes [:jdescottes]]

Fixed by backout: https://hg.mozilla.org/integration/autoland/rev/a68845330c9a36a1f86120058875cc34c29a274c

Comment 5

[Intermittent Failures Robot]

8 failures in 3471 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 8

Platform and build breakdown:

• linux1804-64-ccov-qr: 7
  • opt: 7
• windows11-64-2009-ccov-qr: 1
  • opt: 1

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