Open Bug 1895283 Opened 5 months ago Updated 3 months ago

Navigation request from privileged code as triggered right after using `window.location = url` doesn't load the requested page

Categories

(Core :: DOM: Navigation, defect)

Product:
Core
Component:
DOM: Navigation
Type:
defect

Tracking

()

People

(Reporter: whimboo, Unassigned, NeedInfo)

References

Details

Attachments

(1 file)

Log with DocLoader:5 and BCWebProgress:5 enabled
479.46 KB, text/plain
Details

Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:127.0) Gecko/20100101 Firefox/127.0 ID:20240428214249

This bug can easily be reproduced when using Marionette to trigger a navigation. Its WebDriver:NavigateTo command uses browsingContext.fixupAndLoadURIString(url, opts) to start a new navigation to url. Here the test and how to execute it:

# coding=UTF-8

from marionette_harness import MarionetteTestCase


class TestMinimizedTestCase(MarionetteTestCase):

    def test_privileged_navigation_after_content_not_started(self):
        page_actions_scroll = self.marionette.absolute_url(
            "actions_scroll.html")
        page_slow_resource = self.marionette.absolute_url(
            "slow_resource.html")

        # Initiate a navigation as triggered from content scope
        self.marionette.execute_script(
            """window.location = arguments[0];""", script_args=(page_actions_scroll,))

        # Run another navigation immediately afterward from privileged code.
        # In most of the cases the navigation doesn't start at all in Firefox.
        self.marionette.navigate(page_slow_resource)
        self.assertEqual(self.marionette.get_url(), page_slow_resource)

It can easily be run with mach marionette-test -vv --gecko-log - --setpref="remote.log.truncate=true" _a/test_minimized.py --run-until-failure. This repeats the test until it fails. Usually it should start failing with the 2nd iteration.

Navigations in Marionette work usually fine but if another navigation is started right before from executing a script in the content scope of the web page, the content triggered navigation continues until the page is loaded. But the URL from the privileged code triggered navigation (slow_resource.html) is never loaded.

Adding a sleep between both navigation requests make it work, so I assume that this is most likely a race condition with the synchronization between the parent and the content process.

When checking the log it looks like that the docloader continue loading the formerly triggered URL and completely forgets about the slow_resource.html page:

1715009524229	Marionette	DEBUG	3 -> [0,5,"WebDriver:Navigate",{"url":"http://127.0.0.1:52547/slow_resource.html"}]
1715009524230	RemoteAgent	TRACE	[10] ProgressListener Start: expectNavigation=false resolveWhenStarted=true unloadTimeout=200 waitForExplicitStart=true
1715009524230	RemoteAgent	TRACE	[10] ProgressListener Document already loading http://127.0.0.1:52547/actions_scroll.html
1715009524230	RemoteAgent	TRACE	[10] ProgressListener Setting unload timer (200ms)
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: Stop() called
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: OnStopRequest[10308a240](documentchannel:http://127.0.0.1:52547/actions_scroll.html) status=804b0002 mIsLoadingDocument=true, mDocumentOpenedButNotLoaded=false, 0 active URLs
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: ++ Firing OnStateChange for end url load (...).	URI: documentchannel:http://127.0.0.1:52547/actions_scroll.html status=804b0002
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: Status (documentchannel:http://127.0.0.1:52547/actions_scroll.html): code: 10010
[Child 80617: Main Thread]: D/DocLoader DocLoader:103198620: Status (documentchannel:http://127.0.0.1:52547/actions_scroll.html): code: 10010
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: Is now idle...
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: ++ Firing OnStateChange for end document load (...).	URI: documentchannel:http://127.0.0.1:52547/actions_scroll.html Status=804b0002
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: Status (documentchannel:http://127.0.0.1:52547/actions_scroll.html): code: 20010
[Child 80617: Main Thread]: D/DocLoader DocLoader:103198620: Status (documentchannel:http://127.0.0.1:52547/actions_scroll.html): code: 20010
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: Status (documentchannel:http://127.0.0.1:52547/actions_scroll.html): code: c0010
[Child 80617: Main Thread]: D/DocLoader DocLoader:103198620: Status (documentchannel:http://127.0.0.1:52547/actions_scroll.html): code: c0010
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: OnStartRequest[10308a350](documentchannel:http://127.0.0.1:52547/slow_resource.html) mIsLoadingDocument=false, 1 active URLs
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: ++ Firing OnStateChange for start document load (...).	URI: documentchannel:http://127.0.0.1:52547/slow_resource.html
[Child 80617: Main Thread]: D/DocLoader DocLoader:109e56c00: Status (documentchannel:http://127.0.0.1:52547/slow_resource.html): code: f0001
[Child 80617: Main Thread]: D/DocLoader DocLoader:103198620: Status (documentchannel:http://127.0.0.1:52547/slow_resource.html): code: f0001
[Parent 80614: Main Thread]: D/DocLoader DocLoader:137a68400: OnStartRequest[137acd600](about:document-onload-blocker) mIsLoadingDocument=false, 1 active URLs
[Parent 80614: Main Thread]: D/DocLoader DocLoader:137a68400: ++ Firing OnStateChange start url load (...).	URI: about:document-onload-blocker
[Parent 80614: Main Thread]: D/DocLoader DocLoader:137a68400: Status (about:document-onload-blocker): code: 10001
[Parent 80614: Main Thread]: D/DocLoader DocLoader:1023c52a0: Status (about:document-onload-blocker): code: 10001
[Child 80619: Main Thread]: D/DocLoader DocLoader:10be77c00: created.
[Child 80619: Main Thread]: D/DocLoader DocLoader:10be77c00: load group 10beb6e20.
1715009524234	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 12
[Child 80619: Main Thread]: D/DocLoader DocLoader [10be77c00] calling 104790c20->OnLocationChange to about:blank 0
[Child 80619: Main Thread]: D/DocLoader DocLoader [10be77c00] calling 1045eab78->OnLocationChange to about:blank 0
[Child 80619: Main Thread]: D/DocLoader DocLoader [10be77c00] calling 10be77da8->OnLocationChange to about:blank 0
[Child 80619: Main Thread]: D/DocLoader DocLoader:10be77c00: Stop() called
[Child 80619: Main Thread]: D/DocLoader DocLoader:10be77c00: OnStartRequest[1047c1c78](http://127.0.0.1:52547/actions_scroll.html) mIsLoadingDocument=false, 1 active URLs

With the --run-until-failure it's actually also possible to catch this problem in the profiler. Here two excepts from the same profile that are showing a working example, and then a failing one:

Olli, can you see something in this recorded profile that could give an indication why it's failing?

Flags: needinfo?(smaug)

So which page should be loaded? The one from window.location = "foo.html" or marionette.navigate("bar.html") ?
You want "bar.html", right?

What does "self.marionette.execute_script()" do? Does it block until the script is executed?

Flags: needinfo?(smaug) → needinfo?(hskupin)

Yes, I would expect that the page via marionette.navigate() gets loaded given that this command is executed afterward. At the point when marionette.navigate() is called the script execution is done. Everything runs sequentially for the Python client of Marionette. You can see that as well when searching for the Remote-Protocol marker in the parent process of gecko profiles like the ones from above.

Flags: needinfo?(hskupin) → needinfo?(smaug)

Olli, is there anything further that I could provide to understand what's going on here?

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: