1229259 - Tabs get stuck if they're zombified immediately after creation

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Chenxia Liu [:liuche]]

Attachment: Log filtered on "Gecko"

I've been seeing this more frequently in the past week - I'll open up Firefox and tap on a Top Sites tile or type a url, and Firefox will not load the page. The rest of the UI is responsive, but the progress bar gets stuck.

This is a Moto X Gen 1 running 5.1.

Restarting makes this problem go away temporarily.

Comment 1

[:Margaret Leibovic]

Chenxia, can you reliably reproduce this?

Nothing jumps out at me in the log. It sounds like an error is happening somewhere in Gecko land.

Comment 2

[Chenxia Liu [:liuche]]

I don't have repro steps, unfortunately - this seems to just happen when Firefox is alive for too long.

This happens to my phone at least once a day. I wonder if it has to do with memory pressure, since I usually have about about 5-10 tabs open, and some of them are long-ish articles. Anecdotally, I can only say that this started about a week or two ago, and didn't used to happen, but I don't have any specific steps.

I'll add more info if I notice anything else.

Comment 3

[:Margaret Leibovic]

I have no idea how to make progress on this bug, but we won't be able to do anything for 44.

However, if this did start during the 44 cycle, maybe it is indeed a memory issue. Bug 1233220 might be able to help confirm that suspicion.

Comment 4

[:Margaret Leibovic]

Chenxia, do you still see this? Or should we just close this until we have more actionable STR?

Comment 5

[Kevin Brosnan [Ex-Mozilla]]

You mentioned seeing this any STR.

Comment 6

[Justin Wood (:Callek)]

(In reply to Kevin Brosnan [:kbrosnan] from comment #5)
> You mentioned seeing this any STR.

I had seen it for a while, but not anymore (as reported) I do see a VERY similar issue where I get a half-loaded url progress bar but no content. Then I click in the url-bar and click "go" on my phones keyboard and it actually  then loads.

This is most prevelant on ad-heavy pages I click through to from facebook, I have Aurora set to load things in the background (the deferred tabs feature) and usually load like 6 or 7 and then go to Firefox to try and read them. the related symptom of course is *none* of those deferred tabs staying in session store for cases where Aurora crashes, and then I have no way to get back to them (they never actually loaded so not in history either).

Comment 7

[Justin Wood (:Callek)]

(In reply to Justin Wood (:Callek) from comment #6)
> (In reply to Kevin Brosnan [:kbrosnan] from comment #5)
> > You mentioned seeing this any STR.

For added detail, I'm using a Samsung Galaxy S5 from Verizon: 

Android Version: 5.0
Android Security Patch Level: 2015-11-01
Kernel Version: 3.4.0 Tue Nov 17 20:06:51 KST 2015

Comment 8

[Chenxia Liu [:liuche]]

I still see this occasionally, on Nightly, but I still don't have an STR :/

Comment 9

[:Margaret Leibovic]

Kevin, can you make a post to mobile-firefox-dev to raise awareness of this bug and see if we can get any other reports of this happening?

Comment 10

[:Margaret Leibovic]

I've noticed this happen sometimes when loading tabs from tab queues. Some of them will fail to load, and hitting reload won't work. This just happened to me now, and I see these two potentially interesting things in the log:

02-18 06:20:10.703 26598 29426 E GeckoConsole: [JavaScript Error: "TypeError: aTabData is undefined" {file: "jar:jar:file:///data/app/org.mozilla.fennec-1/base.apk!/assets/omni.ja!/components/SessionStore.js" line: 1001}]
02-18 06:27:39.064 26598 29426 E GeckoConsole: [JavaScript Error: "NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIWebNavigation.reload]" {file: "chrome://browser/content/browser.js" line: 1704}]

When I tried to attach a debugger I got these errors:

02-18 06:29:45.068 26598 29426 I GeckoDump: *************************
02-18 06:29:45.068 26598 29426 I GeckoDump: A coding exception was thrown in a Promise resolution callback.
02-18 06:29:45.068 26598 29426 I GeckoDump: See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
02-18 06:29:45.068 26598 29426 I GeckoDump: 
02-18 06:29:45.069 26598 29426 I GeckoDump: Full message: TypeError: sessionStore is undefined
02-18 06:29:45.069 26598 29426 I GeckoDump: Full stack: .get@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:1947:11
02-18 06:29:45.069 26598 29426 I GeckoDump: BTA_form@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:928:7
02-18 06:29:45.069 26598 29426 I GeckoDump: RootActor.prototype.onListTabs/</reply.tabs<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:43
02-18 06:29:45.069 26598 29426 I GeckoDump: RootActor.prototype.onListTabs/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:17
02-18 06:29:45.069 26598 29426 I GeckoDump: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:937:23
02-18 06:29:45.069 26598 29426 I GeckoDump: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7
02-18 06:29:45.069 26598 29426 I GeckoDump: this.PromiseWalker.scheduleWalkerLoop/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:750:11
02-18 06:29:45.069 26598 29426 I GeckoDump: 
02-18 06:29:45.069 26598 29426 I GeckoDump: *************************
02-18 06:29:45.069 26598 29426 E GeckoConsole: [JavaScript Error: "error occurred while processing 'listTabs: TypeError: sessionStore is undefined
02-18 06:29:45.069 26598 29426 E GeckoConsole: Stack: .get@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:1947:11
02-18 06:29:45.069 26598 29426 E GeckoConsole: BTA_form@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:928:7
02-18 06:29:45.069 26598 29426 E GeckoConsole: RootActor.prototype.onListTabs/</reply.tabs<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:43
02-18 06:29:45.069 26598 29426 E GeckoConsole: RootActor.prototype.onListTabs/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:17
02-18 06:29:45.069 26598 29426 E GeckoConsole: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:937:23
02-18 06:29:45.069 26598 29426 E GeckoConsole: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7
02-18 06:29:45.069 26598 29426 E GeckoConsole: this.PromiseWalker.scheduleWalkerLoop/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:750:11
02-18 06:29:45.069 26598 29426 E GeckoConsole: Line: 1947, column: 11" {file: "resource://gre/m
02-18 06:29:45.091 26598 29426 I GeckoDump: *************************
02-18 06:29:45.091 26598 29426 I GeckoDump: A coding exception was thrown in a Promise resolution callback.
02-18 06:29:45.091 26598 29426 I GeckoDump: See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
02-18 06:29:45.091 26598 29426 I GeckoDump: 
02-18 06:29:45.091 26598 29426 I GeckoDump: Full message: TypeError: sessionStore is undefined
02-18 06:29:45.091 26598 29426 I GeckoDump: Full stack: .get@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:1947:11
02-18 06:29:45.091 26598 29426 I GeckoDump: BTA_form@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:928:7
02-18 06:29:45.091 26598 29426 I GeckoDump: RootActor.prototype.onListTabs/</reply.tabs<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:43
02-18 06:29:45.091 26598 29426 I GeckoDump: RootActor.prototype.onListTabs/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:17
02-18 06:29:45.091 26598 29426 I GeckoDump: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:937:23
02-18 06:29:45.091 26598 29426 I GeckoDump: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7
02-18 06:29:45.091 26598 29426 I GeckoDump: this.PromiseWalker.scheduleWalkerLoop/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:750:11
02-18 06:29:45.091 26598 29426 I GeckoDump: 
02-18 06:29:45.091 26598 29426 I GeckoDump: *************************
02-18 06:29:45.092 26598 29426 E GeckoConsole: [JavaScript Error: "error occurred while processing 'listTabs: TypeError: sessionStore is undefined
02-18 06:29:45.092 26598 29426 E GeckoConsole: Stack: .get@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:1947:11
02-18 06:29:45.092 26598 29426 E GeckoConsole: BTA_form@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webbrowser.js:928:7
02-18 06:29:45.092 26598 29426 E GeckoConsole: RootActor.prototype.onListTabs/</reply.tabs<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:43
02-18 06:29:45.092 26598 29426 E GeckoConsole: RootActor.prototype.onListTabs/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/root.js:275:17
02-18 06:29:45.092 26598 29426 E GeckoConsole: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:937:23
02-18 06:29:45.092 26598 29426 E GeckoConsole: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7
02-18 06:29:45.092 26598 29426 E GeckoConsole: this.PromiseWalker.scheduleWalkerLoop/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:750:11
02-18 06:29:45.092 26598 29426 E GeckoConsole: Line: 1947, column: 11" {file: "resource://gre/m


So it seems like something gets busted with session store for these tabs. I can still load pages normally in new tabs, so it's just those tabs that are busted. I don't know a great way to debug this, but maybe we should add debug logging in any suspect areas of the code to see if we can gather more information when this happens again.

Comment 11

[:Margaret Leibovic]

Looking at the first error message about session store data, I think what could be happening is that we're trying to restore a tab before it even has any session store data. Maybe this could happen with tab queues if we're trying to load a bunch of tabs and they somehow get zombified before we've properly stored any session store data for them.

A quick fix could be to add a check to make sure we actually have tab data before trying to restore the tab, and in that case we fall back to just reloading the URL we have.

Comment 12

[Jan Henning [:JanH]]

(In reply to Justin Wood (:Callek) [back on Mar 21] from comment #6)
> I had seen it for a while, but not anymore (as reported) I do see a VERY
> similar issue where I get a half-loaded url progress bar but no content.
> Then I click in the url-bar and click "go" on my phones keyboard and it
> actually  then loads.

I haven't actually confirmed this, but my suspicion is that this might happen if a zombification is triggered while the tab is still loading in background.

Comment 13

[:Margaret Leibovic]

(In reply to Jan Henning [:JanH] from comment #12)
> (In reply to Justin Wood (:Callek) [back on Mar 21] from comment #6)
> > I had seen it for a while, but not anymore (as reported) I do see a VERY
> > similar issue where I get a half-loaded url progress bar but no content.
> > Then I click in the url-bar and click "go" on my phones keyboard and it
> > actually  then loads.
> 
> I haven't actually confirmed this, but my suspicion is that this might
> happen if a zombification is triggered while the tab is still loading in
> background.

Yes, I agree. The issue is that we're trying to load these tabs from session restore, but something has gone wrong with saving them before they were fully loaded.

Comment 14

[:Margaret Leibovic]

JanH, would you be interested in taking over this bug? I haven't had time to investigate more, and it seems related to the other bugs you've been working on recently.

Comment 15

[Jan Henning [:JanH]]

I can't guarantee anything, but I'll try taking a look. Bug 1044556 might improve the situation somewhat once it lands, because it means that the session store won't loose contact with zombified tabs any more.

Comment 16

[Jan Henning [:JanH]]

It seems this bug might have morphed somewhat from liuche's original problem :), but in any case I can sort of reproduce comment 10 by queueing up a number of tabs (preferably pages that are slow to load), switching to Firefox and then, once all the queued tabs have opened and started loading, immediately executing "adb shell am broadcast -a org.mozilla.gecko.FORCE_MEMORY_PRESSURE".
This will also trip up the memory observer if a second zombification is triggered some time later (for debug purposes, if you're watching "adb logcat -s "GeckoMemoryMonitor", you need to wait for memory pressure to decay back to 3 or lower before the FORCE_MEMORY_PRESSURE command has any effect), because this line (https://dxr.mozilla.org/mozilla-central/rev/68c0b7d6f16ce5bb023e08050102b5f2fe4aacd8/mobile/android/chrome/content/MemoryObserver.js#54) will fail for tabs that have already been zombified but don't have any session data. So in that case, instead of zombifiying all background tabs, it will stop once it encounters the first tab without session store data.

I've also seen this line (https://dxr.mozilla.org/mozilla-central/rev/68c0b7d6f16ce5bb023e08050102b5f2fe4aacd8/mobile/android/chrome/content/browser.js#1237) failing in the console, so we've got yet another location that in fact depends on session store data always being available. Given that, I'm inclined to actually give bnicholson's suggestion from bug 852267 comment 14 a try and always initialise new tabs with some basic session store data.

> A quick fix could be to add a check to make sure we actually have tab data
> before trying to restore the tab, and in that case we fall back to just
> reloading the URL we have.

I think that's not quite enough. Let's say Firefox starts up and proceeds opening a number of tabs which have accumulated in the tab queue and then a zombification is triggered. For those tabs for which the session store's OnTabLoad() handler hasn't had a chance to run, no session store data exists. Just fixing the code in OnTabSelect() to cope with such tabs mighty fix the problem of the tabs not un-zombifiying when reloaded, but it means they still won't be included in any session save and will therefore get lost if Firefox is killed.

Comment 17

[Jan Henning [:JanH]]

Attachment: MozReview Request: Bug 1229259 - Always initialise new tabs with basic session store data. r=margaret

When opening a new tab, there is a small window between tab creation and the DOMTitleChanged event firing where the tab - if it is not created as a delay loaded zombie tab right away - won't have any session store data. However a number of functions (tab zombification and restoring of zombified tabs, undo close tabs) depend on the session store data always being available, so things can fall apart if e.g. a zombification is triggered immediately after opening a new tab.
This also means that a tab which is zombfied immediately after its creation (e.g. when a number of tabs are opened through tab queues on startup) is not included in a session save and will therefore get lost if Firefox is killed.

Therefore, we now always intialise new tabs with some basic session store data.

Review commit: https://reviewboard.mozilla.org/r/45095/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/45095/

Comment 18

[:Margaret Leibovic]

Comment on attachment 8739184 [details]
MozReview Request: Bug 1229259 - Always initialise new tabs with basic session store data. r=margaret

https://reviewboard.mozilla.org/r/45095/#review41801

Nice, this fix sounds reasonable to me. Good catch.

Comment 19

[Jan Henning [:JanH]]

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

Comment 20

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/870df3ae9853

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/870df3ae9853

Comment 22

[:Margaret Leibovic]

This bug is tracking 47, can you request uplift to beta?

Comment 23

[Jan Henning [:JanH]]

This seems relatively self-contained, so yes, will do.

Comment 24

[Jan Henning [:JanH]]

Comment on attachment 8739184 [details]
MozReview Request: Bug 1229259 - Always initialise new tabs with basic session store data. r=margaret

Approval Request Comment
[Feature/regressing bug #]: Session store/tab zombification
[User impact if declined]: Tabs opened in background might get stuck under memory pressure.
[Describe test coverage new/current, TreeHerder]: a month on Nightly/Aurora
[Risks and why]: Low, this only ensures that all tabs (as opposed to only delay-loaded ones) are initialised with basic session store data because various functions assume this data is always present.
[String/UUID change made/needed]: none

Comment 25

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8739184 [details]
MozReview Request: Bug 1229259 - Always initialise new tabs with basic session store data. r=margaret

Fixes a regression in session restore, baked in Nightly for a week, Beta47+

Comment 26

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/025d85d86864