577533 - Calendar attachments trigger disconnection from Exchange IMAP server

Status: RESOLVED INCOMPLETE

(Thunderbird :: Mail Window Front End, defect)

Description

[Scott A. Colcord]

While connected to an IMAP server, Thunderbird behaves normally for a time, but then begins repeatedly popping up error messages saying "Server foo.com has disconnected. The server may have gone down or there may be a network problem".  The messages continue popping up, at a rate of about one per second, until Thunderbird is closed.

After reading through related issues, I have tried adjusting the "Maximum number of server connections to cache" to values from 1 to 5, with no improvement.

This might be considered two issues:

1) What's causing the disconnect in the first place?
2) Regardless of the cause, error messages should not spam the display.

I've tried outputting an imap.log, but it's extremely verbose, so I'm not sure what to look for.  One possible anomaly is that my IMAP server's address changed from oldservername.com to newservername.com, but Thunderbird still considers the folders to be at imap://[e-mail].

The first lines of imap.log are:

0[1e33140]: 4b6a000:oldservername.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
15232[5ebbe00]: 4b6a000:oldservername.com:NA:ProcessCurrentURL: entering
15232[5ebbe00]: 4b6a000:oldservername.com:NA:ProcessCurrentURL:imap://[e-mail]:143/select%3E/INBOX:  = currentUrl
15232[5ebbe00]: 4b6a000:oldservername.com:NA:CreateNewLineFromSocket: * OK Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (newservername.com) ready.

15232[5ebbe00]: 4b6a000:oldservername.com:NA:SendData: 1 capability

15232[5ebbe00]: 4b6a000:oldservername.com:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4 IMAP4rev1 IDLE LOGIN-REFERRALS MAILBOX-REFERRALS NAMESPACE LITERAL+ UIDPLUS CHILDREN AUTH=NTLM

15232[5ebbe00]: 4b6a000:oldservername.com:NA:CreateNewLineFromSocket: 1 OK CAPABILITY completed.

15232[5ebbe00]: 4b6a000:oldservername.com:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
15232[5ebbe00]: 4b6a000:oldservername.com:NA:CreateNewLineFromSocket: 3 OK LOGIN completed.

15232[5ebbe00]: 4b6a000:oldservername.com:A:SendData: 4 namespace

15232[5ebbe00]: 4b6a000:oldservername.com:A:CreateNewLineFromSocket: * NAMESPACE (("" "/")) NIL NIL

15232[5ebbe00]: 4b6a000:oldservername.com:A:CreateNewLineFromSocket: 4 OK NAMESPACE completed.

15232[5ebbe00]: 4b6a000:oldservername.com:A:SendData: 5 list "" "%"

Comment 1

[David :Bienvenu]

see bug 577343 for dealing with 2). For 1), those are just the folder URI's, which use the original host name; I doubt that's the cause of the problem. The part of the log that's more interesting is the end, when the disconnects are happening. If you want to zip a log up, and send it to me, I can have a look. But I suspect that you really are getting disconnected, either because of server or network issues.

Comment 2

[Scott A. Colcord]

I did not have these issues prior to upgrading from 2.0.0.24, although it's possible that the network issues were there, but I just didn't notice them because the alerts weren't there and they didn't cause any major problems.  The log contains many thousands of CreateNewLineFromSocket records that essentially dump the contents of my mailbox, which contains information I can't resend; there's no clear error at the end.  I will see if I can find a way to filter out the cruft.

Comment 3

[Scott A. Colcord]

The fix for bug 577343 does indeed appear to have eliminated the rapid-fire messages.  However, I'm still getting frequent disconnection errors.  
Here's the IMAP log for one of them:

[...Fetching messages lines...]
3276[4c32840]: 3faa800:servername:S-MyFolder:CreateNewLineFromSocket: END:DAYLIGHT 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=15 needmore=0]
3276[4c32840]: 3faa800:servername:S-MyFolder:CreateNewLineFromSocket: END:VTIMEZONE 3276[4c32840]: ReadNextLine [stream=522a748 nb=4294967295 needmore=0]
3276[4c32840]: 3faa800:servername:S-MyFolder:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b0014
3276[4c32840]: 3faa800:servername:S-MyFolder:TellThreadToDie: close socket connection
3276[4c32840]: 3faa800:servername:S-MyFolder:CreateNewLineFromSocket: (null)
3276[4c32840]: 3faa800:servername:S-MyFolder:STREAM:CLOSE: Abort Message  Download Stream
0[1d33140]: creating protocol instance to retry queued url:imap://username@servername:143/select>/MyFolder
0[1d33140]: retrying  url:imap://username@servername:143/select>/MyFolder
3788[50f2cc0]: ImapThreadMainLoop entering [this=2bb0000]
0[1d33140]: 2bb0000:servername:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
3788[50f2cc0]: 2bb0000:servername:NA:ProcessCurrentURL: entering
3276[4c32840]: ImapThreadMainLoop leaving [this=3faa800]
3788[50f2cc0]: 2bb0000:servername:NA:ProcessCurrentURL:imap://username@servername:143/select%3E/MyFolder:  = currentUrl
3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=107 needmore=0]
3788[50f2cc0]: 2bb0000:servername:NA:CreateNewLineFromSocket: * OK Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (servername) ready. 3788[50f2cc0]: 2bb0000:servername:NA:SendData: 1 capability 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=115 needmore=0]
3788[50f2cc0]: 2bb0000:servername:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4 IMAP4rev1 IDLE LOGIN-REFERRALS MAILBOX-REFERRALS NAMESPACE LITERAL+ UIDPLUS CHILDREN AUTH=NTLM 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=28 needmore=0]
3788[50f2cc0]: 2bb0000:servername:NA:CreateNewLineFromSocket: 1 OK CAPABILITY completed. 3788[50f2cc0]: try to log in
3788[50f2cc0]: IMAP auth: server caps 0x186235, pref 0x1006, failed 0x0, avail caps 0x4
3788[50f2cc0]: (GSSAPI = 0x1000000, CRAM = 0x20000, NTLM = 0x100000, MSN =  0x200000, PLAIN = 0x1000, LOGIN = 0x2, old-style IMAP login = 0x4)
3788[50f2cc0]: trying auth method 0x4
3788[50f2cc0]: got new password
3788[50f2cc0]: IMAP: trying auth method 0x4
3788[50f2cc0]: old-style auth
3788[50f2cc0]: 2bb0000:servername:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=23 needmore=0]
3788[50f2cc0]: 2bb0000:servername:NA:CreateNewLineFromSocket: 3 OK LOGIN completed. 3788[50f2cc0]: login succeeded
3788[50f2cc0]: 2bb0000:servername:A:SendData: 4 select "MyFolder" 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=14 needmore=0]
3788[50f2cc0]: 2bb0000:servername:A:CreateNewLineFromSocket: * 213 EXISTS 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=12 needmore=0]
3788[50f2cc0]: 2bb0000:servername:A:CreateNewLineFromSocket: * 0 RECENT 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=61 needmore=0]
3788[50f2cc0]: 2bb0000:servername:A:CreateNewLineFromSocket: * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent) 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=91 needmore=0]
3788[50f2cc0]: 2bb0000:servername:A:CreateNewLineFromSocket: * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=43 needmore=0]
3788[50f2cc0]: 2bb0000:servername:A:CreateNewLineFromSocket: * OK [UIDVALIDITY 7170] UIDVALIDITY value 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=37 needmore=0]
3788[50f2cc0]: 2bb0000:servername:A:CreateNewLineFromSocket: 4 OK [READ-WRITE] SELECT completed. 3788[50f2cc0]: 2bb0000:servername:S-MyFolder:SendData: 5 UID fetch 1:* (FLAGS) 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=35 needmore=0]
3788[50f2cc0]: 2bb0000:servername:S-MyFolder:CreateNewLineFromSocket: * 1 FETCH (FLAGS (\Seen) UID 892) 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=35 needmore=0]
3788[50f2cc0]: 2bb0000:servername:S-MyFolder:CreateNewLineFromSocket: * 2 FETCH (FLAGS (\Seen) UID 893) 3788[50f2cc0]: ReadNextLine [stream=4d1cc08 nb=35 needmore=0]

This last message repeats 213 times, with the numbers before the FETCH and after the UID both incrementing.

All of the errors seem to follow this form, and the common theme I'm seeing is the "nb=4294967295".  Is that a value one would normally expect to see?  It looks like it's always happening on similar lines; the END:VTIMEZONE lines of VCALENDAR attachments.

Comment 4

[David :Bienvenu]

0x804b0014 is NS_ERROR_NET_RESET, meaning either the server dropped the connection, or a firewall dropped the connection, or something like that.

Comment 5

[Scott A. Colcord]

So it seems like Exchange server is dropping the connection every time (or at least some of the time) it tries to send us a VCALENDAR appointment?

What does the "nb=4294967295" indicate?

Comment 6

[Scott A. Colcord]

A bit more information:  I'm seeing more such errors; they are not all on the END:VTIMEZONE lines, but they do all happen during the transmission of a calendar attachment from an Exchange server to Thunderbird.  

I'm able to look at and manipulate the affected message normally from Outlook via its regular client or via web access.  Moving the message to a different folder makes the Thunderbird error happen on the new folder instead.

Thunderbird also does not recover properly from this event.  After it occurs, I then start to see messages for the affected folder:  "Downloading message X of Y", where X > Y.

Comment 7

[David :Bienvenu]

nb=4294967295 is probably a small negative number, indicating that an error happened on the read.

This could be the issue with Exchange where it doesn't like to calculate attachment sizes exactly so it reports a rough approximation. I believe there's a setting on the Exchange server which can be tweaked to make it report correct attachment sizes for IMAP.

Comment 8

[Scott A. Colcord]

Unfortunately, this is a large-corporation mail server; getting IT to reconfigure it to accommodate anything but Outlook is unlikely.

I'm not sure about the attachment size hypothesis.  There are lots of other emails with attachments in my mailbox, but only the calendar ones are causing problems.

Comment 9

[Wayne Mery (:wsmwk)]

duplicate of bug 92111 ?

Scott, do you still see this probllem?

Comment 10

[Wayne Mery (:wsmwk)]

incomplete?

Scott writes "I changed jobs about a year ago" and no longer has access to reproduce

Comment 11

[Wayne Mery (:wsmwk)]

perhaps invalid or fixed, but we can't know without reporter testing, so incomplete.