1451137 - MOZ_ASSERT(strlen(fCurrentLine) == 1 && fCurrentLine[0] == '\n', "Expect '\n' as only character in this line") - triggered

Status: RESOLVED FIXED

(MailNews Core :: Networking: IMAP, defect)

Description

[Jorg K (CEST = GMT+2)]

+++ This bug was initially created as a clone of Bug #1216951 +++

Today I started a debug build on my testing profile which includes a few IMAP accounts and I crashed :-(

The IMAP account is just my regular mail account that receives bug mail, nothing heavy and nothing that I would expect to use chunking.

I crashed here:
https://hg.mozilla.org/comm-central/rev/4868c63422f5#l1.151

There's been discussion in an somewhat unrelated bug about this: Bug 1443750 comment #9 and further down.

Comment 1

[gene smith]

Interesting. I assume you saw the crash when you clicked and tried to read an email with no huge attachments or complex structure? 

Also, need to know exactly how you are set up:

Using offline store?
If so, mbox or maildir?
Viewing attachments inline or as links?
Chunking enabled and threshold at default (~96000)?
Any other non-default prefs set?

I checked with several emails of moderate size that shouldn't cause chunking and, with a printf added to see if that assert is checked, I don't see the assert even being tried. Also, from what I have seen, chunking only occurs if you disable offline stores. 

Is there any more info about what you were doing when the assert hit that you can provide?

> There's been discussion in an somewhat unrelated bug about this: Bug 1443750 comment #9 and further down.

In that case, with attachments as links, when the attached eml is clicked it causes the whole message to be fetched in chunks. Then, with this fetch in progress, if you click on the png attachment link at the bottom of the new eml page, the png file is fetched as a single part, non-chunked. When the fetch in chunks gets to the point where it expect to see the orphan \n instead it see a random "line" from the simultaneously occurring non-chunk fetch that triggers the assert. I haven't figured out how these are getting "mixed" together yet(*). However, I have determined how to avoid the problem by preventing the extraneous full message fetch by chunks when the eml is clicked. (This full message download is never saved to cache and doesn't cause the url to be marked "Not Modified".) With this fix in place, the assert never occurs and the full png is downloaded, stored to cache and not corrupted and the picture fully displays and is not cut off.

(*)Maybe for a given message/folder, only 1 stream at a time is assumed to ever occur? I do see that the chunked and non-chucked fetches are on different tcp connections. I tried reducing the number of "cached" connections down to 1 and they *still* occurred on separate ports/connections!

Comment 2

[gene smith]

Looking closer at the code, it appears there is one nsImapServerResponseParser instance associated with each nsImapProtocol instance. I think there is a protocol instance for each of up to 5 mailboxes/folders per server (max cached connections). So if  a given message in a mailbox has more than one fetch/download in progress (even though they will be on separate streams/tcp ports), they will share the same instance of nsImapServerResponseParser::msg_fetch_literal() and potentially cause corrupted parser output. So doing more than one large download of a message at a time must be avoided.

Here's a description of the sequence when the picture (abstract art) displays correctly as I see when downloading from my localhost based dovecot server:

Click on eml link
Starts a full message download in chunks
eml page displays with png link at bottom
click png link
Now part fetch of the png body part begins (not in chunks) to a part cache entry
Several "assert" errors occur due to interleaving of responses. Part cache probably corrupted.
A pseudo interrupt occurs and dooms the part cache entry (which is good because it is probably bad)
Both downloads finish
Another part cache url is passed to OpenCacheEntry()
This restarts the part fetch of the png body part
This time it finishes with no interference and stores correct png to its parts cache entry.

So the full download and the first parts download occur and interfere with each other. The full download is useless and not save to the "entire message" cache like you would expect. The part download of the png is saved but gets, luckily, doomed. After both finish downloading, the png url occurs again and the parts download occurs again with no problems and the png cache is saved and the png file is not corrupted.
 
When downloading the same message from the tbtest server over the internet a similar sequence occurs but with different timing. However, the clashes between the full download and the png part download occur even after the last doom so no more "retry" part downloads occur after the full download finishes. This causes the png part cache entry to be good only up to the first "clash" and causes the partial picture to display. (Of course, if you wait to click the png link until the full message download finishes, the picture displays OK. However, there is no way to know when it finishes unless you watch the network.)

So the solution, that seems to work in all cases, is to suppress the extraneous full download and only allow the eml body part download to occur when eml link is clicked. Unfortunately, the doom also occurs while downloading just the png part that causes it download twice. The pseudo interrupt seems to cause a lot of redundant network traffic when large items are being downloaded.

Comment 3

[Jorg K (CEST = GMT+2)]

(In reply to gene smith from comment #1)
> Interesting. I assume you saw the crash when you clicked and tried to read
> an email with no huge attachments or complex structure? 
> 
> Also, need to know exactly how you are set up:
> 
> Using offline store?
> If so, mbox or maildir?
> Viewing attachments inline or as links?
> Chunking enabled and threshold at default (~96000)?
> Any other non-default prefs set?
I saw the crash when starting TB. No clicking, no nothing. I assume it was downloading IMAP messages at start-up.
I guess the profile is all mbox, all prefs at default values. I don't even know what the relevant ones are:
mail.server.default.fetch_by_chunks, mail.imap.chunk_size and mail.imap.min_chunk_size_threshold?

Comment 4

[gene smith]

Sounds like you are just configured as default. Yes, for chunking those are the relevant items. With a large inbox, I deleted the inbox.msf and inbox file and let them re-sync the enabled offline store. Saw absolutely no occurrence of the assert check, based on a printf, and, of course, no crash when the 64M inbox re-downloaded. Trying more variations to duplicate what you saw.

Can you duplicate the problem? Maybe you will have to shutdown tb and delete the files X and X.msf mailbox you were downloading and then startup tb.

Still trying various things but so far see nothing bad. Will keep trying...

Comment 5

[Jorg K (CEST = GMT+2)]

Well, all I can say is that I crashed again earlier today. I'll get you a stack next time.

Comment 6

[Jorg K (CEST = GMT+2)]

Gene, I crash on this in my debug build all the time. My test profile is connected to various real IMAP accounts, and when I start TB, e-mail is retrieved and this assert is triggered (which doesn't make my development easier).

I won't have time for the IMAP cache improvements (bug 1454542), but I'd look at this since I'm afraid that will affect TB 60 users once this is released as ESR. Also I think, we should do IMAPCache logging before we start anything else.

Comment 7

[gene smith]

Ok, I'll look at this again. I assume you are running with with offline store and attachments inline, i.e., basically default.
I've made a first cut at the IMAPCache logging and it seems to be working.

Comment 8

[gene smith]

Attachment: 1451137-for-review-v0.patch

I have tried and tried but the only way I can cause the assert is when I have two downloads going at the same time and one has chunks that split the \r\n. I have been unable to see a problem when just new messages come in at tb startup like you describe. 

The assert problem that I have been able to see is due to the static variable "nextChunkStartsWithNewline" being "shared" between multiple class instances, so it is set in one instance (download of one part) and then seen in another instance (concurrent download of another part) and causes the assert there.

The solution is to just make nextChunkStartsWithNewline a private class variable so it is not shared between instances. With this change I don't see the assert.

Since you say the assert crash occurs for you "all the time" maybe you can try this and see if it helps. But if it doesn't help, then could you send me an IMAP log so maybe I can see exactly what is happening for you? Thanks.

Comment 9

[Jorg K (CEST = GMT+2)]

Comment on attachment 8984783 [details] [diff] [review]
1451137-for-review-v0.patch

Yes, this sounds reasonable. In fact, it happens to me "all the time", usually when I start my local debug build after some messages have accumulated in various accounts connected to the test profile.

In any case, making this a member variable, strangely prefixed with "f" instead of "m", won't hurt. In fact, isn't the static quite fatal, since multiple instances share it and things get confused?

Comment 10

[Jorg K (CEST = GMT+2)]

Comment on attachment 8984783 [details] [diff] [review]
1451137-for-review-v0.patch

Review of attachment 8984783 [details] [diff] [review]:
-----------------------------------------------------------------

::: mailnews/imap/src/nsImapServerResponseParser.cpp
@@ -3085,5 @@
>                      numberOfCharsInThisChunk));
>  #endif
>  
>    charsReadSoFar = 0;
> -  static bool nextChunkStartsWithNewline = false;

How about initialising it here for safety?

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/28b628b92314
Make "next chunk starts with newline" flag a member variable to fix MOZ_ASSERT(). r=jorgk DONTBUILD

Comment 12

[Jorg K (CEST = GMT+2)]

Landed with DONTBUILD, Daily will build this.

Thanks Gene. I took the liberty to leave the initialisation in the code, I hope you agree:
https://hg.mozilla.org/comm-central/rev/28b628b92314#l1.30

Comment 13

[Jorg K (CEST = GMT+2)]

Unbelievable, this caused two test failures:

TEST-UNEXPECTED-FAIL | comm/mailnews/imap/test/unit/test_chunkLastLF.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | comm/mailnews/imap/test/unit/test_chunkLastLF.js | verifyContentLength - [verifyContentLength : 89] 1957 == 1958
TEST-UNEXPECTED-FAIL | comm/mailnews/imap/test/unit/test_imapChunks.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | comm/mailnews/imap/test/unit/test_imapChunks.js | OnStopRunningUrl - [OnStopRunningUrl : 112] "Message-ID: <foo.12345@bar>\\r\\nDate: Sun, 19 Oct 2008 08:00:00 +0000\\r\\nFrom: Me <[e-mail]>\\r\\nTo: You <[e-mail]>\\r\\nSubject: Test message\\r\\n\\r\\nThis message tests several conditions at the same time when\\r\\nused by test_imapChunks.js, which downloads 1000 byte chunks:\\r\\n\\r\\n1) download of a message in several chunks, when the

Can we fix those quickly, or otherwise I need to back this out :-(

Comment 14

[Jorg K (CEST = GMT+2)]

My sincere apologies, the test failures were (most likely) caused by the line I added to the original patch. I'll check it out and fix it.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/f7a87bfeedc5
Backed out changeset 28b628b92314. a=jorgk
https://hg.mozilla.org/comm-central/rev/5ee92a30a3f4
Make "next chunk starts with newline" flag a member variable to fix MOZ_ASSERT(). r=jorgk DONTBUILD

Comment 16

[gene smith]

Yes, that variable should only be initialized in the constructor. Anyhow, I am uncertain if this will fix the assert crash you see on tb startup and new mail is detected. But I'm sure you will let me know if it fails again. :)

Comment 17

[Jorg K (CEST = GMT+2)]

TB 60 beta 8 (BETA_60_CONTINUATION branch):
https://hg.mozilla.org/releases/comm-beta/rev/bd54ffd4d39b34b56de469c20f04d6d0d9a7e26b

Comment 18

[Jorg K (CEST = GMT+2)]

https://hg.mozilla.org/releases/comm-esr60/rev/9ceb60aadc29