Intermittent testing/firefox-ui/tests/functional/security/test_https_first.py TestHTTPSFirst.<test-name> | marionette_driver.errors.ScriptTimeoutException: Timed out after 30000 ms
Categories
(Testing :: Firefox UI Tests, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=492854438&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VN205YmdTIihN0kN4mMKAg/runs/0/artifacts/public/logs/live_backing.log
[task 2025-02-02T01:02:40.765Z] 01:02:40 INFO - 1738458160765 Marionette DEBUG 8 -> [0,34,"WebDriver:GetPageSource",{}]
[task 2025-02-02T01:02:40.799Z] 01:02:40 INFO - 1738458160798 RemoteAgent TRACE WebDriverProcessData actor created for PID 1390
[task 2025-02-02T01:02:40.815Z] 01:02:40 INFO - 1738458160815 Marionette TRACE [25] MarionetteCommands actor created for window id 40802189313
[task 2025-02-02T01:02:40.833Z] 01:02:40 INFO - 1738458160833 Marionette DEBUG 8 <- [1,34,null,{"value":"<html><head>\n <title>Example Domain</title>\n\n <meta charset=\"utf-8\">\n <meta http-equiv=\"Content-type\" content=\"text/ ... for permission.</p>\n <p><a href=\"https://www.iana.org/domains/example\">More information...</a></p>\n</div>\n\n\n</body></html>"}]
[task 2025-02-02T01:02:40.837Z] 01:02:40 INFO - 1738458160836 Marionette DEBUG 8 -> [0,35,"Marionette:SetContext",{"value":"content"}]
[task 2025-02-02T01:02:40.838Z] 01:02:40 INFO - 1738458160838 Marionette DEBUG 8 <- [1,35,null,{"value":null}]
[task 2025-02-02T01:02:40.874Z] 01:02:40 INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/security/test_https_first.py TestHTTPSFirst.test_upgrade_with_schemeless_url | marionette_driver.errors.ScriptTimeoutException: Timed out after 30000 ms
[task 2025-02-02T01:02:40.874Z] 01:02:40 INFO - stacktrace:
[task 2025-02-02T01:02:40.874Z] 01:02:40 INFO - RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2025-02-02T01:02:40.874Z] 01:02:40 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:197:5
[task 2025-02-02T01:02:40.875Z] 01:02:40 INFO - ScriptTimeoutError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:722:5
[task 2025-02-02T01:02:40.875Z] 01:02:40 INFO - evaluate.sandbox/timeoutPromise</scriptTimeoutID<@chrome://remote/content/marionette/evaluate.sys.mjs:97:11
[task 2025-02-02T01:02:40.876Z] 01:02:40 INFO - notify@resource://gre/modules/Timer.sys.mjs:49:17
[task 2025-02-02T01:02:40.877Z] 01:02:40 INFO - Traceback (most recent call last):
[task 2025-02-02T01:02:40.877Z] 01:02:40 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2025-02-02T01:02:40.878Z] 01:02:40 INFO - testMethod()
[task 2025-02-02T01:02:40.878Z] 01:02:40 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/security/test_https_first.py", line 39, in test_upgrade_with_schemeless_url
[task 2025-02-02T01:02:40.879Z] 01:02:40 INFO - self.wait_for_page_navigated(
[task 2025-02-02T01:02:40.879Z] 01:02:40 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/security/test_https_first.py", line 81, in wait_for_page_navigated
[task 2025-02-02T01:02:40.880Z] 01:02:40 INFO - Wait(self.marionette, ignored_exceptions=[JavascriptException]).until(
[task 2025-02-02T01:02:40.880Z] 01:02:40 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/wait.py", line 130, in until
[task 2025-02-02T01:02:40.880Z] 01:02:40 INFO - rv = condition(self.marionette)
[task 2025-02-02T01:02:40.880Z] 01:02:40 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/security/test_https_first.py", line 63, in navigated
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - return self.marionette.execute_async_script(
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 1929, in execute_async_script
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - return func(*args, **kwargs)
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 776, in _send_message
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - self._handle_error(err)
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 788, in _handle_error
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - TEST-INFO took 30986ms
[task 2025-02-02T01:02:40.881Z] 01:02:40 INFO - 1738458160842 Marionette DEBUG 8 -> [0,36,"Marionette:GetContext",{}]
[task 2025-02-02T01:02:40.882Z] 01:02:40 INFO - 1738458160843 Marionette DEBUG 8 <- [1,36,null,{"value":"content"}]
[task 2025-02-02T01:02:40.882Z] 01:02:40 INFO - 1738458160846 Marionette DEBUG 8 -> [0,37,"Marionette:SetContext",{"value":"chrome"}]
[task 2025-02-02T01:02:40.882Z] 01:02:40 INFO - 1738458160847 Marionette DEBUG 8 <- [1,37,null,{"value":null}]
[task 2025-02-02T01:02:40.882Z] 01:02:40 INFO - 1738458160856 Marionette DEBUG 8 -> [0,38,"WebDriver:ExecuteScript",{"script":"Services.perms.removeAll();","args":[],"newSandbox":true,"sandbox":"default","line":33,"filename":"tests/testing/firefox-ui/tests/functional/security/test_https_first.py"}]
[task 2025-02-02T01:02:40.888Z] 01:02:40 INFO - 1738458160887 Marionette DEBUG 8 <- [1,38,null,{"value":null}]
[task 2025-02-02T01:02:40.891Z] 01:02:40 INFO - 1738458160890 Marionette DEBUG 8 -> [0,39,"Marionette:SetContext",{"value":"content"}]
[task 2025-02-02T01:02:40.892Z] 01:02:40 INFO - 1738458160891 Marionette DEBUG 8 <- [1,39,null,{"value":null}]
[task 2025-02-02T01:02:40.895Z] 01:02:40 INFO - 1738458160895 Marionette DEBUG 8 -> [0,40,"Marionette:GetContext",{}]
[task 2025-02-02T01:02:40.896Z] 01:02:40 INFO - 1738458160896 Marionette DEBUG 8 <- [1,40,null,{"value":"content"}]
[task 2025-02-02T01:02:40.899Z] 01:02:40 INFO - 1738458160899 Marionette DEBUG 8 -> [0,41,"Marionette:SetContext",{"value":"chrome"}]
[task 2025-02-02T01:02:40.900Z] 01:02:40 INFO - 1738458160900 Marionette DEBUG 8 <- [1,41,null,{"value":null}]
[task 2025-02-02T01:02:40.902Z] 01:02:40 INFO - 1738458160901 Marionette DEBUG 8 -> [0,42,"WebDriver:GetWindowHandles",{}]
[task 2025-02-02T01:02:40.903Z] 01:02:40 INFO - 1738458160903 Marionette DEBUG 8 <- [1,42,null,["0999a6bf-7957-4d3a-82cc-95fc7cf770c0"]]
[task 2025-02-02T01:02:40.905Z] 01:02:40 INFO - 1738458160905 Marionette DEBUG 8 -> [0,43,"Marionette:SetContext",{"value":"content"}]
[task 2025-02-02T01:02:40.905Z] 01:02:40 INFO - 1738458160905 Marionette DEBUG 8 <- [1,43,null,{"value":null}]
[task 2025-02-02T01:02:40.908Z] 01:02:40 INFO - 1738458160908 Marionette DEBUG 8 -> [0,44,"Marionette:GetContext",{}]
[task 2025-02-02T01:02:40.909Z] 01:02:40 INFO - 1738458160908 Marionette DEBUG 8 <- [1,44,null,{"value":"content"}]
[task 2025-02-02T01:02:40.911Z] 01:02:40 INFO - 1738458160911 Marionette DEBUG 8 -> [0,45,"Marionette:SetContext",{"value":"content"}]
[task 2025-02-02T01:02:40.912Z] 01:02:40 INFO - 1738458160911 Marionette DEBUG 8 <- [1,45,null,{"value":null}]
[task 2025-02-02T01:02:40.913Z] 01:02:40 INFO - 1738458160913 Marionette DEBUG 8 -> [0,46,"WebDriver:GetWindowHandles",{}]
[task 2025-02-02T01:02:40.915Z] 01:02:40 INFO - 1738458160915 Marionette DEBUG 8 <- [1,46,null,["2eac694d-c496-402a-99c4-2cbeae82adb9"]]
[task 2025-02-02T01:02:40.918Z] 01:02:40 INFO - 1738458160917 Marionette DEBUG 8 -> [0,47,"Marionette:SetContext",{"value":"content"}]
[task 2025-02-02T01:02:40.918Z] 01:02:40 INFO - 1738458160918 Marionette DEBUG 8 <- [1,47,null,{"value":null}]
[task 2025-02-02T01:02:40.920Z] 01:02:40 INFO - 1738458160920 Marionette DEBUG 8 -> [0,48,"WebDriver:DeleteSession",{}]
[task 2025-02-02T01:02:40.923Z] 01:02:40 INFO - 1738458160922 Marionette TRACE [25] MarionetteCommands actor destroyed for window id 40802189313
[task 2025-02-02T01:02:40.924Z] 01:02:40 INFO - 1738458160923 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2025-02-02T01:02:40.924Z] 01:02:40 INFO - 1738458160923 Marionette TRACE [9] MarionetteCommands actor destroyed for window id 38654705665
[task 2025-02-02T01:02:40.933Z] 01:02:40 INFO - 1738458160932 Marionette DEBUG 8 <- [1,48,null,{"value":null}]
[task 2025-02-02T01:02:40.935Z] 01:02:40 INFO - TEST-START | testing/firefox-ui/tests/functional/security/test_ssl_status_after_restart.py TestSSLStatusAfterRestart.test_ssl_status_after_restart
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•7 months ago
|
||
The hangs here do origin in the async script evaluation call when waiting for the page to be loaded. Hereby we are waiting for the interactive or complete ready state of the document. Both seem to be not happening when loading example.org. But based on the call to get page source the page is loaded.
We could try to run the tests on try with the BCWebProgress:5 environment variable to see what the problem with navigation is here.
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Updated•6 months ago
|
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 27•2 months ago
|
||
There's been a recent spike affecting autoland, central and beta
whimboo, do you know what this could be?
Failure logs:
https://treeherder.mozilla.org/logviewer?job_id=518251049&repo=mozilla-beta&lineNumber=2361
https://treeherder.mozilla.org/logviewer?job_id=518257367&repo=try&lineNumber=2225
|
|
||
Comment 28•2 months ago
•
|
||
This is very strange. I can see that we have the navigation started by entering the URL into the location bar, but then it takes a long time until it gets reported as done or never completes.
The command to reproduce is:
mach test testing/firefox-ui/tests/functional/security/test_https_first.py --gecko-log - -vv --run-until-failure
Here an excerpt from the log output:
1752780520873 Marionette DEBUG 10 -> [0,26,"WebDriver:ElementSendKeys",{"id":"51c15914-fdf0-4fcc-a474-91379b95e307","text":"example.org"}]
1752780520884 Marionette DEBUG 10 <- [1,26,null,{"value":null}]
1752780520891 Marionette DEBUG 10 -> [0,27,"Marionette:SetContext",{"value":"content"}]
1752780520891 Marionette DEBUG 10 <- [1,27,null,{"value":null}]
[Parent 7968: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:0}, {URI:http://example.org/, originalURI:http://example.org/}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:12, url:about:blank}
1752780520893 Marionette DEBUG 10 -> [0,28,"WebDriver:ExecuteAsyncScript",{"script":"const [url, resolve] = arguments;\n\n if (\n [\"interactive\", \"complete\"].includes(document.ready ... t.readyState}\n`);\n //resolve(window.location.href)\n }, { once: true });\n }","args":["https://example.org/"],"newSandbox":true,"sandbox":"default","scriptTimeout":null,"line":71,"filename":"testing/firefox-ui/tests/functional/security/test_https_first.py"}]
1752780520893 RemoteAgent TRACE WebDriverProcessData actor created for PID 7992
1752780520893 Marionette TRACE [18] MarionetteCommands actor created for window id 30064771076
1752780520894 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 19
** 1752780520895 current url: about:blank
[Parent 7968: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:13, url:about:blank}
[Parent 7968: Main Thread]: I/BCWebProgress OnLocationChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, https://example.org/, 0) on {top:1, id:13, url:https://example.org/}
[Parent 7968: Main Thread]: I/BCWebProgress OnSecurityChange({isTopLevel:1, isLoadingDocument:1}, <null>, 8000002) on {top:1, id:13, url:https://example.org/}
[Parent 7968: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Read example.org") on {top:1, id:13, url:https://example.org/}
[Parent 7968: Main Thread]: I/BCWebProgress OnProgressChange(<null>, <null>, 0, 0, 648, 648) on {top:1, id:13, url:https://example.org/}
[Parent 7968: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, STATE_STOP|STATE_IS_DOCUMENT, NS_OK) on {top:1, id:13, url:https://example.org/}
[Parent 7968: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, STATE_STOP|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:13, url:https://example.org/}
console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 434))
1752780541827 Marionette TRACE [18] MarionetteCommands actor destroyed for window id 30064771076
it can be seen that the web progress in the parent process shows a STATE_STOP for the expected target URL, but in the content process we never actually receive a DOMContentLoaded nor load event. Note that this is a HTTPS-First upgrade test.
A recorded Gecko profile can be found here: https://share.firefox.dev/3TIsgbR
Olli, do you have any idea what might be wrong here? It's very suspicious that this behavior started immediately today across all the branches. See comment 27 and the classified failures.
|
|
||
Comment 29•2 months ago
|
||
I can workaround the problem for now when I run all the sub tests each in its own tab. Then this reported hang is not visible. I'll most likely do that tomorrow if we aren't able to figure out soon what's causing this. But I'll file as well a new bug to get this issue investigated and fixed.
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 31•2 months ago
|
||
I added a patch on bug 1977978 to workaround this problem for now. The hang can then still be observed with the two lines in setUp() removed which create the new tab, and switch to it.
|
|
||
Comment 32•2 months ago
|
||
After investigating this issue a bit more I think that I found the underlying reason (but it doesn't yet explain why it started across all branches).
The navigation as triggered via the location bar is started in the top-level browsing context with the id 14. In that context we also run our async script that should detect a DOMContentLoaded event. But then we have a remoteness change and the top-level browsing context changes to id 15. The script that we run is not getting aborted and continues to run and for sure doesn't see the incoming DOMContentLoaded event from the other browsing context / window. It's not clear to me why we keep the former DOMWindow (the script runs in) around.
Here the log excerpt:
[Parent 19605: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:0}, {URI:http://example.org/, originalURI:http://example.org/}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:14, url:about:blank?schemeless-url}
1752826515406 Marionette DEBUG 10 -> [0,27,"Marionette:SetContext",{"value":"content"}]
1752826515406 Marionette DEBUG 10 <- [1,27,null,{"value":null}]
1752826515408 Marionette DEBUG 10 -> [0,28,"WebDriver:ExecuteAsyncScript",{"script":"const [url, resolve] = arguments;\n\n if (\n [\"interactive\", \"complete\"].includes(document.ready ... entLoaded\", () => {\n resolve(window.location.href)\n }, { once: true });\n }","args":["https://example.org/"],"newSandbox":true,"sandbox":"default","scriptTimeout":null,"line":70,"filename":"testing/firefox-ui/tests/functional/security/test_https_first.py"}]
1752826515408 RemoteAgent TRACE WebDriverProcessData actor created for PID 19628
1752826515408 Marionette TRACE [20] MarionetteCommands actor created for window id 27917287429
1752826515408 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 21
[Parent 19605: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:15, url:about:blank}
[Parent 19605: Main Thread]: I/BCWebProgress OnLocationChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, https://example.org/, 0) on {top:1, id:15, url:https://example.org/}
console.error: "Search service failed to init"
[Parent 19605: Main Thread]: I/BCWebProgress OnSecurityChange({isTopLevel:1, isLoadingDocument:1}, <null>, 8000002) on {top:1, id:15, url:https://example.org/}
[Parent 19605: Main Thread]: I/BCWebProgress OnStatusChange(<null>, <null>, NS_OK, "Read example.org") on {top:1, id:15, url:https://example.org/}
[Parent 19605: Main Thread]: I/BCWebProgress OnProgressChange(<null>, <null>, 0, 0, 648, 648) on {top:1, id:15, url:https://example.org/}
[Parent 19605: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, STATE_STOP|STATE_IS_DOCUMENT, NS_OK) on {top:1, id:15, url:https://example.org/}
[Parent 19605: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:https://example.org/, originalURI:http://example.org/}, STATE_STOP|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:15, url:https://example.org/}
console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 434))
1752826545410 Marionette DEBUG 10 <- [1,28,{"error":"script timeout","message":"Timed out after 30000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... scriptTimeoutID<@chrome://remote/content/marionette/evaluate.sys.mjs:97:11\nnotify@resource://gre/modules/Timer.sys.mjs:66:16\n"},null]
The workaround with opening a new tab didn't work out as well as the try build shows. So my suggestion is to make it a sync script and actually do polling for the target URL and the expected readyState. Lets see if that will work and I'll update my patch on bug 1977978.
|
|
||
Comment 33•2 months ago
|
||
As per Treeherder on autoland the last successful tests were run at Thu, Jul 17, 13:10:58 (ignore the retriggered jobs) and the first failures started with the retriggered jobs around Thu, Jul 17, 13:14:21.
|
|
||
Comment 34•2 months ago
|
||
There is something very strange going on in CI at the moment! I've pushed another try build with an extended timeout for Wait.until() so that it not only waits 5s but 30s (similar to the page load timeout that we usually use for navigations). And now the tests are passing, but ONLY with the caveat that those affected sub tests now not only run some milliseconds but 3 minutes!
https://treeherder.mozilla.org/logviewer?job_id=518410543&repo=try&lineNumber=5758-9390
[task 2025-07-18T11:19:08.658+00:00] 11:19:08 INFO - 1752837548657 Marionette DEBUG 5 -> [0,25,"WebDriver:ElementSendKeys",{"id":"8f711272-02e4-4234-aba6-ff7baa0ddfa4","text":"http://example.org/"}]
[task 2025-07-18T11:19:08.683+00:00] 11:19:08 INFO - 1752837548682 Marionette DEBUG 5 <- [1,25,null,{"value":null}]
[task 2025-07-18T11:19:08.683+00:00] 11:19:08 INFO - 1752837548683 Marionette DEBUG 5 -> [0,26,"Marionette:SetContext",{"value":"content"}]
[task 2025-07-18T11:19:08.683+00:00] 11:19:08 INFO - 1752837548683 Marionette DEBUG 5 <- [1,26,null,{"value":null}]
[task 2025-07-18T11:19:08.685+00:00] 11:19:08 INFO - 1752837548684 Marionette DEBUG 5 -> [0,27,"WebDriver:ExecuteScript",{"script":"const [url] = arguments;\n\n if (\n [\"interactive\", \"complete\"].includes(document.readyState) && ... window.location.href == url\n ) {\n return window.location.href;\n }","args":["http://example.org/"],"newSandbox":true,"sandbox":"default","line":61,"filename":"tests/testing/firefox-ui/tests/functional/security/test_https_first.py"}]
[task 2025-07-18T11:19:08.685+00:00] 11:19:08 INFO - 1752837548685 RemoteAgent TRACE WebDriverProcessData actor created for PID 4047
[task 2025-07-18T11:19:08.685+00:00] 11:19:08 INFO - 1752837548685 Marionette TRACE [24] MarionetteCommands actor created for window id 38654705665
[task 2025-07-18T11:19:08.687+00:00] 11:19:08 INFO - 1752837548686 Marionette DEBUG 5 <- [1,27,null,{"value":null}]
[task 2025-07-18T11:19:08.785+00:00] 11:19:08 INFO - 1752837548784 Marionette DEBUG 5 -> [0,28,"WebDriver:ExecuteScript",{"script":"const [url] = arguments;\n\n if (\n [\"interactive\", \"complete\"].includes(document.readyState) && ... window.location.href == url\n ) {\n return window.location.href;\n }","args":["http://example.org/"],"newSandbox":true,"sandbox":"default","line":61,"filename":"tests/testing/firefox-ui/tests/functional/security/test_https_first.py"}]
[..]
[task 2025-07-18T11:22:09.675+00:00] 11:22:09 INFO - 1752837729675 Marionette DEBUG 5 <- [1,1834,null,{"value":null}]
[task 2025-07-18T11:22:09.701+00:00] 11:22:09 INFO - 1752837729700 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 24
[task 2025-07-18T11:22:09.707+00:00] 11:22:09 INFO - 1752837729706 Marionette TRACE [24] MarionetteCommands actor destroyed for window id 38654705665
[task 2025-07-18T11:22:09.708+00:00] 11:22:09 INFO - 1752837729708 Marionette WARN Ignoring event 'pageshow' because document has an invalid readyState of 'uninitialized'.
[task 2025-07-18T11:22:09.776+00:00] 11:22:09 INFO - 1752837729775 Marionette DEBUG 5 -> [0,1835,"WebDriver:ExecuteScript",{"script":"const [url] = arguments;\n\n if (\n [\"interactive\", \"complete\"].includes(document.readyState) && ... window.location.href == url\n ) {\n return window.location.href;\n }","args":["http://example.org/"],"newSandbox":true,"sandbox":"default","line":61,"filename":"tests/testing/firefox-ui/tests/functional/security/test_https_first.py"}]
[task 2025-07-18T11:22:09.801+00:00] 11:22:09 INFO - 1752837729800 RemoteAgent TRACE WebDriverProcessData actor created for PID 4099
[task 2025-07-18T11:22:09.803+00:00] 11:22:09 INFO - 1752837729802 Marionette TRACE [24] MarionetteCommands actor created for window id 40802189313
[task 2025-07-18T11:22:09.815+00:00] 11:22:09 INFO - 1752837729815 Marionette DEBUG 5 <- [1,1835,null,{"value":"http://example.org/"}]
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 36•2 months ago
|
||
Do you know if anything might have changed on your side which could have caused these failures?
|
||
Comment 37•2 months ago
|
||
We discussed this with Henrik in Slack. Nothing I can think of. Especially nothing that would affect all branches (nightly, beta, release) :-/
|
||
Comment 38•2 months ago
|
||
didn't bug 1977978 remove the error- if this was only seen in a single task, this doesn't seem so critical. Also new failures that we see since Friday are on mozilla-beta and mozilla-esr140, so it appears that bug 1977978 (or something else) has solved the problem
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 43•2 months ago
|
||
After looking a bit more at the previous test logic, I think it was just badly written.
We are first typing a URL in the address bar and then we start the following script:
const [url, resolve] = arguments;
if (
["interactive", "complete"].includes(document.readyState) &&
window.location.href == url
) {
resolve(window.location.href);
} else {
window.addEventListener("DOMContentLoaded", () => {
resolve(window.location.href)
}, { once: true });
}
)
The condition to resolve immediately is ["interactive", "complete"].includes(document.readyState) && window.location.href == url.
I think in the cases where the test failed, we were in readyState === "complete", but still on the previous page, meaning navigation had not started.
So if readyState === "complete" but url is still on the previous page (eg badssl), then we are going to add an event listener on a window object which is about to get destroyed and we will never get the event. The fact that we check the URL means we know we might not be with the correct window object yet. In this case, the only thing we can do is poll.
In my opinion, the test's script was racy from the beginning and the fact that it relies on real external websites explains why the failure occurred across all channels. I would consider this fixed by Bug 1977978.
Description
•