Here's what's going on (relevant browser is browser 36).
[rr 502130 274898]RestoreDocShellState(browser=36, bc=94, )
[rr 502130 274902]RemoteWebNavigation.currentURI browser=36 bc=94 http://mochi.test:8888/#1
[rr 502130 274906]BrowsingContext::LoadURI(browser=36, bc=94, about:blank)
From a previous restore we correctly wait for:
0 _restoreTabContent( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":5984:30]
<failed to get 'this' value>
1 _sendRestoreTabContent( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":6002:11]
<failed to get 'this' value>
2 restoreTabContent( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4684:9]
<failed to get 'this' value>
3 restoreTab( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4565:13]
<failed to get 'this' value>
4 restoreTabs( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
aSelectTab = "1") ["resource:///modules/sessionstore/SessionStore.jsm":4413:11]
<failed to get 'this' value>
5 ssi_restoreWindow( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4189:11]
<failed to get 'this' value>
6 _restoreWindowsFeaturesAndTabs( <Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4275:11]
<failed to get 'this' value>
7 _restoreWindowsInReversedZOrder( <Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4299:9]
<failed to get 'this' value>
8 ssi_restoreWindows/<( <Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4359:11][rr 502506 275264]BrowsingContext::LoadURI(browser=36, bc=94, about:blank)
[rr 502506 275268]DocumentChannelChild::AsyncOpen(browser=36, bc=94, about:blank)
[rr 502130 275388]RemoteWebNavigation.currentURI browser=36 bc=94 http://mochi.test:8888/#1
[rr 502506 275629]BrowserChild::OnLocationChange(browser=36, bc=94, about:blank)
[rr 502130 276944]updateForLocationChange browser=36 bc=94 - about:blank
[rr 502130 277084]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 277358]RestoreDocShellState(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
[rr 502506 277378]BrowserChild::OnLocationChange(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
[rr 502130 277390]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 277554]BrowserParent::LoadURL(browser=36, bc=94, about:blank)
From:
#18 0x00007ff0bdb1efcc in mozilla::dom::BrowserParent::LoadURL(nsDocShellLoadState*) (this=0x7ff08f2b9800, aLoadState=0x7ff094e1d580) at /home/emilio/src/moz/gecko/dom/ipc/BrowserParent.cpp:861
#19 0x00007ff0bc1117f9 in nsFrameLoader::ReallyStartLoadingInternal() (this=0x7ff08f283400) at /home/emilio/src/moz/gecko/dom/base/nsFrameLoader.cpp:718
#20 0x00007ff0bc11129f in nsFrameLoader::ReallyStartLoading() (this=0x7ff08f283400) at /home/emilio/src/moz/gecko/dom/base/nsFrameLoader.cpp:640
#21 0x00007ff0bc0002f5 in mozilla::dom::Document::MaybeInitializeFinalizeFrameLoaders() (this=0x7ff0a17e2000) at /home/emilio/src/moz/gecko/dom/base/Document.cpp:9008
#22 0x00007ff0bc057891 in mozilla::detail::RunnableMethodArguments<>::applyImpl<mozilla::dom::Document, void (mozilla::dom::Document::*)()>(mozilla::dom::Document*, void (mozilla::dom::Document::*)(), mozilla::Tuple<>&, std::integer_sequence<unsigned long>) (o=<optimized out>, m=<optimized out>, args=<optimized out>) at /home/emilio/src/moz/gecko/obj-debug/dist/include/nsThreadUtils.h:1150
#23 mozilla::detail::RunnableMethodArguments<>::apply<mozilla::dom::Document, void (mozilla::dom::Document::*)()>(mozilla::dom::Document*, void (mozilla::dom::Document::*)()) (this=<optimized out>, o=<optimized out>, m=<optimized out>)
at /home/emilio/src/moz/gecko/obj-debug/dist/include/nsThreadUtils.h:1156
#24 mozilla::detail::RunnableMethodImpl<mozilla::dom::Document*, void (mozilla::dom::Document::*)(), true, (mozilla::RunnableKind)0>::Run() (this=<optimized out>) at /home/emilio/src/moz/gecko/obj-debug/dist/include/nsThreadUtils.h:1203
#25 0x00007ff0bbef8209 in nsContentUtils::RemoveScriptBlocker() () at /home/emilio/src/moz/gecko/dom/base/nsContentUtils.cpp:5696
#26 0x00007ff0bc11c427 in nsAutoScriptBlocker::~nsAutoScriptBlocker() (this=<optimized out>) at /home/emilio/src/moz/gecko/obj-debug/dist/include/nsContentUtils.h:3499
#27 nsFrameLoaderOwner::ChangeRemotenessCommon(nsFrameLoaderOwner::ChangeRemotenessContextType const&, mozilla::dom::RemotenessChangeOptions const&, bool, bool, mozilla::dom::BrowsingContextGroup*, std::function<void ()>&, mozilla::ErrorResult&) (this=<optimized out>, this@entry=0x7ff0a041b608, aContextType=@0x7ffe238847fc: nsFrameLoaderOwner::ChangeRemotenessContextType::PRESERVE, aOptions=
..., aSwitchingInProgressLoad=false, aIsRemote=<optimized out>, aGroup=<optimized out>, aGroup@entry=0x0, aFrameLoaderInit=..., aRv=...) at /home/emilio/src/moz/gecko/dom/base/nsFrameLoaderOwner.cpp:191
#28 0x00007ff0bc11c81f in nsFrameLoaderOwner::ChangeRemoteness(mozilla::dom::RemotenessOptions const&, mozilla::ErrorResult&) (this=0x7ff0a041b608, aOptions=..., rv=...) at /home/emilio/src/moz/gecko/dom/base/nsFrameLoaderOwner.cpp:250
#29 0x00007ff0bcb59003 in mozilla::dom::XULFrameElement_Binding::changeRemoteness(JSContext*, JS::Handle<JSObject*>, void*, JSJitMethodCallArgs const&)Traceback (most recent call last):
File "/home/emilio/src/moz/gecko/js/src/gdb/mozilla/Root.py", line 55, in to_string
ptr = ptr.dereference()
gdb.error: value has been optimized out
(cx_=<optimized out>, obj=
, void_self=<optimized out>, args=...) at XULFrameElementBinding.cpp:513
#30 0x00007ff0bcecc02a in mozilla::dom::binding_detail::GenericMethod<mozilla::dom::binding_detail::NormalThisPolicy, mozilla::dom::binding_detail::ThrowExceptions>(JSContext*, unsigned int, JS::Value*) (cx=0x1,
cx@entry=0x7ff0a871b000, argc=<optimized out>, vp=<optimized out>) at /home/emilio/src/moz/gecko/dom/bindings/BindingUtils.cpp:3297
#31 0x00007ff0bf67b1f1 in CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&)From:
0 updateBrowserRemoteness( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["chrome://browser/content/tabbrowser.js":1937:15]
<failed to get 'this' value>
1 updateBrowserRemotenessByURL( <Failed to get argument while inspecting stack frame>
aURL = ""http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html"") ["chrome://browser/content/tabbrowser.js":2052:20]
<failed to get 'this' value>
2 restoreTabContent( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4662:38]
<failed to get 'this' value>
3 restoreTab( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4565:13]
<failed to get 'this' value>
4 restoreTabs( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
aSelectTab = "2") ["resource:///modules/sessionstore/SessionStore.jsm":4413:11]
<failed to get 'this' value>
5 ssi_restoreWindow( <Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
<Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4189:11]
<failed to get 'this' value>
6 _restoreWindowsFeaturesAndTabs( <Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4275:11]
<failed to get 'this' value>
7 _restoreWindowsInReversedZOrder( <Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4299:9]
<failed to get 'this' value>
8 ssi_restoreWindows/<( <Failed to get argument while inspecting stack frame>
) ["resource:///modules/sessionstore/SessionStore.jsm":4359:11]This load triggers a remoteness change.
[rr 502130 277558]RemoteWebNavigation.currentURI browser=36 bc=94 undefined
[rr 502130 277561]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 277564]RestoreDocShellState(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
[rr 502130 277568]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 277572]BrowsingContext::LoadURI(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
This is the load that should actually end up in the browsing context.
[rr 502578 280053]DocumentChannelChild::AsyncOpen(browser=36, bc=94, about:blank)
From the previous remoteness update.
[rr 502130 280138]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 280141]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 280143]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
[rr 502130 280146]RemoteWebNavigation.currentURI browser=36 bc=94 about:blank
At this point, we try to use the BFCache, and end up replacing the
browsing context:
#0 mozilla::dom::CanonicalBrowsingContext::AllowedInBFCache(mozilla::Maybe<unsigned long> const&) (this=0x7ff08f2b5800, aChannelId=...) at /home/emilio/src/moz/gecko/docshell/base/CanonicalBrowsingContext.cpp:2158
#1 0x00007ff0bb3157c1 in mozilla::net::DocumentLoadListener::MaybeTriggerProcessSwitch(bool*) (this=this@entry=0x7ff093b74090, aWillSwitchToRemote=aWillSwitchToRemote@entry=0x7ffe23887838)
at /home/emilio/src/moz/gecko/netwerk/ipc/DocumentLoadListener.cpp:1723
#2 0x00007ff0bb317feb in mozilla::net::DocumentLoadListener::OnStartRequest(nsIRequest*) (this=0x7ff093b74090, aRequest=0x7ff0a0b7a3c8) at /home/emilio/src/moz/gecko/netwerk/ipc/DocumentLoadListener.cpp:2263
#3 0x00007ff0bb238a0c in mozilla::net::ParentChannelListener::OnStartRequest(nsIRequest*) (this=0x7ff08d5c4ee0, aRequest=0x7ff0a0b7a3c8) at /home/emilio/src/moz/gecko/netwerk/protocol/http/ParentChannelListener.cpp:91
#4 0x00007ff0bb9abec2 in nsDocumentOpenInfo::OnStartRequest(nsIRequest*) (this=<optimized out>, request=0x7ff0a0b7a3c8) at /home/emilio/src/moz/gecko/uriloader/base/nsURILoader.cpp:166
#5 0x00007ff0bb32baf0 in mozilla::net::ParentProcessDocumentOpenInfo::OnDocumentStartRequest(nsIRequest*) (this=0x7ff093bc5b80, request=0x7ff0a0b7a3c8) at /home/emilio/src/moz/gecko/netwerk/ipc/DocumentLoadListener.cpp:292
#6 0x00007ff0bae6446c in nsBaseChannel::OnStartRequest(nsIRequest*) (this=<optimized out>, request=<optimized out>) at /home/emilio/src/moz/gecko/netwerk/base/nsBaseChannel.cpp:833
#7 0x00007ff0bae82bdd in nsInputStreamPump::OnStateStart() (this=this@entry=0x7ff08f2593c0) at /home/emilio/src/moz/gecko/netwerk/base/nsInputStreamPump.cpp:481
#8 0x00007ff0bae828d9 in nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) (this=0x7ff08f2593c0, stream=<optimized out>) at /home/emilio/src/moz/gecko/netwerk/base/nsInputStreamPump.cpp:390
#9 0x00007ff0bae8339b in non-virtual thunk to nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) () at /home/emilio/src/moz/gecko/netwerk/base/nsInputStreamPump.cpp:632
#10 0x00007ff0bacd29d5 in mozilla::NonBlockingAsyncInputStream::RunAsyncWaitCallback(mozilla::NonBlockingAsyncInputStream::AsyncWaitRunnable*, already_AddRefed<nsIInputStreamCallback>)
(this=this@entry=0x7ff094eb5a50, aRunnable=aRunnable@entry=0x7ff08f228560, aCallback=...) at /home/emilio/src/moz/gecko/xpcom/io/NonBlockingAsyncInputStream.cpp:397
#11 0x00007ff0bacdf2ec in mozilla::NonBlockingAsyncInputStream::AsyncWaitRunnable::Run() (this=0x7ff08f228560) at /home/emilio/src/moz/gecko/xpcom/io/NonBlockingAsyncInputStream.cpp:33
#12 0x00007ff0bad48d04 in mozilla::RunnableTask::Run() (this=0x7ff093bc5980) at /home/emilio/src/moz/gecko/xpcom/threads/TaskController.cpp:482
#13 0x00007ff0bad316d4 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) (this=<optimized out>, this@entry=0x7ff0c54f2400, aProofOfLock=...)
at /home/emilio/src/moz/gecko/xpcom/threads/TaskController.cpp:766
#14 0x00007ff0bad3091d in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) (this=this@entry=0x7ff0c54f2400, aProofOfLock=...)
at /home/emilio/src/moz/gecko/xpcom/threads/TaskController.cpp:621
#15 0x00007ff0bad30a83 in mozilla::TaskController::ProcessPendingMTTask(bool) (this=0x7ff0c54f2400, aMayWait=false) at /home/emilio/src/moz/gecko/xpcom/threads/TaskController.cpp:405
#16 0x00007ff0bad4388f in mozilla::TaskController::InitializeInternal()::$_0::operator()() const (this=<optimized out>) at /home/emilio/src/moz/gecko/xpcom/threads/TaskController.cpp:138
#17 mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() (this=<optimized out>) at /home/emilio/src/moz/gecko/obj-debug/dist/include/nsThreadUtils.h:534
#18 0x00007ff0bad3b7f6 in nsThread::ProcessNextEvent(bool, bool*) (this=0x7ff0c541d680, aMayWait=false, aResult=0x7ffe23888437) at /home/emilio/src/moz/gecko/xpcom/threads/nsThread.cpp:1159
#19 0x00007ff0bad3f384 in NS_ProcessNextEvent(nsIThread*, bool) (aThread=0x7ff08f2b5800, aThread@entry=0x7ff0c541d680, aMayWait=false) at /home/emilio/src/moz/gecko/xpcom/threads/nsThreadUtils.cpp:548
#20 0x00007ff0bb43dfe0 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) (this=0x7ff0c54d12c0, aDelegate=0x7ff0c54353e0) at /home/emilio/src/moz/gecko/ipc/glue/MessagePump.cpp:85
#21 0x00007ff0bb3be7b7 in MessageLoop::RunInternal() (this=this@entry=0x7ff0c54353e0) at /home/emilio/src/moz/gecko/ipc/chromium/src/base/message_loop.cc:335
#22 0x00007ff0bb3be707 in MessageLoop::RunHandler() (this=0x7ff0c54353e0) at /home/emilio/src/moz/gecko/ipc/chromium/src/base/message_loop.cc:328
#23 MessageLoop::Run() (this=0x7ff0c54353e0) at /home/emilio/src/moz/gecko/ipc/chromium/src/base/message_loop.cc:310
#24 0x00007ff0bded2bdb in nsBaseAppShell::Run() (this=0x7ff0a880c580) at /home/emilio/src/moz/gecko/widget/nsBaseAppShell.cpp:137
#25 0x00007ff0bf449d85 in nsAppStartup::Run() (this=0x7ff0a883de20) at /home/emilio/src/moz/gecko/toolkit/components/startup/nsAppStartup.cpp:273
#26 0x00007ff0bf5428b6 in XREMain::XRE_mainRun() (this=<optimized out>, this@entry=0x7ffe238887c0) at /home/emilio/src/moz/gecko/toolkit/xre/nsAppRunner.cpp:5239
#27 0x00007ff0bf5433ef in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) (this=this@entry=0x7ffe238887c0, argc=argc@entry=5, argv=argv@entry=0x7ffe23889a68, aConfig=<optimized out>)
at /home/emilio/src/moz/gecko/toolkit/xre/nsAppRunner.cpp:5437
#28 0x00007ff0bf54385e in XRE_main(int, char**, mozilla::BootstrapConfig const&) (argc=-1816706824, argv=0x7ff0c56441a0, aConfig=...) at /home/emilio/src/moz/gecko/toolkit/xre/nsAppRunner.cpp:5496
#29 0x0000562d08f8e415 in do_main(int, char**, char**) (argc=-1816706824, argv=0x7ffe23889a68, envp=<optimized out>) at /home/emilio/src/moz/gecko/browser/app/nsBrowserApp.cpp:224[rr 502130 280199]CanonicalBrowsingContext::ReplacedBy(94 -> 104)
[rr 502130 280344]didChangeRemoteness browser=36, bc=104
[rr 502130 280348]RemoteWebNavigation.currentURI browser=36 bc=104 undefined
[rr 502130 280625]RedirectToRealChannel(36, about:blank)
[rr 502578 280695]BrowserChild::OnLocationChange(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
[rr 502578 280699]BrowsingContext::LoadURI(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
[rr 502578 280703]DocumentChannelChild::AsyncOpen(browser=36, bc=94, http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html)
This is the LoadURI call for the "final" load, however it went to the wrong browsing context, as we just replaced this!
[rr 502130 280803]updateForLocationChange browser=36 bc=104 - http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html
[rr 502130 280807]RemoteWebNavigation.currentURI browser=36 bc=104 http://example.com/browser/browser/base/content/test/tabs/file_new_tab_page.html
[rr 502578 281334]BrowserChild::OnLocationChange(browser=36, bc=104, about:blank)
And this one is from the process switch.
[rr 502130 281461]updateForLocationChange browser=36 bc=104 - about:blank
[rr 502130 281465]RemoteWebNavigation.currentURI browser=36 bc=104 about:blank
[rr 502130 282028]
ⰲ겿{"action":"test_status","time":1621467211822,"thread":null,"pid":null,"source":"mochitest","test":"chrome://mochitests/content/browser/browser/base/content/test/tabs/browser_new_tab_insert_position.js","subtest":"tab pos 0 matched http://mochi.test:8888/#0","status":"PASS","message":"","js_source":"TestRunner.js"}ⰲ겿
[rr 502130 282031]RemoteWebNavigation.currentURI browser=36 bc=104 about:blank
[rr 502130 282033]RemoteWebNavigation.currentURI browser=36 bc=104 about:blank
[rr 502130 282117]
So this is certainly the easy fix, but I think we should generally try
to deal with this better, somehow?