565852 - Login to IMAP server is invoked upon every view of multipart/mixed mail, because downloading of multipart/mixed mail doesn't complete and LOGOUT is issued when other mail is clicked(Gmal IMAP,offline-use=off,mail.server.default.mime_parts_on_demand=true)

Status: VERIFIED FIXED

(MailNews Core :: Networking: IMAP, defect)

Description

[WADA:World Anti-bad-Duping Agency]

Attachment: NSPR log(imap:5)

[Buil Id]
> Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.3a5pre) Gecko/20100513 Shredder/3.2a1pre
Problem is observed with both Tb 3.1pre and Tb 3.0.4 too.

Download of multipart/mixed mail of IMAP offline-use=off folder doesn't complete, even after fetch of mail body part is executed and IDLE is normally issued and mail is displayed in message pane.

[Steps to rproduce]
(0) IDLE is enabled to see flow of IDLE command.
    Cached Connection : 2 or 3
    IMAP folder : ABCDEF, Offline-use=Off, Gmail IMAP is used
    View/Messages As Original HTML
    Display 
    UID=1: text/plain, Subject=fcc test, body=text,
           size=1KB
    UID=2: multipart/mixed, text part: Subject=big mail,body=zzz,
           size=12512KB, 1 PDF attachments
    UID=4: multipart/mixed, text part: Subject=big-mail-001, body=big-mail-001,
           size=20322KB, 1 PDF attachments
(1) Clear Disk Cache, and restart Tb 3.2pre
(2) Open ABCDEF
    Click UID=1 => OK => saved in Disk Cache
    Click UID=2 => OK => saved in Disk Cache
    Click UID=4 => OK => saved in Disk Cache
(3) Click UID=1 => OK
    Click UID=2 => fetch OK, IDLE is issued, mail is displayed
                   Downloading message... stays
    Click UID=1 => looks OK, but LOGOUT is issued
    Click UID=2 => re-login, fetch OK, IDLE is issued, mail is displayed
    Click UID=1 => OK
    Click UID=4 => fetch OK, IDLE is issued, mail is displayed
                   Downloading message... stays
    Click UID=1 => looks OK, but LOGOUT is issued

"Click UID=1" can be replaced by "Click Inbox". LOGOUT is issued at ABCDEF.

(Problem-1)
fetch of mail body part is noraly end, "S-ABCDEFG:STREAM:CLOSE: Normal Message End Download Stream" is logged, IDLE is issued, and mail is displayed,  downloading doesn't complete. And LOGOUT is issued when already downloaded small text/plain message(UID=1) is clicked while "Downloading message..." and progress bar is displayed.
(Problem-2)
Even though text/plain part(mail body part of multipart/mixed) is already donloaded in Disk Cache, UID fetch 2(or 4) (BODY.PEEK[1]) is always issued.

Disk Cache data is corrupted?

Comment 1

[Phil Lacy]

There was a post on the support group
news://news.mozilla.org:119/[e-mail]

not sure if that is applicable, where the poster reports imap folders are not being updated until they are clicked.

Comment 2

[WADA:World Anti-bad-Duping Agency]

Attachment: _CACHE_001_ of Disk Cache after first fetch of thee mails

Comment 3

[WADA:World Anti-bad-Duping Agency]

Attachment: _CACHE_002_ of Disk Cache after first fetch of thee mails

Comment 4

[WADA:World Anti-bad-Duping Agency]

_CACHE_001_ : two entries for mail data of UID=1, UID=2 
_CACHE_002_ : one entry for mail data of UID=4, and one entry of next lines.
> lIMAP-anywhere:23e692edimap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E1
>  ContentModified,  Not Modified,  security-info ...
> tIMAP-anywhere:23e692edimap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E4
>  ContentModified,  Modified View Inline,  security-info ...

Comment 5

[WADA:World Anti-bad-Duping Agency]

Attachment: _CACHE_002_ after problem occurred on UID=4

Comment 6

[WADA:World Anti-bad-Duping Agency]

Attachment: _CACHE_001_ after problem was observed on both UID=2 and UID=4

Comment 7

[WADA:World Anti-bad-Duping Agency]

Attachment: _CACHE_002_ after problem was observed on both UID=2 and UID=4

Comment 8

[WADA:World Anti-bad-Duping Agency]

Attachment: IMAP log, with Leak gauge enabled

Log with next, using DebugView for sequence number/timestamp.
> SET NSPR_LOG_MODULES=imap:5,ImapAutoSync:5,IMAPOFFLINE:5,MsgPurge:5,DOMLeak:5,DocumentLeak:5,nsDocShellLeak:5

When mail(UID=2,UID=4) was clicked, even though offline mode, next log was written, and progress bar was displayed.
> ImapThreadMainLoop entering
When other mail(UID=1) was clicked, next log was written, 
> CONTROL: PSEUDO-Interrupted
> TellThreadToDie: close socket connection
> ImapThreadMainLoop leaving
When mail(UID=2,UID=4) was clicked, "message of "not downloaded yet" was displayed at message pane.

This excess trying of connection to server looks cause of problem for me.

[1] Work Offline
> 00000468	16:33:32.853	[2584] 3068[4c07c80]: 8373000:imap.gmail.com:S-ABCDEFG:SendData: DONE 	
> 00000469	16:33:32.853	[2584] 3068[4c07c80]: 8373000:imap.gmail.com:S-ABCDEFG:SendData: 31 logout 	
> 00000470	16:33:32.869	[2584] 3068[4c07c80]: 8373000:imap.gmail.com:S-ABCDEFG:TellThreadToDie: close socket connection	
> 00000471	16:33:32.869	[2584] 3068[4c07c80]: ImapThreadMainLoop leaving [this=8373000]	
[2] Entered offline mode
[3] View UID=1
> 00000519	16:34:11.166	[2584] 0[192c140]: DOCSHELL 24ab850 InternalLoad imap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E1	
> [4] View UID=2 => Load doesn't complete
> 00000527	16:34:24.635	[2584] 0[192c140]: DOCSHELL 24ab850 InternalLoad imap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E2	
> 00000528	16:34:24.650	[2584] 3576[192e940]: ImapThreadMainLoop entering [this=286d800]	
> 00000529	16:34:24.650	[2584] 0[192c140]: 286d800:imap.gmail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN	
> 00000530	16:34:24.650	[2584] 0[192c140]: 286d800:imap.gmail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN	
[5] View UID=1 again
> 00000531	16:34:46.088	[2584] 0[192c140]: 286d800:imap.gmail.com:NA:CONTROL: PSEUDO-Interrupted	
> 00000532	16:34:46.088	[2584] 0[192c140]: DOCSHELL 24ab850 InternalLoad imap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E1	
> 00000533	16:34:46.088	[2584] 3576[192e940]: 286d800:imap.gmail.com:NA:TellThreadToDie: close socket connection	
> 00000534	16:34:46.088	[2584] 3576[192e940]: ImapThreadMainLoop leaving [this=286d800]	
[6] View UID=2 again
    => Message of "not downloaded yet..."  is displayed at message pane
> 00000574	16:35:05.681	[2584] DOCSHELL 24ab850 InternalLoad data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
> 00000577	16:35:05.728	[2584] DOCUMENT 197f800 StartDocumentLoad data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
> 00000580	16:35:05.728	[2584] DOCUMENT 197f800 ResetToURI data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
> 00000583	16:35:05.728	[2584] DOCSHELL 24ab850 SetCurrentURI data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
[7] View UID=1
> 00000584	16:35:20.822	[2584] 0[192c140]: DOCSHELL 24ab850 InternalLoad imap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E1	
[8] View UID=4
    => Load doesn't complete
> 00000591	16:35:23.572	[2584] 0[192c140]: DOCSHELL 24ab850 InternalLoad imap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E4	
> 00000592	16:35:23.588	[2584] 0[192c140]: 270d000:imap.gmail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN	
> 00000593	16:35:23.588	[2584] 3148[192ee40]: ImapThreadMainLoop entering [this=270d000]	
> 00000594	16:35:23.588	[2584] 0[192c140]: 270d000:imap.gmail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN	
[9] View UID=1 again
> 00000626	16:36:03.181	[2584] 0[192c140]: 270d000:imap.gmail.com:NA:CONTROL: PSEUDO-Interrupted	
> 00000627	16:36:03.181	[2584] 0[192c140]: DOCSHELL 24ab850 InternalLoad imap://[e-mail]:993/fetch%3EUID%3E/ABCDEFG%3E1	
> 00000628	16:36:03.181	[2584] 3148[192ee40]: 270d000:imap.gmail.com:NA:TellThreadToDie: close socket connection	
> 00000629	16:36:03.181	[2584] 3148[192ee40]: ImapThreadMainLoop leaving [this=270d000]	
[10] View UID=4 again
     => Message of "not downloaded yet..."  is displayed at message pane
> 00000637	16:36:16.510	[2584] DOCSHELL 24ab850 InternalLoad data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
> 00000640	16:36:16.556	[2584] DOCUMENT 28e5800 StartDocumentLoad data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
> 00000643	16:36:16.556	[2584] DOCUMENT 28e5800 ResetToURI data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
> 00000646	16:36:16.556	[2584] DOCSHELL 24ab850 SetCurrentURI data:text/html;base64,PGh0bWw+PGhlYWQ+PG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9VVRGLTgiPjwvaGVhZD48Ym9keT5UaGUgYm9keSBvZiB0aGlzIG1lc3NhZ2UgaGFzIG5vdCBiZWVuIGRvd25sb2FkZWQgZnJvbSB0aGUgc2VydmVyIGZvciByZWFkaW5nIG9mZmxpbmUuIFRvIHJlYWQgdGhpcyBtZXNzYWdlLCB5b3UgbXVzdCByZWNvbm5lY3QgdG8gdGhlIG5ldHdvcmssIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIEZpbGUgbWVudSBhbmQgdGhlbiB1bmNoZWNrIFdvcmsgT2ZmbGluZS4gSW4gdGhlIGZ1dHVyZSwgeW91IGNhbiBzZWxlY3Qgd2hpY2ggbWVzc2FnZXMgb3IgZm9sZGVycyB0byByZWFkIG9mZmxpbmUuIFRvIGRvIHRoaXMsIGNob29zZSBPZmZsaW5lIGZyb20gdGhlIGZpbGUgbWVudSBhbmQgdGhlbiBzZWxlY3QgU3luY2hyb25pemUuIFlvdSBjYW4gYWRqdXN0IHRoZSBEaXNrIFNwYWNlIHByZWZlcmVuY2UgdG8gcHJldmVudCB0aGUgZG93bmxvYWRpbmcgb2YgbGFyZ2UgbWVzc2FnZXMuPC9ib2R5PjwvaHRtbD4=	
[11] Work Online,
     repeat view UID=1,UID=1,UID=4,
     observe "download doesn't complete" and "logout"

Comment 9

[WADA:World Anti-bad-Duping Agency]

If mime_parts_on_demand=false is set,
> mail.server.server2.mime_parts_on_demand=false
whole mail data is held in Disk Cache as single file if user waits for download completion of whole mail data, and data in Disk Cache is used as expected upon next access.
However, when mails are quickly switched and Thunderbird is terminated, the sigle file for whole mail data was deleted.
Something around Disk Cache is still not implemented well? Problem around Disk Cache close upon termination?

Comment 10

[WADA:World Anti-bad-Duping Agency]

If attachments are image/jpeg, image/gif etc., problem was observed only with "Display Attachments Inline=Off", and absolutely same phenomenon as pdf attachments case. (mime_parts_on_demand=true)
As mail body part(first text/plain part) is small, mail data is held in _CACHE_00x_(x=one of 1, 2, 3). 

Problem was not observed with "Display Attachments Inline=On" if image attachements. Creation of some files in Disk Cache directory like next was observed in this case.
  When mail of text/plain + one or multiple image/xxx parts,
  next files were generated in Disk Cache directory.
    - one to several files with image data, with some parts of next data,
          "This body part will be downloaded on demand." 
    - and one file of whole mail data.

Inconsistency among MIME handling, new Disk Cache from Tb 3, and IMAP networking?

Comment 11

[WADA:World Anti-bad-Duping Agency]

Note: Bug 516211 comment #14 may be this bug on 2010-02-13.

Comment 12

[WADA:World Anti-bad-Duping Agency]

Shown text as mail body by InternalLoad data:text/html;base64,PGh0... in comment #8 while offline mode is next.

The body of this message has not been downloaded from the server for reading offline. To read this message, you must reconnect to the network, choose Offline from the File menu and then uncheck Work Offline. In the future, you can select which messages or folders to read offline. To do this, choose Offline from the file menu and then select Synchronize. You can adjust the Disk Space preference to prevent the downloading of large messages.

Comment 13

[Simon Paquet [:sipaq]]

David, can you please take a look at this? 
This is one of the major hurdles for people updating from TB2 to TB3.x

Comment 14

[David :Bienvenu]

I've got a lot on my plate right now getting the tree green again so it will be a while before I can look at this. Turning off the disk cache for imap messages would probably be a quick simple fix.

Comment 15

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #14)
> Turning off the disk cache for imap messages would probably be a quick simple fix.

It was not effective as workaround of this bug. Disabling of both of disk cache and memory cache was required with Tb 3.1.
OK  : browser.cache.disk.enable=false,        browser.cache.memory.enable=false
BAD : browser.cache.disk.enable=true, size=0, browser.cache.memory.enable=false
BAD : browser.cache.disk.enable=true, size>0, browser.cache.memory.enable=false
BAD : browser.cache.disk.enable=false,        browser.cache.memory.enable=true
BAD : browser.cache.disk.enable=true, size=0, browser.cache.memory.enable=true
BAD : browser.cache.disk.enable=true, size>0, browser.cache.memory.enable=true

When second access of a multipart/mixed(with PDF) mail, "Dowloading ..." and Progress bar remained at status bar. CPU utilization while it is 5 to 10%(on Dual Core. So 20 to 40% if single core). Refressing of progress bar looks to consume high CPU. No file I/O of Tb was traced by Process Monitor during the retry loop like behaviour. CPU was consumed by Tb's Thread-0 only(main thread, Checked with Performance Counter log).

To know "what Tb is doing", debug build or debug tools will be required.

Note:
Even if offline-use=on, if user clicks new mail which is not auto-sync'ed yet, auto-sync is paused and Cache(Disk Cache or Memory Cache) is used and this bug happens until troubled mail is auto-sync'ed.
See bug 570914.

Comment 16

[David :Bienvenu]

Comment on attachment 445309 [details]
NSPR log(imap:5)

this log looks like it's taken after the headers/messages are first downloaded, because the imap code is using cached body structures, so I can't really tell too much about the structure of the messages, or what happened when they were initially downloaded. I don't know why the server connection is getting dropped. I have not been able to reproduce this using the information here, unfortunately.

Comment 17

[WADA:World Anti-bad-Duping Agency]

Attachment: IMAP log for initial fetch of three mails

(In reply to comment #16)
> this log looks like it's taken after the headers/messages are first downloaded,
> because the imap code is using cached body structures, so I can't really tell
> too much about the structure of the messages, or what happened when they were
> initially downloaded.

See newly attached log for initial fetch, please.
(1) Clear Disk Cache, (2) Repair Folder, (3) Click UID=1, UID=2, UID=3
Note: folder name is changed from ABCDEFG to abcdefg.
      UID is changed to 1,2,3

Comment 18

[David :Bienvenu]

Thx, WADA. I didn't see a problem using my own IMAP server, but I did with gmail. Perhaps we have a problem parsing the gmail body structure, or maybe gmail's logging out is involved. What I think I've found is that the problem message fits in the memory cache, we will use mime parts on demand correctly, but otherwise we try to fetch the whole message.

Er, when I say I saw a problem, I just mean that we tried to fetch the whole message, when we shouldn't. I didn't see corrupted messages getting into the disk cache, or the message failing to load.

Comment 19

[WADA:World Anti-bad-Duping Agency]

Tb's request.
> 17 UID fetch 3 (BODY.PEEK[HEADER] BODY.PEEK[1.MIME] BODY.PEEK[2.MIME] BODY.PEEK[3.MIME] BODY.PEEK[4.MIME])
Gmail IMAP retruns [n.MIME]s in reversed order.
  HEADER, [4.MIME], [3.MIME], [2.MIME], [1.MIME]
Is this a cause?

Comment 20

[David :Bienvenu]

I don't know - I've been stupidly testing this with audio files, and I think we've never been smart enough to know that we shouldn't download audio files inline. Also, unbeknownst to me, one of my messages got into the offline store, which was confusing me and my testing.

PDF's are of type application, and we do know that they're not supposed to be inline. So I have a small patch that fixes AUDIO files, and I'll go back to testing.

Comment 21

[David :Bienvenu]

The logout is issued because we're trying to load a url in a doc shell that thinks it is already loading a url, which causes a cancel of the load group, which interrupts the imap url. I think the issue is simply that the notifications about starting and stopping the url have gotten a bit confused. I think I have a simple fix for that.

Unlike WADA, I'm not seeing partial messages ending up in the disk cache, at least according to about:cache, though I haven't looked at the actual files on disk yet.

Comment 22

[David :Bienvenu]

Ah, the partial messages are in the disk cache files on disk, but they're not valid or used, so that's a bit misleading. I don't think this bug has anything to do with the disk cache, or any of the corruptions people have been reporting.

Comment 23

[David :Bienvenu]

Attachment: only set reading from cache to true if we opened the cache entry successfully.

not sure how I'd write a unit test for this, but it seems to fix the problem for me.

Comment 24

[David :Bienvenu]

fix checked in - WADA, if you want to try tomorrow's nightly build and verify that what you were seeing is fixed, that would be very helpful, thx!

Comment 25

[WADA:World Anti-bad-Duping Agency]

Checked with next build,
> Mozilla/5.0 (Windows NT 5.1; rv:2.0b4pre) Gecko/20100806 Shredder/3.2a1pre
with
> browser.cache.disk.enable=true, browser.cache.memory.enable=true

From tester's perspective, problem of bug summary is only partially resolved, although it's improved very much by fixing of problem you quickly found.

(1) Click mail which is BODY[1] is already downloaded.
(1-1) FETCH BODY[1] is issued, even though BODY[1] is already downloaded.
(1-2) Even though FETCH BODY[1] completed and Subject, mail body, is shown
      at message pane, "Downloading..." continues.
(2) When ohter mail is clicked, LOGOUT is issued.
    Then next click of other mail forces start from LOGIN.

As (1-2) disappeared by your patch, (2) didn't occur, if I wait completion of step (1-1). However, some problems still remain.
(Problem-A)
Even though FETCH BODY[1] normally ended at step (1-1), FETCH BODY[1] is issued upon next click of the mail.
i.e. DISK cache has no meaning.
(Problem-B)
If other mail is clicked while step (1-1), LOGOUT seems to be issued, because "connectiong to server..." or "opening folder ..." is shown at status bar, when other mail is clicked.
i.e. Your patch resolved problem of (1-2) only.

Should we open bug for each phenomnon with slightly different operations or conditions?

Comment 26

[David :Bienvenu]

We don't want to cache partial messages in the disk cache, so I would expect the body[1] to be fetched each time. It sounds like what you're saying the remaining issue is that if you click on a separate message while we're still loading body[1] (i.e., body[1] is a very large body), then we get interrupted by the doc shell and logout. That's a separate issue. In other words, pseudo-interruption isn't working for body part fetches...

Comment 27

[WADA:World Anti-bad-Duping Agency]

Problem-A and Problem-B I observed sounds design or spec. I seems to have had overexpectation on Disk Cache with mime_parts_on_demand=true. I dont't touch "Disk Cache with mime_parts_on_demand=true" case any more.
Closing as FIXED/VERIFIED, as infinite "Downloading..." problem has been fixed.

Comment 28

[David :Bienvenu]

the disk and memory caches use the url that's run as the lookup key to the cache entry. When you click on a message, the url is for the whole message; it's not until we've examined the body structure that we realize we're not going to fetch the whole message, but we've already set up the cache entry.

Comment 29

[Wayne Mery (:wsmwk)]

wada, what is the performance impact of this bug on the user experience, and it's friends, bug 576194 and bug 572974?

Comment 30

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #29)

Performance impact for user in comment #0 are;
a) If mail ismultipart mail and not-all parts are downloaded upon first mail
   view, fetch body[1] for mail body and subsequent fetch body[N] for
   inline-displayed parts are always requested again before showing mail at
   message in pane, even though the parts are already downloaded onece.
b) Upon a), login is always forced before fetch body[1].
c) Due to a) & b), mail showing takes "time for b)" + "time for a)" always.
  
Performance impact for server is;
d) Tb forces excess server workload due to b).

As b) is fixed by this bug, d) is not problem any more.
As a) is current design, I say nothing about "time for a)".

Comment 31

[Mark Lord]

Whatever you guys did, Imap is suddenly usable again (TB 3.1.4) for the first time since TB2.  It used to be dead slow, downloading only 1-5 messages per second.  Now it's back into the 50-150 range.  Thanks!

Comment 34

[rsx11m]

This should be suitable as a stability fix for the release branches as well.
As can be seen from the duplicates, the issue causes visible problems...

Comment 36

[David :Bienvenu]

Comment on attachment 462459 [details] [diff] [review]
only set reading from cache to true if we opened the cache entry successfully.

should be a safe fix for 3.1.7 or 3.1.8

Comment 37

[Mark Banner (:standard8)]

Checked into 1.9.2: http://hg.mozilla.org/releases/comm-1.9.2/rev/b74c2de39308

Comment 39

[rsx11m]

I see an apparent re-caching of attachments after a successful cache operation, but I'm not sure if it's a consequence or was just masked by the issue here.

I've filed bug 629738 on this observation, not setting any dependency though.

Comment 40

[Andreas M. Kirchwitz]

I'm currently using Thunderbird 7.0.1, and the same behaviour now happens again with messages containing attachments. Has the fix been removed accidentally?

Comment 41

[rsx11m]

Are you sure that the IMAP connection is actually dropped and Thunderbird logs in again when going to a new message (watch the status bar), otherwise it's most likely bug 629738 what you observe.

Comment 42

[David :Bienvenu]

(In reply to Andreas M. Kirchwitz from comment #40)
> I'm currently using Thunderbird 7.0.1, and the same behaviour now happens
> again with messages containing attachments. Has the fix been removed
> accidentally?

No, the patch is still in the code. Are you seeing disk cache corruptions, or are we really logging out of the connection when you click on an other message?

Comment 43

[Andreas M. Kirchwitz]

I don't see the connection to bug #629738 but it looks like Thunderbird now also has problems with attachments that can be displayed inline. That's different. Haven't noticed that because I just focused on the endless "Downloading message..." display and that remembered me of this bug here. Looks like I need to open a new bug. But I'll have to collect some more information first to make it easily reproducible. Thanks a lot for your fast response!