1124426 - [email/UI] The cookie cache may permanently screw up if we ever have more than 40 cookies worth of cache.

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::E-Mail, defect)

Description

[Jovan Gerodetti]

When ever I start the e-mail app it looks like this [1]. Some times I have luck and it works but even when it does, then only until the next restart.

I'm using a Geeksphone Peak v2.1 build from the last few days. I already removed my account from the app (using the webIDE I was able to hide some of the UI elements and then I could access the app settings) and added it again. Then the app worked for once until I had to start it again. 

Observations:
this seemed to got started after I started to have a lot of emails in my inbox (currently about 148).
the email at the top saying "studentjob.de...", it is not in my inbox. acutally I couldn't even find it anywhere in my GMail account, I deleted it along time ago.

Okay, I hope this helps to fix this bug :)


[1] http://i.imgur.com/qImqYdw.png


Required Info:
Device: Geeksphone Peak
Git Commit Info: 77c57eb8
Network Connection: is working properly
E-Mail Domain: gmail.com
Account type: the UI does not respond at all, so I can't look it up, but I think it's "IMAP+SMTP"

ADB Logcat:

>debug: [AppUsage] app://verticalhome.gaiamobile.org/manifest.webapp ran for 6
>I/GeckoDump( 9519): LOG: pushCard for type: message_list
>I/Gecko   ( 9519): WLOG: Email knows that it is: online and previously was: online
>I/Gecko   ( 9519): WLOG: deferring getConfig call until ready
>I/Gecko   ( 9519): WLOG: main thread reports DB ready
>I/Gecko   ( 9519): WLOG: issuing getConfig call to main thread
>I/Gecko   ( 9519): WLOG: cronsync: ensureSync called
>I/Gecko   ( 9519): 
>I/Gecko   ( 9519): WLOG: Mail universe/bridge created and notified!
>I/GeckoDump( 9519): LOG: cronsync-main: ensureSync called
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://email.gaiamobile.org/manifest.webapp ran for 4
>E/GeckoConsole( 9553): [JavaScript Warning: "Unknown property 'will-change'.  >Declaration dropped." {file: "resource://gre-resources/full-screen-override.css" >line: 24 column: 13 source: "  will-change: initial !important;"}]
>E/GeckoConsole(  122): [JavaScript Error: "NS_ERROR_NOT_INITIALIZED: Component >returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) >[nsIMessageSender.sendAsyncMessage]" {file: "resource://gre/modules/AlarmService.jsm" line: 190}]
>I/Gecko   ( 9553): ###################################### forms.js loaded
>I/Gecko   ( 9553): ############################### browserElementPanning.js >loaded
>I/Gecko   ( 9553): ######################## BrowserElementChildPreload.js loaded
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] Saved app usage data
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] >app://verticalhome.gaiamobile.org/manifest.webapp ran for 8
>I/GeckoDump( 9553): LOG: pushCard for type: message_list
>I/Gecko   ( 9553): WLOG: Email knows that it is: online and previously was: online
>I/Gecko   ( 9553): WLOG: deferring getConfig call until ready
>I/Gecko   ( 9553): WLOG: main thread reports DB ready
>I/Gecko   ( 9553): WLOG: issuing getConfig call to main thread
>I/Gecko   ( 9553): WLOG: cronsync: ensureSync called
>I/Gecko   ( 9553): 
>I/Gecko   ( 9553): WLOG: Mail universe/bridge created and notified!
>I/GeckoDump( 9553): LOG: cronsync-main: ensureSync called
>I/GeckoDump( 9553): LOG: cronsync-main: success!
>I/GeckoDump( 9553): LOG: cronsync-main: existing alarm is OK
>I/GeckoDump( 9553): LOG: cronsync-main: ensureSync completed
>I/Gecko   ( 9553): WLOG: cronsync: received an syncEnsured via a message handler
>I/Gecko   ( 9553): 
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] Saved app usage data
>I/GeckoDump( 9553): LOG: htmlCache.save: 18289 in 10 segments
>E/GeckoConsole( 9575): [JavaScript Warning: "Unknown property 'will-change'.  >Declaration dropped." {file: "resource://gre-resources/full-screen-override.css" >line: 24 column: 13 source: "  will-change: initial !important;"}]
>I/Gecko   ( 9553): WLOG: [slog] mailslice:mutex-released {"folderId":"2/0"}
>I/GeckoDump( 9553): LOG: message_list complete: 15 items of 19 alleged known >headers. canGrow: false
>I/GeckoDump( 9553): LOG: message_list loadNextChunk growing 3 to 18 items out of >19 alleged known
>I/Gecko   ( 9553): WLOG: [slog] mailslice:mutex-released {"folderId":"2/0"}
>I/GeckoDump( 9553): LOG: message_list complete: 18 items of 19 alleged known >headers. canGrow: false
>I/Gecko   ( 9575): ###################################### forms.js loaded
>I/Gecko   ( 9575): ############################### browserElementPanning.js loaded
>I/Gecko   ( 9575): ######################## BrowserElementChildPreload.js loaded
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://email.gaiamobile.org/manifest.webapp ran for 80
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] Saved app usage data
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://lockscreen.gaiamobile.org/index.html/manifest.webapp ran for 2
>E/GeckoConsole(  122): [JavaScript Error: "TypeError: this.element is null" {file: "app://system.gaiamobile.org/js/app_window.js" line: 230}]
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://email.gaiamobile.org/manifest.webapp ran for 4
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] app://verticalhome.gaiamobile.org/manifest.webapp ran for 4
>I/GeckoDump( 9575): LOG: pushCard for type: message_list
>I/Gecko   ( 9575): WLOG: Email knows that it is: online and previously was: online
>I/Gecko   ( 9575): WLOG: deferring getConfig call until ready
>I/Gecko   ( 9575): WLOG: main thread reports DB ready
>I/Gecko   ( 9575): WLOG: issuing getConfig call to main thread
>I/Gecko   ( 9575): WLOG: cronsync: ensureSync called
>I/Gecko   ( 9575): 
>I/Gecko   ( 9575): WLOG: Mail universe/bridge created and notified!
>I/GeckoDump( 9575): LOG: cronsync-main: ensureSync called
>I/GeckoDump( 9575): LOG: cronsync-main: success!
>I/GeckoDump( 9575): LOG: cronsync-main: existing alarm is OK
>I/GeckoDump( 9575): LOG: cronsync-main: ensureSync completed
>I/Gecko   ( 9575): WLOG: cronsync: received an syncEnsured via a message handler
>I/Gecko   ( 9575): 
>E/GeckoConsole(  122): Content JS LOG at app://system.gaiamobile.org/js/app_usage_metrics.js:120 in debug: [AppUsage] Saved app usage data
>E/GeckoConsole( 9624): [JavaScript Warning: "Unknown property 'will-change'.  >Declaration dropped." {file: "resource://gre-resources/full-screen-override.css" line: 24 column: 13 source: "  will-change: initial !important;"}]
>I/GeckoDump( 9575): LOG: htmlCache.save: 18289 in 10 segments
>I/Gecko   ( 9575): WLOG: [slog] mailslice:mutex-released {"folderId":"2/0"}
>I/GeckoDump( 9575): LOG: message_list complete: 15 items of 19 alleged known headers. canGrow: false
>I/GeckoDump( 9575): LOG: message_list loadNextChunk growing 3 to 18 items out of 19 alleged known
>I/Gecko   ( 9575): WLOG: [slog] mailslice:mutex-released {"folderId":"2/0"}
>I/GeckoDump( 9575): LOG: message_list complete: 18 items of 19 alleged known headers. canGrow: false
>I/Gecko   ( 9624): ###################################### forms.js loaded
>I/Gecko   ( 9624): ############################### browserElementPanning.js loaded
>I/Gecko   ( 9624): ######################## BrowserElementChildPreload.js loaded

Comment 1

[Andrew Sutherland [:asuth] (he/him)]

I checked the git hashes self-documented by the current peak v2.1 build of http://downloads.geeksphone.com/peak/v2.1/images-peak-v2.1-2015-01-21.Gecko-3d437ed.Gaia-77c57eb.zip and everything looks correct there.

Based on the weird message having been deleted in the past, I'd strongly suspect the cookie cache being messed up.

The only thing that makes sense is once we exceeded our cookie cache maxSegment limit.  We seem to have a bug on that where if we write more than 40 cookies, we will delete 0 through 39, but we'll still leave indices 40+ around.  html_cache_restore.js doesn't range-check the cookie number/index.  So then those "high cookies" will still get joined at the end.

It's possible there's some other explanation, but I think I'm reading the code right.  Assuming I am, I think maybe we want to:
- have save()'s main for loop also have a check on index/maxSegment.
- have restore() sanity check the cookie number and ignore and clear values that are >= maxsegments.

Comment 2

[James Burke [:jrburke]]

Attachment: GitHub pull request

:asuth's identification of a cache problem would explain the symptoms here. While it is hard to imagine how we got junk in the cache above the limit, it could have very well been a temporary bug at some point in the nightlies where we wrote out too much and the DOM was not properly trimmed.

The changes in this pull request should have been there anyway, to make sure we stay within our expected limits.

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

Comment on attachment 8553402 [details] [review]
GitHub pull request

r=asuth, noting that the hypothetical nefarious cookie from this scenario will no longer cause damage, but will still continue to exist.  This makes sense for code sanity purposes, but it would be nice to be able to have some way to address this situation, even if it's just a secret debug menu option called "nuke all cookies" or "nom nom nom".  (It does make sense to keep such a secret debug thing separated since it'd be hard to ever make a case for uplift of those things.)

Comment 4

[James Burke [:jrburke]]

Merged in master:
https://github.com/mozilla-b2g/gaia/commit/f508ed93c237f185c2cb8402f6737f2ce5cc5287

from pull request:
https://github.com/mozilla-b2g/gaia/pull/27608

I am not sure how the original reporter can test this fix. I can generate a zip file for a copy of the email app with this change, but because the issue is with the state in a currently configured account, the zip file will not show the problem.

I am going to ask for uplift for 2.2 and 2.1 for this change. For 2.1, a custom patch will be needed. This is bad enough that if the user gets stuck, it will be very hard to get unstuck depending on how bad the cookie cache is corrupted.

On the plus side, I expect this issue shows up primarily for nightly users where they may have gotten a build where email did something bad temporarily with the cache.

Comment 5

[Jovan Gerodetti]

Hello, as I said, I'm using the Geeksphone 2.1 builds. So when this gets uplifted to 2.1 I'll get the fix? 
How can I get unstuck? Would it help if I remove my email account form the app and re add it?

Comment 6

[James Burke [:jrburke]]

Comment on attachment 8553402 [details] [review]
GitHub pull request

For 2.2:

[Approval Request Comment]

[Bug caused by] (feature/regressing bug #):
Long standing edge case with the HTML cookie cache not enforcing a boundary.

[User impact] if declined:
Some early testers could get in a bad state where the startup HTML is corrupted. Depending on how bad the corruption is, could be inoperable UI.

It is more unlikely that users of final releases will hit this problem, but since it can affect dogfooders and lead to duplicate bugs or causing other bugs to be filed, best to fix.

[Testing completed]:
Tested on flame device. Seeded bad extra data to reproduce and verified fix avoided the corruption.

[Risk to taking this patch] (and alternatives if risky):
Very low risk. Just strongly enforces a boundary that was specified but not strictly enforced before.

[String changes made]:
none

Will also be asking for 2.1, but that will need a special patch, uplift is not seamless, so that will be a different attachment.

Comment 7

[James Burke [:jrburke]]

Attachment: v2.1 Gaia pull request

The 2.1 version of this patch. Equivalent to the master patch so carrying r+ forward, just some line numbers and formatting made it hard to cherry-pick.

Tested the same way on a 2.1 flashed flame device, seeding with garbage then confirming the garbage was skipped.

Comment 8

[James Burke [:jrburke]]

Comment on attachment 8553527 [details] [review]
v2.1 Gaia pull request

For 2.1:

[Approval Request Comment]

[Bug caused by] (feature/regressing bug #):
Long standing edge case with the HTML cookie cache not enforcing a boundary.

[User impact] if declined:
Some early testers could get in a bad state where the startup HTML is corrupted. Depending on how bad the corruption is, could be inoperable UI.

It is more unlikely that users of final releases will hit this problem, but since it can affect dogfooders and lead to duplicate bugs or causing other bugs to be filed, best to fix.

[Testing completed]:
Tested on flame device. Seeded bad extra data to reproduce and verified fix avoided the corruption.

[Risk to taking this patch] (and alternatives if risky):
Very low risk. Just strongly enforces a boundary that was specified but not strictly enforced before.

[String changes made]:
none

Comment 9

[James Burke [:jrburke]]

Jovan, I am hopeful we can get this on 2.1 soon. I did a separate patch for it, and if it goes well we can get it in the 2.1 branch in the next day or two. I am unclear how geeksphone builds are made, but the build that comes out after that uplift should do the trick.

The trouble with the issue is that removing the account will probably not fix it. Selfishly for me, if you can wait to get the updated build, it would help us verify the issue is fixed, but I completely understand if you just need to be able to read your mail.

If you are really stuck on this and prefer not to wait, then I can work out a specialized patch for your case that you can apply manually. Note that the issue could come back until 2.1 gets the update.

Comment 11

[bhavana bajaj [:bajaj]]

Blocking given the dog-fooders report/user impact described and the described risk.

James, if you need help QA do any more testing around this, please add-in testcases. For now, I'll request them to verify this issues once it lands on 2.1/2.2

Comment 12

[James Burke [:jrburke]]

Merged on v2.1:
https://github.com/mozilla-b2g/gaia/commit/0b840c5b94ba08a6169765512f1b2dc8c926b5a9

from pull request:
https://github.com/mozilla-b2g/gaia/pull/27620

Will let the uplifting to 2.2 happen via the automated path, did the merge for 2.1 manually given the separate pull request.

Comment 13

[James Burke [:jrburke]]

As for additional test cases, that will be hard to do. It would likely be caused by an intermittent glitch from a nightly build. I had to manually simulate it by using code to inject garbage. Hopefully the original reporter can also verify once this is on 2.2 and gets into a build for their phone. 

Otherwise, I expect the verification for now would be that it did not horribly break the UI when starting up the email app after being opened previously.

Comment 14

[Jovan Gerodetti]

okay, since this is merged on v2.1 now I think I'll receive the fix with the next or at least second next 2.1 nightly build from Geeksphone. 
Is there anything else I need to do beside installing the new build?

Comment 15

[James Burke [:jrburke]]

Jovan: installing a build that includes the fix should be enough. You can then open and close the email app a couple of times to see if the UI is correctly shown. Thanks for reporting the issue!

Comment 16

[Ryan VanderMeulen [:RyanVM]]

v2.2: https://github.com/mozilla-b2g/gaia/commit/1ed600532d7ddf7a752edbc828694f5913543b55

Comment 17

[ankit93040]

Hi Asuth

I also experienced this issue (V2.0) & even more I also experienced a complete black screen(V2.0) issue (even if you kill the app & reopen) the Email app is shown in complete black screen.

I tried with the your PR https://github.com/mozilla-b2g/gaia/pull/28386/files, and found that issues were fixed.

I found out an STR to reproduce this:

1) Set up Gmail account using IMAP in a phone.
2) Send an email from Gmail(Web) with a VERY VERY long subject. 
3) Send an email from Gmail(Web) with a broken subject like the below. 
「�������J�[�h���L���������i���������I�I」

4) Launch an Email app and receive the emails. Kill the email app while it is retreiving and launch it again. 

A complete black email app is seen (once in 20 times). there is no way to launch the email app unless factory reset is done.

If this can be uplifted to V2.0 as well it would be great.

Thank you

Comment 18

[Andrew Sutherland [:asuth] (he/him)]

Comment on attachment 8553527 [details] [review]
v2.1 Gaia pull request

I am duplicating the contents of :jrburke's comment 8 here, the key extra points are:
- This was reproduced on v2.0, see comment 17.  This explains the cookie cache problem we've observed.  I will also spin off a bug about truncating message subjects in the message list to avoid needlessly bloating the cookie cache, and also as a defensive backend measure (with a much longer limit).
- A pull request I created that cherry-picked the v2.1 fix onto v2.0 addressed the problem, see comment 17.

[Approval Request Comment]

[Bug caused by] (feature/regressing bug #):
Long standing edge case with the HTML cookie cache not enforcing a boundary.

[User impact] if declined:
Some early testers could get in a bad state where the startup HTML is corrupted. Depending on how bad the corruption is, could be inoperable UI.

It is more unlikely that users of final releases will hit this problem, but since it can affect dogfooders and lead to duplicate bugs or causing other bugs to be filed, best to fix.

[Testing completed]:
Tested on flame device. Seeded bad extra data to reproduce and verified fix avoided the corruption.

[Risk to taking this patch] (and alternatives if risky):
Very low risk. Just strongly enforces a boundary that was specified but not strictly enforced before.

[String changes made]:
none

Comment 19

[bhavana bajaj [:bajaj]]

Comment on attachment 8553527 [details] [review]
v2.1 Gaia pull request

Requesting verification on 2.0 branch once this lands. Approving given the super low risk and dogfooder comments here.

Comment 20

[Ryan VanderMeulen [:RyanVM]]

v2.0: https://github.com/mozilla-b2g/gaia/commit/4de843d5809a61a72afe63001c5983e2bdfe373c

Comment 21

[Pi Wei Cheng [:piwei] (inactive)]

QA trying to verify this issue. Is there an STR for this bug? Or will comment 17 suffice for STR?

Comment 22

[Andrew Sutherland [:asuth] (he/him)]

We no longer use the cookie cache, we use a localStorage cache, so this bug and its fix are both moot from the perspective of v2.2 and later, I believe.

Comment 23

[Pi Wei Cheng [:piwei] (inactive)]

We will need to verify this issue as long as verifyme tag is on there. You can take out the tag, or we can exclude this bug in our queries.

Comment 24

[Andrew Sutherland [:asuth] (he/him)]

Ah, right.  Removed!