Bug 1311041 has been marked as wontfix, but we need a way to safely track content browsers / windows with a fixed handle. Using the outerWindowId wasn't working due to the fact that remoteness changes can happen at any time when navigating through pages.

All this should be possible since Firefox 65 and bug 1496840 landed. So there is an easy way to retrieve the browsing context id.

Note that for chrome windows we would still have to keep using the outerWindowId.

Felipe, when I check your patch on bug 1496840 I see that we return the context id from the docshell if the browser is not remote. So my question is now if the id is really the same whether how many remoteness changes we face?

To be clear, ChromeWindows still needs to be tracked by their
outerWindowID as they don’t have a corresponding BrowsingContext.
This is fine because they live perpetually in chrome space.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #1)

Felipe, when I check your patch on bug 1496840 I see that we return the
context id from the docshell if the browser is not remote. So my question is
now if the id is really the same whether how many remoteness changes we face?

Yeah, that is the ultimate goal of how the BrowsingContexts should work. However, I just tested it now and it seems that this doesn't yet for a remoteness change. I imagine this will be fixed at some point.

The reason this doesn't work right now is because there are two slightly different concepts here. The "remoteness" concept that the front-end has right now is limited to being "remote" or "non-remote", and whenever there's a remoteness change, the updateBrowserRemoteness function takes action and that's what probably breaks this right now.

For Fission it won't be as much as "remote" vs "non-remote", but more likely "changing of host process whenever navigation occurs".

I imagine that this will require a front-end fix to do a more Fission compatible remoteness change, whenever that's available from Gecko. Right now what the code does is to remove the <browser> from the XUL, change the remote attribute and reinsert it, and that's probably what causes the bug.

Maybe a different fix would be to make the BrowsingContext withstand this.. I'll talk to some people to see how feasible that is.

Hope that answers the question of "what's the intended behavior". I realize that it doesn't solve your immediate problem right now because the desired behavior is not implemented yet.. But that's where things stand in the moment

Felipe, thanks for all that information. It's pretty useful, and good to know that this is the way we want to go. Having a really unique id here, would be absolutely helpful. I will observe your newly filed bug 1519989, and once that has been fixed we might have a look into this bug.

:farre, do we still need this?

Mike, given that Felipe is no longer with us, would you mind to have a look at comment 3? How hard would it be to get it implemented? I assume we should better file a new bug in some component? Thanks!

From the current state of things, it looks like the BrowsingContext only gets swapped when switching between process types (remote to non-remote, for example).

When transitioning from domain to domain, and web process to web process, with Fission enabled, it appears as if the BrowsingContext ID does not change. This looks relevant.

So, assuming you don't need to account for the case where you transition from web content to something like about:addons or about:preferences, then you should be fine to use the BrowsingContext ID today.

(In reply to Andreas Tolfsen 「:ato」 from comment #2)

To be clear, ChromeWindows still needs to be tracked by their
outerWindowID as they don’t have a corresponding BrowsingContext.
This is fine because they live perpetually in chrome space.

Actually, anything with a DocShell will have a BrowsingContext and a BrowsingContext ID. So if you open up the Browser Console, you can get the BrowsingContext ID of your current browser window with:

window.docShell.browsingContext.id;

Looks like I got it all done. Interestingly the outerWindowID is also pretty stable those days and don't change between remote navigations.

Here a first try build:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f01de60836ab3eb57302b3285bbfa4821239f02f

I hit a problem with Wdspec tests but only for ASAN builds on Ubuntu 18.04:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=303928241&repo=try&lineNumber=61316-61326

[task 2020-05-27T13:02:41.641Z] 13:02:41     INFO - PID 17503 | 1590584561635	webdriver::server	DEBUG	<- 200 OK {"value":["5","22"]}
[task 2020-05-27T13:02:41.641Z] 13:02:41     INFO - PID 17503 | 1590584561636	webdriver::server	DEBUG	-> DELETE /session/b34f1b58-b894-4d23-a688-2a9fa5c0b130/window
[task 2020-05-27T13:02:41.641Z] 13:02:41     INFO - PID 17503 | 1590584561638	Marionette	DEBUG	0 -> [0,192,"WebDriver:CloseWindow",{}]
[task 2020-05-27T13:02:41.662Z] 13:02:41     INFO - PID 17503 | 1590584561659	Marionette	TRACE	Received DOM event TabClose for [object XULElement]
[task 2020-05-27T13:02:41.685Z] 13:02:41     INFO - PID 17503 | 1590584561683	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2020-05-27T13:02:41.686Z] 13:02:41     INFO - PID 17503 | 1590584561684	Marionette	DEBUG	0 <- [1,192,null,["5"]]
[task 2020-05-27T13:02:41.695Z] 13:02:41     INFO - PID 17503 | 1590584561687	webdriver::server	DEBUG	<- 200 OK {"value":["5"]}
[task 2020-05-27T13:02:41.695Z] 13:02:41     INFO - PID 17503 | 1590584561688	webdriver::server	DEBUG	-> POST /session/b34f1b58-b894-4d23-a688-2a9fa5c0b130/window {"handle": "5"}
[task 2020-05-27T13:02:41.699Z] 13:02:41     INFO - PID 17503 | DEBUG: Starting phase xpcom-will-shutdown
[task 2020-05-27T13:02:41.699Z] 13:02:41     INFO - PID 17503 | 1590584561695	Marionette	DEBUG	0 -> [0,193,"WebDriver:SwitchToWindow",{"handle":"5","name":"5"}]
[task 2020-05-27T13:02:41.703Z] 13:02:41     INFO - PID 17503 | DEBUG: Spinning the event loop
[task 2020-05-27T13:02:41.703Z] 13:02:41     INFO - PID 17503 | 1590584561698	Marionette	DEBUG	0 <- [1,193,null,{"value":null}]
[task 2020-05-27T13:02:41.706Z] 13:02:41     INFO - PID 17503 | DEBUG: Finished phase xpcom-will-shutdown

Somehow when closing the 2nd last tab, and switching back to the primary tab Firefox initiates a shutdown. And this is always happening in one of the new window tests.

I decided to disable the affected tests for asan builds on linux1804 for now (bug 1641273).

The newest try build including some refactorings looks better. Even the formerly failing tests seem to work now, but user_prompts.py is still failing.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=60d66d51d36bf2d2028be43e8e4822c688702cd2&selectedTaskRun=UpAk9LkgR1mN8ftAfK7Vew-0

It's all green now whereby the Wdspec jobs for these ASAN builds take twice that long. I had the same yesterday evening, but this morning was all fine. Maybe it's just overloaded workers? I will keep an eye on it.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=be8778b60d8ddeb4264895510f4c3a6a6cf3aa81

Depends on D77278

Depends on D77279

Depends on D77280

Depends on D77281

The number and order of tests has been changed between the chunks. So it makes it harder to compare. But anyway, here some findings:

• The following numbers are from the very first test as run in the patched case:

/webdriver/tests/accept_alert/accept.py | took 1421ms (not first test)
/webdriver/tests/accept_alert/accept.py | took 11416ms (first test)

These extra 10s are coming from the font cache generation, and will be fixed as part of bug 1633101. So nothing to worry here.

• Tests which do not restart Firefox or have less overhead, like screenshot.py. Interesting is the iframe test, which doesn't restart the browser but also takes 3s longer. A huge difference I can see in the user prompt tests with a couple of restarts. Here the difference is nearly 20s!

/webdriver/tests/take_screenshot/iframe.py | took 7846ms
/webdriver/tests/take_screenshot/screenshot.py | took 468ms
/webdriver/tests/take_screenshot/user_prompts.py | took 54856ms

vs.

/webdriver/tests/take_screenshot/iframe.py | took 10646ms
/webdriver/tests/take_screenshot/screenshot.py | took 721ms
/webdriver/tests/take_screenshot/user_prompts.py | took 73185ms

As such I also checked a subset of tests which restart Firefox a lot. These are the new session tests. So here a comparison with a different base job (because it isn't part of the attached file):

/webdriver/tests/new_session/create_alwaysMatch.py | took 233373ms
/webdriver/tests/new_session/create_firstMatch.py | took 231713ms

vs.

/webdriver/tests/new_session/create_alwaysMatch.py | took 299088ms
/webdriver/tests/new_session/create_firstMatch.py | took 299668ms

Both of the tests take each an extra minute longer.

Counting everything up we have the test job taking around 60 minutes longer!

I'm not sure yet where this comes from, because an earlier try builds from yesterday haven't shown that:

https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=NttVQu6wQZmomOYN-X3kYQ-0&author=hskupin%40mozilla.com

Joel and Edwin, are we aware of any timing issues with ASAN builds on linux18.04? ASAN builds are slow to startup but these differences are drastic.

I also triggered a Mn job now to see if these are also affected.

Mn jobs don't show a difference. Both are ~22 minutes long:

https://treeherder.mozilla.org/logviewer.html#?job_id=304241201&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=304237089&repo=try

And one more thing... for the same try build with jobs run at the same time but different workers I see a huge difference too:

68 minutes:
https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=HvtFE13YQzmI6D3zt_gmmg-0&revision=be8778b60d8ddeb4264895510f4c3a6a6cf3aa81

88 minutes:
https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=BULRzieIQeuoK7n2H-_YIQ-0&revision=be8778b60d8ddeb4264895510f4c3a6a6cf3aa81

I assume that this is something I wouldn't have to take care of on this bug, but we should file a new bug to get this investigated. I will wait for Joel's and Edwin's reply.

wow, 20 minute difference; the c5d instance is 75% runtime of m5a instance.

I am not aware of slow startup issues on asan, it is something we should investigate. I will wait to see what :egao says, maybe he knows more.

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #23)

wow, 20 minute difference; the c5d instance is 75% runtime of m5a instance.

Note that by default these jobs run only 30 minutes! So we have ~30 minutes and ~50 minutes difference!!

I am not familiar with ASAN builds or the startup timings.

Just to be sure, this isn't related to the font cache issue you reported in Bug 1633101 right?

(In reply to Edwin Takahashi (:egao) from comment #25)

Just to be sure, this isn't related to the font cache issue you reported in Bug 1633101 right?

No. See my comment 20. The font cache only affects the very first Firefox process.

So I will file some bug under Testing / General when I'm back next week, so we can further investigate this problem.

For ubuntu1804, there was a longstanding issue on marionette and web-platform-tests-wdspec that prevented its migration from ubuntu1604, which is Bug 1602701. I worked around that by setting NEED_COMPIZ env var to true.

Could that be part of the problem? Essentially, those two suites are running a slightly different environment than all other tests on CI.

EDIT: here's where that is set: https://searchfox.org/mozilla-central/source/taskcluster/taskgraph/transforms/job/mozharness_test.py#125-130

I triggered a couple of try pushes for the individual Phabricator revisions on this bug the the failures indeed appear with the very last revision that introduces the usage of the browsing context id:

outer window id:
https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=dMrJkWOOS5W8fV7qbM3qLw-0&revision=e536761fcbb3c84c1ff67b981aec7358d0285dca

browsing context id:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c3bd8ff59ef547a4886d6d37da7196eb76f3574d

What I don't understand is that even with the patch applied the tests are all running for the expected duration. No job takes longer than the 25 minutes! I'm really getting the impression that the long duration might be related to some specific workers or times during the day.

But as it can be seen there are still failures listed. Checking the one for send_alert_text I see the following log entry:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=304679246&repo=try&lineNumber=86838

INFO - PID 21758 | JavaScript error: chrome://marionette/content/driver.js, line 582: TypeError: can't access property "currentWindowGlobal", BrowsingContext.get(...) is null

That should have actually caused an error and shouldn't have been silently failed as in this case, and triggering a timeout of the test. I will check if I can reproduce it locally, and how to properly handle it. Btw. the code should access the window property anyway I think.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #28)

INFO - PID 21758 | JavaScript error: chrome://marionette/content/driver.js, line 582: TypeError: can't access property "currentWindowGlobal", BrowsingContext.get(...) is null

So this problem always seems to happen when a new tab/window in Firefox gets opened. Our framescript gets automatically loaded, and we send a registration message to the parent process. But in these particular cases the browsing context for the new tab/window is not available yet, and as such BrowsingContext.get() returns undefined:

0:12.99 pid:16226 1591105801604	Marionette	DEBUG	0 -> [0,6,"WebDriver:ExecuteScript",{"args":[],"script":"window.open()"}]
0:13.00 pid:16226 JavaScript error: resource://gre/modules/URIFixup.jsm, line 281: NS_ERROR_FAILURE: Should pass a non-null uri
0:13.06 pid:16226 1591105801663	Marionette	TRACE	[2147483651] Frame script loaded
0:13.10 pid:16226 *** trying to get browsing context for id: 2147483651
0:13.10 pid:16226 *** browsing context: null

Nika or Kris, is there some kind of delay until the newly created browsing context has been made available to the parent process? Or maybe the browser isn't ready yet, and we would have to wait for some additional event like Browser:init?

Sorry, the problem here was actually with a busted rebase which removed all the changes for listener.js from the Phabricator revision. As such the framescript reported the outerWindowID instead of the browsing context id. So it's clear why no browsing context has been found.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #29)

Nika or Kris, is there some kind of delay until the newly created browsing context has been made available to the parent process? Or maybe the browser isn't ready yet, and we would have to wait for some additional event like Browser:init?

There shouldn't be. We do sometimes lazily create browsing contexts without immediately registering them, but by the time you see them from JS, they should be registered. It's possible that the BrowsingContext you're dealing with has been destroyed, though...

That said, you should generally send BrowsingContext objects rather than IDs. We've generally been trying to discourage use of BrowsingContext.get from JS.

Oh good to know. I will try to get rid of the BrowsingContext.get() usage. I haven't known that sending the BrowsingContext object will be fine given that it is not serializable due to cyclic references.

Actually to unblock us, I will do that in a follow-up patch.

Also note that with the latest set of patches all the ASAN builds still have the normal duration. Not sure what was acting up there:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=33423264567ba19aa27468c6eb39cc8f658fce75&searchStr=asan

Backed out 4 changesets (bug 1519335) for causing a spike in bug 1641788, per whimboo's request

Backout link: https://hg.mozilla.org/integration/autoland/rev/6ffead9985f06152d026cf95e3d73853ce698dc5

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=304913428&repo=autoland&lineNumber=1498

[task 2020-06-03T15:03:27.753Z] 15:03:27     INFO - TEST-START | /editing/event.html
[task 2020-06-03T15:03:27.796Z] 15:03:27     INFO - Setting pref dom.input_events.beforeinput.enabled (true)
[task 2020-06-03T15:03:28.163Z] 15:03:28  WARNING - Traceback (most recent call last):
[task 2020-06-03T15:03:28.163Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 642, in run_func
[task 2020-06-03T15:03:28.163Z] 15:03:28  WARNING -     self.result = True, self.func(self.protocol, self.url, self.timeout)
[task 2020-06-03T15:03:28.163Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 753, in do_testharness
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -     self.script_resume % format_map, asynchronous=True)
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 67, in execute_script
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -     return method(script, new_sandbox=False, sandbox=None)
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1661, in execute_async_script
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -     return func(*args, **kwargs)
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\marionette.py", line 602, in _send_message
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -     self._handle_error(err)
[task 2020-06-03T15:03:28.164Z] 15:03:28  WARNING -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\marionette.py", line 622, in _handle_error
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING - JavascriptException: TypeError: window.__wptrunner_process_next_event is not a function
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING - stacktrace:
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING - 	@Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py:72:8
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING - 	@Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py:73:8
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING - 
[task 2020-06-03T15:03:28.165Z] 15:03:28  WARNING - 
[task 2020-06-03T15:03:28.184Z] 15:03:28     INFO - PID 4448 | [Child 4708, Main Thread] WARNING: NS_ENSURE_TRUE(aNextContent && aRange) failed: file /builds/worker/checkouts/gecko/editor/spellchecker/FilteredContentIterator.cpp, line 240
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO - TEST-UNEXPECTED-ERROR | /editing/event.html | TypeError: window.__wptrunner_process_next_event is not a function
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO - Traceback (most recent call last):
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 642, in run_func
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO -     self.result = True, self.func(self.protocol, self.url, self.timeout)
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 753, in do_testharness
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO -     self.script_resume % format_map, asynchronous=True)
[task 2020-06-03T15:03:28.187Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 67, in execute_script
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -     return method(script, new_sandbox=False, sandbox=None)
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1661, in execute_async_script
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -     return func(*args, **kwargs)
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\marionette.py", line 602, in _send_message
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -     self._handle_error(err)
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -   File "Z:\task_1591194385\build\venv\lib\site-packages\marionette_driver\marionette.py", line 622, in _handle_error
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-06-03T15:03:28.188Z] 15:03:28     INFO - JavascriptException: TypeError: window.__wptrunner_process_next_event is not a function
[task 2020-06-03T15:03:28.189Z] 15:03:28     INFO - stacktrace:
[task 2020-06-03T15:03:28.189Z] 15:03:28     INFO - 	@Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py:72:8
[task 2020-06-03T15:03:28.189Z] 15:03:28     INFO - 	@Z:\task_1591194385\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py:73:8
[task 2020-06-03T15:03:28.189Z] 15:03:28     INFO - 
[task 2020-06-03T15:03:28.189Z] 15:03:28     INFO - TEST-INFO took 431ms

Happened frequently on various wpt tests.

https://hg.mozilla.org/mozilla-central/rev/f84fa4157d90
https://hg.mozilla.org/mozilla-central/rev/7c82cbd6f034
https://hg.mozilla.org/mozilla-central/rev/315a7ffd643b
https://hg.mozilla.org/mozilla-central/rev/80a0c09b0211

This got backed out on autoland. I will investigate tomorrow what's wrong with wptrunner.

This change needs a fix for bug 1641788 before it can be re-landed.

https://hg.mozilla.org/mozilla-central/rev/2d06caf869f6
https://hg.mozilla.org/mozilla-central/rev/6b6d3f5a3397
https://hg.mozilla.org/mozilla-central/rev/c1903ff63629
https://hg.mozilla.org/mozilla-central/rev/db55b898e188

== Change summary for alert #26172 (as of Wed, 10 Jun 2020 04:30:23 GMT) ==

Improvements:

0.28% Base Content JS linux1804-64-shippable opt 3,709,674.67 -> 3,699,417.00
0.28% Base Content JS linux1804-64-shippable-qr opt 3,710,203.33 -> 3,699,643.33
0.27% Base Content JS linux1804-64-shippable-qr opt 3,709,879.33 -> 3,699,737.00

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=26172

Florin, the graph shows that this was only temporary:
https://treeherder.mozilla.org/perf.html#/graphs?highlightAlerts=1&series=autoland,2204017,1,4&timerange=1209600&zoom=1591579852842,1591719565772,3697010.8272077506,3707989.0310306284

So not really a persistent improvement or did something else regress it again?

Bug 1646371 - 0.18% Base Content JS (linux1804-64-shippable) regression on push 32d9a307ba08dc723c6065439e6e782b91818e28 (Tue June 9 2020)