gecko-dev/docshell
Emilio Cobos Álvarez 555cddd8c9 Bug 1711690 - Don't bfcache during session restore. r=kashav,peterv
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?

Differential Revision: https://phabricator.services.mozilla.com/D115560
2021-06-01 20:05:24 +00:00
..
base Bug 1711690 - Don't bfcache during session restore. r=kashav,peterv 2021-06-01 20:05:24 +00:00
build Bug 1695817 - Part 2: Introduce a blank page about:third-party r=Gijs,fluent-reviewers,xpcom-reviewers,kmag 2021-05-28 22:35:57 +00:00
resources/content Bug 1710334 - Fix misplacement of about:netError "Try Again" button. r=ckerschb,johannh 2021-05-30 22:48:07 +00:00
shistory Bug 1648825 - Add nsISHEntry::hasUserActivation r=ckerschb,smaug 2021-05-25 17:37:08 +00:00
test Bug 1705872 - Clear history's epoch in the parent when replacing BC. r=smaug 2021-05-29 08:51:47 +00:00
moz.build Bug 1654103: Standardize on Black for Python code in `mozilla-central`. 2020-10-26 18:34:53 +00:00