658533 - Thunderbird can't finish downloading messages

Status: RESOLVED WORKSFORME

(MailNews Core :: Networking: IMAP, defect)

Description

[qbsmd]

User-Agent:       Mozilla/5.0 (Windows NT 5.1; rv:2.0.1) Gecko/20100101 Firefox/4.0.1
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.17) Gecko/20110414 Thunderbird/3.1.10

Thunderbird deleted all the offline messages on one of my IMAP accounts a few days ago (Bug 658528). Since then, it has been unable to redownload the messages. I left it online uninterupted for about 8 hours and about 12 hours, and each time it grew the database files until filling my hard drive. By copying the database files to the local folders account, I was able to see that it was downloading hundreds or thousands of copies of some of the messages, without success. I assume this is a timeout error, but changing the timeout settings (mailnews.tcptimeout, mail.server.server2.timeout, network.ftp.idleConnectionTimeout, and network.http.keep-alive.timeout) had no effect.

Reproducible: Always

Steps to Reproduce:
1. delete the database and .msf files for a large IMAP account containing some large attachments
2. start Thunderbird
3.

Actual Results:  
Thunderbird downloads thousands of partial copies of messages without completely downloading them.

Expected Results:  
Thunderbird downloads one complete copy of each message then stops.

Comment 1

[Ludovic Hirlimann [:Usul]]

Can you capture an imap log as described at https://wiki.mozilla.org/MailNews:Logging so we can see what's going on ?

Comment 2

[qbsmd]

Okay, I can capture logs now. Most of the logs consist of "CreateNewLineFromSocket" statements followed by base 64 data. It looks like Thunderbird starts a session by sending lots of "FETCH" commands, then gets the body of an email, then tries to download the attachment in base 64. I'm pasting in the part of the log that happens before it repeats all of those steps (for the same email):


2156[2e70500]: 3f12800:outlook.com:S-Sent Items:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
2156[2e70500]: 3f12800:outlook.com:S-Sent Items:TellThreadToDie: close socket connection
2156[2e70500]: 3f12800:outlook.com:S-Sent Items:CreateNewLineFromSocket: (null)
2156[2e70500]: 3f12800:outlook.com:S-Sent Items:STREAM:CLOSE: Abort Message  Download Stream
2156[2e70500]: 3f12800:outlook.com:S-Sent Items:ProcessCurrentURL: aborting queued urls
2156[2e70500]: 3f12800:outlook.com:S-Sent Items:SendData: clearing IMAP_CONNECTION_IS_OPEN
2156[2e70500]: ImapThreadMainLoop leaving [this=3f12800]
744[2e70c80]: ReadNextLine [stream=413be28 nb=53 needmore=0]
744[2e70c80]: 3f15800:outlook.com:NA:CreateNewLineFromSocket: * OK The Microsoft Exchange IMAP4 service is ready.

744[2e70c80]: 3f15800:outlook.com:NA:SendData: 1 capability

744[2e70c80]: ReadNextLine [stream=413be28 nb=65 needmore=0]
744[2e70c80]: 3f15800:outlook.com:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN IDLE NAMESPACE LITERAL+

744[2e70c80]: ReadNextLine [stream=413be28 nb=28 needmore=0]
744[2e70c80]: 3f15800:outlook.com:NA:CreateNewLineFromSocket: 1 OK CAPABILITY completed.

744[2e70c80]: try to log in
744[2e70c80]: IMAP auth: server caps 0x85235, pref 0x1006, failed 0x0, avail caps 0x1004
744[2e70c80]: (GSSAPI = 0x1000000, CRAM = 0x20000, NTLM = 0x100000, MSN =  0x200000, PLAIN = 0x1000, LOGIN = 0x2, old-style IMAP login = 0x4)
744[2e70c80]: trying auth method 0x1000
744[2e70c80]: got new password
744[2e70c80]: IMAP: trying auth method 0x1000
744[2e70c80]: PLAIN auth
744[2e70c80]: 3f15800:outlook.com:NA:SendData: 2 authenticate plain

744[2e70c80]: ReadNextLine [stream=413be28 nb=3 needmore=0]
744[2e70c80]: 3f15800:outlook.com:NA:CreateNewLineFromSocket: +

744[2e70c80]: 3f15800:outlook.com:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
744[2e70c80]: ReadNextLine [stream=413be28 nb=30 needmore=0]
744[2e70c80]: 3f15800:outlook.com:NA:CreateNewLineFromSocket: 2 OK AUTHENTICATE completed.

744[2e70c80]: login succeeded
744[2e70c80]: 3f15800:outlook.com:A:SendData: 3 select "INBOX"

744[2e70c80]: ReadNextLine [stream=413be28 nb=14 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * 759 EXISTS

744[2e70c80]: ReadNextLine [stream=413be28 nb=12 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * 0 RECENT

744[2e70c80]: ReadNextLine [stream=413be28 nb=61 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)

744[2e70c80]: ReadNextLine [stream=413be28 nb=91 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags

744[2e70c80]: ReadNextLine [stream=413be28 nb=46 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * OK [UNSEEN 32] Is the first unseen message

744[2e70c80]: ReadNextLine [stream=413be28 nb=45 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * OK [UIDVALIDITY 969948] UIDVALIDITY value

744[2e70c80]: ReadNextLine [stream=413be28 nb=55 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: * OK [UIDNEXT 10265] The next unique identifier value

744[2e70c80]: ReadNextLine [stream=413be28 nb=37 needmore=0]
744[2e70c80]: 3f15800:outlook.com:A:CreateNewLineFromSocket: 3 OK [READ-WRITE] SELECT completed.

744[2e70c80]: 3f15800:outlook.com:S-INBOX:SendData: 4 UID fetch 1:* (FLAGS)

744[2e70c80]: ReadNextLine [stream=413be28 nb=34 needmore=0]

Comment 3

[qbsmd]

I was able to work around this problem by installing Thunderbird on a machine "closer" to the email server, downloading the messages there, and then copying that inbox to my machine while Thunderbird was not running. That indicates to me that this is definitely a timeout issue that needs to be corrected, but I have no way of knowing if Thunderbird is implementing this worthless timeout, or if an email server or router somewhere is responsible.

Comment 4

[Wayne Mery (:wsmwk)]

qbsmd,
do you still see this problem on the *problem* machine when using a current version?

Comment 5

[qbsmd]

I've reformatted and reinstalled the operating system since 2011, but running version 12.0.1 under a Debian variant doesn't seem to have the problem.

Comment 6

[Wayne Mery (:wsmwk)]

qbsmd, thanks for the update