874405 - [email/IMAP] snippet/partial body fetch breaks on zero-length bodies

Status: RESOLVED FIXED

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

Description

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

Overview: zero-length message bodies will hang the IMAP synchronization process on a per-folder basis.  We will not recover until the IMAP connection drops because of a network error.  The auto-IDLE functionality is going to mean that the connection is unlikely to drop for time-out reasons.

psingapati provided an account credential to duplicate a hung connection; running with structured logging revealed the following exception occurring which breaks us:

Error: Invalid body byte range format
app://email.gaiamobile.org/js/ext/mailapi/imap/probe.js	1299	ImapConnection.prototype._fetch
app://email.gaiamobile.org/js/ext/mailapi/imap/probe.js	1264	ImapConnection.prototype.fetch
app://email.gaiamobile.org/js/ext/mailapi/imap/protocollayer.js	352	BodyFetcher.prototype._fetch
app://email.gaiamobile.org/js/ext/mailapi/imap/protocollayer.js	344	BodyFetcher
app://email.gaiamobile.org/js/ext/mailapi/composite/configurator.js	835	gotBody
app://email.gaiamobile.org/js/ext/mailapi/worker-bootstrap.js	8848	ifs_getMessageBody/<
app://email.gaiamobile.org/js/ext/mailapi/worker-bootstrap.js	6912	onLoaded
app://email.gaiamobile.org/js/ext/mailapi/worker-bootstrap.js	9821	receiveCallbackMessage
app://email.gaiamobile.org/js/ext/mailapi/worker-bootstrap.js	9786	receiveMessage

And the source of the problem seems to be zero-length bodies per the log.  Presumably the falsey value is tricking us, etc.

I think the flaw in our unit test coverage that allowed this to happen is that although test_imap_mime.js has a zero-length body test, it uses getMessageBodyWithReps, not the snippet/4k fetching variant.  I believe we will want test_imap_mime to use both code-paths.  So pass 1 finds us doing the 4k snippet fetch followed by the follow-up body fetch.  Pass 2 finds us doing a full body fetch without the 4k snippet fetch.  Not sure if we should add the messages twice, or what.

The 'safe' structured logging output from my reproduction run can be seen here:
https://clicky.visophyte.org/examples/arbpl-loggest/20130521/

Comment 1

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

Attachment: https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/206

The patch:
- Makes test_imap_mime run two passes for each message.  In the first pass, we download the message in its entirety and run our check logic.  In the second pass, we do a snippet pass across all messages, then for each message we fetch the rest of the body and run our check logic.  (The actual download/check logic remains the same).
- Adds a _recreateFolder method to IMAP that is basically identical to what we do for ActiveSync; we empty out all the state on the FolderStorage and replace it with a new instance but don't change the id.  This was added to be able to reuse the same IMAP folder in test_imap_mime without duplicating the messages or anything like that.  The specific choice of doing this was made because we need _recreateFolder for UID validity roll purposes anyway.  (For the same reason ActiveSync has it, but with sync keys.)
- Makes us treat 0-length body parts as if they were downloaded from when they are created.  This fixes the bug on its own and makes the IMAP tests pass.
- Adds some failsafe safeguard logic to avoid requesting a 0 byte hunk of data.  This also fixes the bug on its own, but is wasteful to the network.  I included it too just in case we have weird boundary conditions that find us in this state in the future.  I decided the wasteful (but unlikely) fetch is better than writing additional special case logic to handle the 0-byte fetch situation.

Comment 2

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

and the gaia pull request (for testing, if desired) is:
https://github.com/mozilla-b2g/gaia/pull/9914

Comment 3

[James Burke [:jrburke]]

Comment on attachment 752528 [details] [review]
https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/206

Just a typo in a comment, but otherwise, looks good.

Comment 4

[Alex Keybl [:akeybl]]

Does this only happen once per zero-length email? If so, we may waive this for v1.0.1 and fix in v1.1.

Comment 5

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

(In reply to Alex Keybl [:akeybl] from comment #4)
> Does this only happen once per zero-length email? If so, we may waive this
> for v1.0.1 and fix in v1.1.

The problem will manifest itself whenever we try and fetch a snippet for the message in question.  This will happen every time the message is displayed.  The only thing that will fix this is when enough new messages arrive that do not have zero-length bodies that the old message gets pushed far enough back that the user never scrolls to it.  Of course, if a new zero-length body arrives, the problem comes back.

It's a big enough problem that if we don't uplift it to tef I think there's no point in doing any support of the v1.0.1 e-mail app at all.

Comment 6

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

landed on gaia-email-libs-and-more/master:
https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/206
https://github.com/mozilla-b2g/gaia-email-libs-and-more/commit/5f6e8ba3a701751c8b2c050c6026ea5a89f9783f

landed on gaia/master:
https://github.com/mozilla-b2g/gaia/pull/9914
https://github.com/mozilla-b2g/gaia/commit/aa8364e96ac8a0eef019a73be5efef6df882c86f

Comment 7

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

(In reply to Andrew Sutherland (:asuth) from comment #5)
> (In reply to Alex Keybl [:akeybl] from comment #4)
> > Does this only happen once per zero-length email? If so, we may waive this
> > for v1.0.1 and fix in v1.1.
> 
> The problem will manifest itself whenever we try and fetch a snippet for the
> message in question.  This will happen every time the message is displayed. 
> The only thing that will fix this is when enough new messages arrive that do
> not have zero-length bodies that the old message gets pushed far enough back
> that the user never scrolls to it.  Of course, if a new zero-length body
> arrives, the problem comes back.
> 
> It's a big enough problem that if we don't uplift it to tef I think there's
> no point in doing any support of the v1.0.1 e-mail app at all.

I realize this was ambiguous due to missing info about the DB.  The situation goes like this:
- Snippet fetch on zero length mail.
- We hang *and do not save the database state since we never reached a completion point* so the next time we see this message, we will repeat the process and hang.
- There is no way to recover from the hang other than re-starting the app.

The only reason the problem would ever appear to be go away would be because fetching new headers happens before we would issue our snippet requests, so it is possible to eventually get enough new (safe) headers that the bad message is not visible and so does not get its snippet fetched.  If the user scrolls down, causing the message to become visible, we will hang again.

Comment 8

[Gareth Aye [:gaye] (back from PTO)]

Uplifted aa8364e96ac8a0eef019a73be5efef6df882c86f to:
v1-train: 36ce6d8e61265618228d3efd15c119cf08a264a8
v1.0.1: b88b21c6593a8921de68d03bb52a44752796616e