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)

VERIFIED FIXED in Thunderbird 3.3a1

Status

MailNews Core
Networking: IMAP
--
major
VERIFIED FIXED
7 years ago
6 years ago

People

(Reporter: World, Assigned: Bienvenu)

Tracking

(Blocks: 1 bug)

Trunk
Thunderbird 3.3a1
Dependency tree / graph

Thunderbird Tracking Flags

(thunderbird3.1 .8-fixed)

Details

(Whiteboard: [has protocol log])

Attachments

(9 attachments)

(Reporter)

Description

7 years ago
Created attachment 445309 [details]
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?
(Reporter)

Updated

7 years ago
Attachment #445309 - Attachment mime type: application/octet-stream → text/plain
(Reporter)

Updated

7 years ago
Blocks: 564148

Comment 1

7 years ago
There was a post on the support group
news://news.mozilla.org:119/ef59dc87-82af-4a12-9a37-b8861d8ccf7b@j35g2000yqm.googlegroups.com

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

Comment 2

7 years ago
Created attachment 445567 [details]
_CACHE_001_ of Disk Cache after first fetch of thee mails
(Reporter)

Comment 3

7 years ago
Created attachment 445568 [details]
_CACHE_002_ of Disk Cache after first fetch of thee mails
(Reporter)

Updated

7 years ago
Attachment #445568 - Attachment mime type: application/octet-stream → text/plain
(Reporter)

Updated

7 years ago
Attachment #445567 - Attachment mime type: text/plain → text/plain; charst="iso-8859-1"
(Reporter)

Updated

7 years ago
Attachment #445568 - Attachment mime type: text/plain → text/plain; charst="iso-8859-1"
(Reporter)

Comment 4

7 years ago
_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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com:993/fetch%3EUID%3E/ABCDEFG%3E1
>  ContentModified,  Not Modified,  security-info ...
> tIMAP-anywhere:23e692edimap://yatter%2Eone%40gmail%2Ecom@imap.gmail.com:993/fetch%3EUID%3E/ABCDEFG%3E4
>  ContentModified,  Modified View Inline,  security-info ...
(Reporter)

Comment 5

7 years ago
Created attachment 445569 [details]
_CACHE_002_ after problem occurred on UID=4
(Reporter)

Updated

7 years ago
Attachment #445569 - Attachment mime type: text/plain → text/plain; charst="iso-8859-1"
(Reporter)

Comment 6

7 years ago
Created attachment 445571 [details]
_CACHE_001_ after problem was observed on both UID=2 and UID=4
(Reporter)

Comment 7

7 years ago
Created attachment 445572 [details]
_CACHE_002_ after problem was observed on both UID=2 and UID=4
(Reporter)

Updated

7 years ago
Attachment #445571 - Attachment mime type: text/plain → text/plain; charst="iso-8859-1"
(Reporter)

Updated

7 years ago
Attachment #445572 - Attachment mime type: text/plain → text/plain; charst="iso-8859-1"
(Reporter)

Updated

7 years ago
Summary: 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 → 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 (IMAP, offline-use=off)
(Reporter)

Comment 8

7 years ago
Created attachment 446873 [details]
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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com: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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com: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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com: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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com: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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com: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://yatter%2Eone%40gmail%2Ecom@imap.gmail.com: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"
Whiteboard: [has protocol log]
(Reporter)

Comment 9

7 years ago
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?
(Reporter)

Comment 10

7 years ago
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?
(Reporter)

Comment 11

7 years ago
Note: Bug 516211 comment #14 may be this bug on 2010-02-13.
(Reporter)

Comment 12

7 years ago
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.
(Reporter)

Updated

7 years ago
Blocks: 570914
(Reporter)

Updated

7 years ago
Summary: 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 (IMAP, offline-use=off) → 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 (IMAP, offline-use=off, mail.server.default.mime_parts_on_demand=true)
(Reporter)

Updated

7 years ago
Severity: normal → major
OS: Windows XP → All
Hardware: x86 → All
David, can you please take a look at this? 
This is one of the major hurdles for people updating from TB2 to TB3.x
(Assignee)

Comment 14

7 years ago
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.
(Reporter)

Comment 15

7 years ago
(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.
(Reporter)

Updated

7 years ago
Blocks: 576194
(Reporter)

Updated

7 years ago
Blocks: 570804
(Reporter)

Updated

7 years ago
No longer blocks: 570804
(Reporter)

Updated

7 years ago
Blocks: 572974
(Assignee)

Comment 16

7 years ago
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.
(Reporter)

Comment 17

7 years ago
Created attachment 462181 [details]
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
(Assignee)

Comment 18

7 years ago
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.
(Reporter)

Updated

7 years ago
Summary: 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 (IMAP, offline-use=off, mail.server.default.mime_parts_on_demand=true) → 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)
(Reporter)

Comment 19

7 years ago
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?
(Assignee)

Comment 20

7 years ago
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.
(Assignee)

Comment 21

7 years ago
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.
(Assignee)

Comment 22

7 years ago
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.
(Assignee)

Comment 23

7 years ago
Created attachment 462459 [details] [diff] [review]
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.
Assignee: nobody → bienvenu
Attachment #462459 - Flags: superreview?(neil)
Attachment #462459 - Flags: review?(neil)

Updated

7 years ago
Attachment #462459 - Flags: superreview?(neil)
Attachment #462459 - Flags: superreview+
Attachment #462459 - Flags: review?(neil)
Attachment #462459 - Flags: review+
(Assignee)

Comment 24

7 years ago
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!
Status: NEW → RESOLVED
Last Resolved: 7 years ago
Resolution: --- → FIXED
(Reporter)

Comment 25

7 years ago
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?
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(Assignee)

Comment 26

7 years ago
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...
(Reporter)

Comment 27

7 years ago
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.
Status: REOPENED → RESOLVED
Last Resolved: 7 years ago7 years ago
Resolution: --- → FIXED
(Reporter)

Updated

7 years ago
Status: RESOLVED → VERIFIED
(Assignee)

Comment 28

7 years ago
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.
wada, what is the performance impact of this bug on the user experience, and it's friends, bug 576194 and bug 572974?
(Reporter)

Comment 30

7 years ago
(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

7 years ago
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!

Updated

7 years ago
Duplicate of this bug: 599830

Updated

7 years ago
Duplicate of this bug: 529210

Comment 34

7 years ago
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...
status-thunderbird3.0: --- → ?
status-thunderbird3.1: --- → ?

Updated

7 years ago
Duplicate of this bug: 576194
(Assignee)

Comment 36

7 years ago
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
Attachment #462459 - Flags: approval-thunderbird3.1.7?
Attachment #462459 - Flags: approval-thunderbird3.1.7? → approval-thunderbird3.1.8?
Attachment #462459 - Flags: approval-thunderbird3.1.8? → approval-thunderbird3.1.8+
Target Milestone: --- → Thunderbird 3.3a2
Target Milestone: Thunderbird 3.3a2 → Thunderbird 3.3a1
status-thunderbird3.0: ? → ---
Checked into 1.9.2: http://hg.mozilla.org/releases/comm-1.9.2/rev/b74c2de39308
status-thunderbird3.1: ? → .8-fixed

Updated

7 years ago
Duplicate of this bug: 624347

Comment 39

7 years ago
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.
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

6 years ago
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.
(Assignee)

Comment 42

6 years ago
(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?
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!
You need to log in before you can comment on or make changes to this bug.