1340502 - Pageshow no longer fires with persisted=true when restoring wikipedia from history (Reader Mode icon in URL-bar is not displayed when close the reader mode view on wikipedia)

Status: RESOLVED FIXED

(Core :: DOM: Navigation, defect, P2)

Description

[Timea Zsoldos [:zstimi/tzsoldos], Desktop QA]

[Affected versions]:
 Fx 54.0a1
    53.0a2
    52.0b7
    

[Affected platforms]:
 Windows 8.1 x64
 Ubuntu 16.04 LTS x64
 Mac OS X 10.12.3

[Steps to reproduce]:
 1. Open Firefox.
 2. Go to "https://en.wikipedia.org/wiki/Main_Page".
 3. Click on "Enter Reader View" icon in the URL-bar.
 4. On left side menu-bar click on "Close Reader View" icon.

[Expected result]:
 The reader mode is closed and in URL-bar the "Enter Reader View" icon is displayed.


[Actual result]:
 The reader mode is closed and in URL-bar the "Enter Reader View" icon is not displayed.

[Regression range]:

Last good: build id=20160907030427
First bad: build id=20160908030434
 
 https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=91c2b9d5c1354ca79e5b174591dbb03b32b15bbf&tochange=938ce16be25f9c551c19ef8938e8717ed3d41ff5

I found this bug: 1299154 - added Set/GetOverrideDPPX to restorefromHistory; r=mstange

[Notes]:

a. Gif with the issue: http://imgur.com/a/oOLVf
b. Could not reproduce it on other sites.

Comment 1

[:Gijs (he/him)]

Is 51 affected or not? comment #0 doesn't say, but then you did set the flags, and you did mark this as a regression, so now it's not clear to me.

(In reply to Timea Zsoldos from comment #0)
> [Regression range]:
> 
> Last good: build id=20160907030427
> First bad: build id=20160908030434
>  
>  https://hg.mozilla.org/mozilla-central/
> pushloghtml?fromchange=91c2b9d5c1354ca79e5b174591dbb03b32b15bbf&tochange=938c
> e16be25f9c551c19ef8938e8717ed3d41ff5
> 
> I found this bug: 1299154 - added Set/GetOverrideDPPX to restorefromHistory;
> r=mstange

There are a lot of other bugs in that range. Did you actually isolate the regression to this change? It looks quite unlikely to have caused this problem...

Comment 2

[Timea Zsoldos [:zstimi/tzsoldos], Desktop QA]

Yes, Fx 51.0.1, build ID: 20170125094131  is affected. I used Mozregression to find the pushlog.

Comment 3

[:Gijs (he/him)]

(In reply to Timea Zsoldos from comment #2)
> Yes, Fx 51.0.1, build ID: 20170125094131  is affected. I used Mozregression
> to find the pushlog.

Yes, but what makes you say "I found this bug: 1299154 - added Set/GetOverrideDPPX to restorefromHistory; r=mstange" ? Did you isolate the inbound pushlog to that revision, or not? If not, why pick that bug out of the pushlog?

Comment 4

[Timea Zsoldos [:zstimi/tzsoldos], Desktop QA]

I bisected the inbound builds using mozregression gui on Windows. The first time mozregression tool pointed to that bug, I thought something was wrong (as they don't seem related) so I run mozregression again and the result was the same.

Comment 5

[:Gijs (he/him)]

(In reply to Timea Zsoldos from comment #4)
> I bisected the inbound builds using mozregression gui on Windows. The first
> time mozregression tool pointed to that bug, I thought something was wrong
> (as they don't seem related) so I run mozregression again and the result was
> the same.

But you must be using an old version of mozregression or something - there are no inbound builds and so the best you can get from mozregression is a range on mozilla-central, which doesn't specify which bug in the merge caused the problem (because it doesn't know, and can't know unless you check inbound builds, which aren't available because September last year is too long ago now).

So bug 1299154 is probably unrelated. :-\

Comment 6

[:Gijs (he/him)]

Every time I run mozregression(In reply to :Gijs from comment #5)
> (In reply to Timea Zsoldos from comment #4)
> > I bisected the inbound builds using mozregression gui on Windows. The first
> > time mozregression tool pointed to that bug, I thought something was wrong
> > (as they don't seem related) so I run mozregression again and the result was
> > the same.
> 
> But you must be using an old version of mozregression or something - there
> are no inbound builds and so the best you can get from mozregression is a
> range on mozilla-central, which doesn't specify which bug in the merge
> caused the problem (because it doesn't know, and can't know unless you check
> inbound builds, which aren't available because September last year is too
> long ago now).
> 
> So bug 1299154 is probably unrelated. :-\

But backing out that change does fix the issue... :-\

Markus, any idea what's going on here? I expect it has to do with the fact that reader mode has a paint listener before it checks whether a page is readerable, and this change added a race or something.

Comment 7

[Markus Stange [:mstange]]

Huh!? This is very confusing. Yes, what you're saying sounds like a possible cause. It may be a bit tricky to debug.

Comment 8

[:Gijs (he/him)]

This is a bug in docshell-land. We used to fire a pageshow event with persisted=true. The stack, when checking mIsDocumentRestoring from nsDocumentViewer::LoadComplete, looked (well, looks, if you back out the regressing patch on current nightly) like this:

#0	0x00000001074d7541 in nsDocumentViewer::LoadComplete(nsresult) at layout/base/nsDocumentViewer.cpp:1005
#1	0x000000010800321d in nsDocShell::EndPageLoad(nsIWebProgress*, nsIChannel*, nsresult) at docshell/base/nsDocShell.cpp:7636
#2	0x0000000108002332 in nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*, unsigned int, nsresult) at docshell/base/nsDocShell.cpp:7430
#3	0x00000001080040e0 in non-virtual thunk to nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*, unsigned int, nsresult) at docshell/base/nsDocShell.cpp:7327
#4	0x0000000105d6bb59 in nsDocLoader::DoFireOnStateChange(nsIWebProgress*, nsIRequest*, int&, nsresult) at uriloader/base/nsDocLoader.cpp:1258
#5	0x0000000105d6b7b2 in nsDocLoader::doStopDocumentLoad(nsIRequest*, nsresult) at uriloader/base/nsDocLoader.cpp:842
#6	0x0000000105d6a95d in nsDocLoader::DocLoaderIsEmpty(bool) at uriloader/base/nsDocLoader.cpp:732
#7	0x0000000105d6b3f8 in nsDocLoader::OnStopRequest(nsIRequest*, nsISupports*, nsresult) at uriloader/base/nsDocLoader.cpp:614
#8	0x0000000105d6b66d in non-virtual thunk to nsDocLoader::OnStopRequest(nsIRequest*, nsISupports*, nsresult) at uriloader/base/nsDocLoader.cpp:470
#9	0x0000000105583613 in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) at netwerk/base/nsLoadGroup.cpp:634
#10	0x0000000108007040 in nsDocShell::FinishRestore() at docshell/base/nsDocShell.cpp:8447
#11	0x00000001080069ef in nsDocShell::RestoreFromHistory() at docshell/base/nsDocShell.cpp:9055
#12	0x0000000108005772 in nsDocShell::RestorePresentationEvent::Run() at docshell/base/nsDocShell.cpp:8353
#13	0x00000001054faa53 in nsThread::ProcessNextEvent(bool, bool*) at xpcom/threads/nsThread.cpp:1264
#14	0x000000010550379e in NS_InvokeByIndex at xpcom/reflect/xptcall/md/unix/xptcinvoke_asm_x86_64_unix.S:115
#15	0x0000000105cc1de9 in CallMethodHelper::Invoke() [inlined] at js/xpconnect/src/XPCWrappedNative.cpp:2010
#16	0x0000000105cc1dc9 in CallMethodHelper::Call() [inlined] at js/xpconnect/src/XPCWrappedNative.cpp:1329
#17	0x0000000105cc17ac in XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) at js/xpconnect/src/XPCWrappedNative.cpp:1296
#18	0x0000000105cc3787 in XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) at js/xpconnect/src/XPCWrappedNativeJSOps.cpp:983
#19	0x0000306864fee254 in 0x306864fee254 ()


and now it looks like this:

#0	0x00000001123aa4d1 in nsDocumentViewer::LoadComplete(nsresult) at /Users/gkruitbosch/dev/firefox-unified/layout/base/nsDocumentViewer.cpp:1005
#1	0x0000000112ed61ed in nsDocShell::EndPageLoad(nsIWebProgress*, nsIChannel*, nsresult) at /Users/gkruitbosch/dev/firefox-unified/docshell/base/nsDocShell.cpp:7636
#2	0x0000000112ed5302 in nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*, unsigned int, nsresult) at /Users/gkruitbosch/dev/firefox-unified/docshell/base/nsDocShell.cpp:7430
#3	0x0000000112ed70b0 in non-virtual thunk to nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*, unsigned int, nsresult) at /Users/gkruitbosch/dev/firefox-unified/docshell/base/nsDocShell.cpp:7327
#4	0x0000000110c3eae9 in nsDocLoader::DoFireOnStateChange(nsIWebProgress*, nsIRequest*, int&, nsresult) at /Users/gkruitbosch/dev/firefox-unified/uriloader/base/nsDocLoader.cpp:1258
#5	0x0000000110c3e742 in nsDocLoader::doStopDocumentLoad(nsIRequest*, nsresult) at /Users/gkruitbosch/dev/firefox-unified/uriloader/base/nsDocLoader.cpp:842
#6	0x0000000110c3d8ed in nsDocLoader::DocLoaderIsEmpty(bool) at /Users/gkruitbosch/dev/firefox-unified/uriloader/base/nsDocLoader.cpp:732
#7	0x0000000110c3e388 in nsDocLoader::OnStopRequest(nsIRequest*, nsISupports*, nsresult) at /Users/gkruitbosch/dev/firefox-unified/uriloader/base/nsDocLoader.cpp:614
#8	0x0000000110c3e5fd in non-virtual thunk to nsDocLoader::OnStopRequest(nsIRequest*, nsISupports*, nsresult) at /Users/gkruitbosch/dev/firefox-unified/uriloader/base/nsDocLoader.cpp:470
#9	0x00000001104565a3 in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) at /Users/gkruitbosch/dev/firefox-unified/netwerk/base/nsLoadGroup.cpp:634
#10	0x000000011110bb39 in nsDocument::DoUnblockOnload() at /Users/gkruitbosch/dev/firefox-unified/dom/base/nsDocument.cpp:8817
#11	0x000000011113ad4d in nsUnblockOnloadEvent::Run() at /Users/gkruitbosch/dev/firefox-unified/dom/base/nsDocument.cpp:8768
#12	0x00000001103cd9e3 in nsThread::ProcessNextEvent(bool, bool*) at /Users/gkruitbosch/dev/firefox-unified/xpcom/threads/nsThread.cpp:1264
#13	0x00000001103cc07f in NS_ProcessPendingEvents(nsIThread*, unsigned int) at /Users/gkruitbosch/dev/firefox-unified/xpcom/threads/nsThreadUtils.cpp:331
#14	0x00000001120f9f21 in nsBaseAppShell::NativeEventCallback() at /Users/gkruitbosch/dev/firefox-unified/widget/nsBaseAppShell.cpp:97
#15	0x0000000112151606 in nsAppShell::ProcessGeckoEvents(void*) at /Users/gkruitbosch/dev/firefox-unified/widget/cocoa/nsAppShell.mm:392


in other words, for some reason calling this:

#9	0x0000000105583613 in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) at netwerk/base/nsLoadGroup.cpp:634

no longer synchronously fires the page show event, instead firing it asynchronously sometime later, at which point the tracker bool for "were we restoring a document" (mIsRestoringDocument) has been set to false again, which means we no longer set the right 'persisted' flag.

This is a web-observable regression. :-(

Comment 9

[:Gijs (he/him)]

(In reply to :Gijs from comment #8)
> in other words, for some reason calling this:
> 
> #9	0x0000000105583613 in
> mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*,
> nsresult) at netwerk/base/nsLoadGroup.cpp:634
> 
> no longer synchronously fires the page show event, instead firing it
> asynchronously sometime later, at which point the tracker bool for "were we
> restoring a document" (mIsRestoringDocument) has been set to false again,
> which means we no longer set the right 'persisted' flag.
> 
> This is a web-observable regression. :-(

Err, to be slightly clearer, this:

#9	0x0000000105583613 in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) at netwerk/base/nsLoadGroup.cpp:634
#10	0x0000000108007040 in nsDocShell::FinishRestore() at docshell/base/nsDocShell.cpp:8447

seems to just get delayed and fire the same / a similar RemoveRequest sometime "later". :-\

Comment 10

[:Gijs (he/him)]

[Tracking Requested - why for this release]:
Requesting tracking not so much for the issue in reader mode this reveals but because this is web-observable.

Comment 11

[Ben Kelly [:bkelly, not reviewing]]

Does this only happen under certain circumstances?  Its surprising we don't have a test that would have caught this.

Comment 12

[:Gijs (he/him)]

(In reply to Ben Kelly [not reviewing due to deadline][:bkelly] from comment #11)
> Does this only happen under certain circumstances?

I don't know the answer to this, but I can reliably reproduce with the STR from comment #0, at least.

> Its surprising we don't
> have a test that would have caught this.

Concur...

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

Hmm, do we even enter bfcache in this case? Since the latter stack says we're just unblocking load event.

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

Is it SetOverrideDPPX call which fails here? That certainly isn't infallible.
(building a debug build to check)

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

Doesn't seem to be that.

Second guess is that calling SetOverrideDPPX ends up calling 
mDocument->EnumerateExternalResources(SetExtResourceOverrideDPPX, &ZoomInfo); and that somehow adds requests to loadgroup, and that means we can't restore from bfcache.

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

But I don't have time right now to debug this more.

Comment 17

[Liz Henry (:lizzard) (relman/hg->git project)]

Seems unlikely to be a priority for 53/54. If anyone takes this to work on it and lands a patch, please request uplift if you think it's reasonable.

Comment 19

[Liz Henry (:lizzard) (relman/hg->git project)]

Marking fix-optional to let this fall off regression triage.

Comment 21

[Andrew Overholt [:overholt]]

Let's see if we can investigate this a bit more in the coming months.

Comment 22

[Adam Stevenson [:adamopenweb]]

I'm unable to reproduce this issue in Firefox 59.0.2 for OSX.

Can someone confirm if this issue still exists please?

Comment 23

[Timea Zsoldos [:zstimi/tzsoldos], Desktop QA]

I verified on Firefox 59.0.2, Windows 8.1 x64, this issue is no longer reproducing.

Comment 24

[:Gijs (he/him)]

I bisected this with mozregression. This was fixed in:

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=728b31173deb9b63a2391b8a00fc4da5f4ab439e&tochange=5fc778386eb1e7ff66714919535580bb5f347efd

so probably fixed in bug 1379762, which looks correct from its comment #0, and apparently also added tests that will stop us from doing this again. \o/