561753 - Error message stating failed to save to sent (Internal timeout=20 seconds of Tb after last segment of mail data is sent in APPEND may be too short for some IMAP servers. MS OE like "Wait more one minutes?" prompt may be needed in such case.)

Status: RESOLVED INCOMPLETE

(MailNews Core :: Networking: IMAP, defect)

Description

[Mr. I. M. Williams]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.2.3pre) Gecko/20100405 Firefox/3.6.3plugin1
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.1.8) Gecko/20100227 Thunderbird/3.0.3

Note that this is an issue with XP (Pro), Vista 32 & 64bit as wella s Windows 7 and occurred with earlier versions of Thunderbird, at least as early as February 2009.
If my e-mail exceeds a certain size by having an attachment in excess of some unestablished size, (a file of 2,195Kb fails), I will receive an error message that the message was sent but that Thunderbird failed to save my message to sent, retry? Retrying will also fail. (The messages, even considerably bigger, are, as stated safely transmitted.)
Thunderbird will fail to function correctly subsequently.
The only way, however, I have found to recover is to reboot the system.
When I restart Thunderbird, after rebooting, I will find that Thunderbird has, in fact, successfully saved the e-mail but that there are multiple copies saved depending upon how long I have waited before rebooting the system I was using.

I have contacted my ISP and they have told me that they can find nothing wrong at their side and that I should be able to transmit e-mails of up to 100Mb with no problem.

Reproducible: Always

Steps to Reproduce:
1.As far as I am aware, need to be using Imap mail.
2.The e-mail has an attachment making its overall size greater than at least 2.195Mb.
3.
Actual Results:  
Message declaring Thunderbird had failed to copy e-mail to Sent (on server).
After rebooting and restarting Thunderbird, multiple copies of e-mail found in Sent folder.

Expected Results:  
Thunderbird should have simply reported copying to Sent and closed e-mail being sent once finished.

Comment 1

[Ludovic Hirlimann [:Usul]]

Is your ISP plus.com ?

Can you generate a imap log when this is happening, see https://wiki.mozilla.org/MailNews:Logging for instructions to generate the logs ( you might want to change the log location as c:\ isn't always writable).

Comment 2

[Mr. I. M. Williams]

Yes, if you mean PlusNet.
As for generating an imap log.
Is it a matter of running the (Windows) batch file, as described, and then attempting to send an e-mail which can be expected to exhibit this problem?

Comment 3

[Phil Lacy]

I have intermittently had this problem with gmail but not often enough or with certainty to make a log. It also does successfully copy the message to the sent folder even though it indicates it failed. I never notice multiple copies and have not notice subsequent problems.

Instead of rebooting, can you try using the task manager to kill the running Thunderbird (after exiting). Then after it has been killed from taskmanager, restart thunderbird and check the status. The taskmanager should be available when you hit ctrl-alt-del

Comment 4

[Ludovic Hirlimann [:Usul]]

(In reply to comment #2)
> Yes, if you mean PlusNet.
> As for generating an imap log.
> Is it a matter of running the (Windows) batch file, as described, and then
> attempting to send an e-mail which can be expected to exhibit this problem?

Yes !

Comment 5

[Mr. I. M. Williams]

I have recreated the problem with logging enabled. The resulting log file, however, is a massive 97 Mb. Even compressed it is nearly 63 Mb. How do I send it to you if you still want it?
Thunderbird displayed several error messages whilst trying to save.
A Send Message Error where it informed me it had successfully sent the message but that it could not be copied to my Sent folder. Would I like to return to the compose window. With a choice of OK and Cancel buttons, OK being highlighted.
Whist writing down the error message Thunderbird presented another saying Save Draft Error saying "Unable to save your message as draft. Please verify .... with an OK button.
When closing write mail window Thunderbird presents a "Sending Message" error "Thunderbird is currently in the process of sending a message. Would you like to wait ... with a choice of Wait and Quit buttons, Wait highlighted.
On choosing quit and waiting some ten minuits a copy of the message did appear in the Sent folder and Thunderbird appeared to be working normally.
On rebooting (after about twenty minutes in total), however, and restarting Thunderbird I found that my Sent folder now contained twelve copies of the message.

Comment 6

[David :Bienvenu]

You could edit the log to remove the hex data where we're appending the message to the server, since that's not important to us. There will be long sequences of 74 byte long lines with nothing but hex digits. We're also not that interested in the stuff up to the point where we send the "append" command to the server, so you could remove much of the beginning of the log.

Comment 7

[WADA:World Anti-bad-Duping Agency]

Mr. I. M. Williams, get imap log with timestamp using smallest text mail and check log content first, please.
> http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25328
> SET NSPR_LOG_MODULES=timestamp,imap:5
> SET NSPR_LOG_MODULES=timestamp,imap:5,smtp:5  (if smtp log is required)
"Copy(upload) sent mail data to Sent of IMAP" is roughly;
  (1) append Sent, (2) reply of "please send data" from server,
  (3) pass mail data lines to server, (4) send indicator of "end of data",
  then (5) OK response from server.
Log lines before (1) is not required to see above uploading process at first. As mail data itself is irrelevant, log lines for step (3) can be removed.
See http://tools.ietf.org/html/rfc3501 for IMAP command and response.

After check with small mail, get IMAP log with timestamp using big mail, and remove log lines before step 1 and many many log lines for step 3 from your huge log file. And, check whether step 4 is executed or not(error while step 3), and check whether OK is returned or not(error such as timeout while step 3).

Comment 8

[Mr. I. M. Williams]

I had hoped to copy below the drastically cropped log file from my test e-mail of 30 April.
Reducing its size proved to be a time consuming task. I hope I have not cut out any vital data. After editing out the attachment data it still left a file of around 15.5Mb. The piece I wished to send you is a small fraction of it at some 250Kb. Unfortunately even that exceeds the maximum number of characters allowed for comment length.
Is there another means of getting it to you? At 250Kb it would easily go in an e-mail. I could even put back some of the data I have cut out.
I have copied the very start and a short part of the tail below.


0[162c140]: 80cc800:imap.plus.net:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
1068[7b0ce80]: ReadNextLine [stream=6e0f9c8 nb=23 needmore=0]
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:CreateNewLineFromSocket: 9 OK FETCH completed.1068[7b0ce80]: 80cc800:imap.plus.net:S-

INBOX:SendData: 10 IDLE1068[7b0ce80]: ReadNextLine [stream=6e0f9c8 nb=22 needmore=0]
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:CreateNewLineFromSocket: + entering idle mode1068[7b0ce80]: 80cc800:imap.plus.net:S-

INBOX:SendData: DONE1068[7b0ce80]: ReadNextLine [stream=6e0f9c8 nb=22 needmore=0]
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:CreateNewLineFromSocket: 10 OK IDLE completed1068[7b0ce80]: 80cc800:imap.plus.net:S-

INBOX:ProcessCurrentURL: entering
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:ProcessCurrentURL:imap://[e-mail]:143/folderstatus%3E.INBOX:  = 

currentUrl
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:SendData: 11 noop1068[7b0ce80]: ReadNextLine [stream=6e0f9c8 nb=22 needmore=0]
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:CreateNewLineFromSocket: 11 OK NOOP completed1068[7b0ce80]: 80cc800:imap.plus.net:S-

INBOX:SendData: 12 IDLE3856[9a22d00]: ImapThreadMainLoop entering [this=9d59800]
0[162c140]: 9d59800:imap.plus.net:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
3856[9a22d00]: 9d59800:imap.plus.net:NA:ProcessCurrentURL: entering
3856[9a22d00]: 9d59800:imap.plus.net:NA:ProcessCurrentURL:imap://[e-mail]:143/folderstatus%3E.INBOX.Drafts:  = 

currentUrl
1068[7b0ce80]: ReadNextLine [stream=6e0f9c8 nb=22 needmore=0]
1068[7b0ce80]: 80cc800:imap.plus.net:S-INBOX:CreateNewLineFromSocket: + entering idle mode3856[9a22d00]: ReadNextLine [stream=a3ecd48 nb=233 

needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT 

THREAD=REFERENCES SORT QUOTA IDLE ACL ACL2=UNION] Courier-IMAP ready. Copyright 1998-2008 Double Precision, Inc.  See COPYING for 

distribution information.3856[9a22d00]: 9d59800:imap.plus.net:NA:SendData: Logging suppressed for this command (it probably contained 

authentication information)
3856[9a22d00]: ReadNextLine [stream=a3ecd48 nb=16 needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:NA:CreateNewLineFromSocket: 1 OK LOGIN Ok.3856[9a22d00]: 9d59800:imap.plus.net:A:SendData: 2 STATUS 

"INBOX.Drafts" (UIDNEXT MESSAGES UNSEEN RECENT)3856[9a22d00]: ReadNextLine [stream=a3ecd48 nb=69 needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: * STATUS "INBOX.Drafts" (MESSAGES 10 RECENT 0 UIDNEXT 719 UNSEEN 0)3856

[9a22d00]: ReadNextLine [stream=a3ecd48 nb=24 needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: 2 OK STATUS Completed.3856[9a22d00]: 

9d59800:imap.plus.net:A:ProcessCurrentURL: entering
3856[9a22d00]: 9d59800:imap.plus.net:A:ProcessCurrentURL:imap://[e-mail]:143/folderstatus%3E.INBOX.Sent:  = currentUrl
3856[9a22d00]: 9d59800:imap.plus.net:A:SendData: 3 STATUS "INBOX.Sent" (UIDNEXT MESSAGES UNSEEN RECENT)3856[9a22d00]: ReadNextLine 

[stream=a3ecd48 nb=69 needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: * STATUS "INBOX.Sent" (MESSAGES 569 RECENT 0 UIDNEXT 1730 UNSEEN 0)3856

[9a22d00]: ReadNextLine [stream=a3ecd48 nb=24 needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: 3 OK STATUS Completed.3856[9a22d00]: 

9d59800:imap.plus.net:A:ProcessCurrentURL: entering
3856[9a22d00]: 9d59800:imap.plus.net:A:ProcessCurrentURL:imap://[e-mail]:143/appendmsgfromfile%3E.INBOX.Sent:  = 

currentUrl
3856[9a22d00]: 9d59800:imap.plus.net:A:SendData: 4 append "INBOX.Sent" (\Seen) {5532021}3856[9a22d00]: ReadNextLine [stream=a3ecd48 nb=6 

needmore=0]
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: + OK3856[9a22d00]: 9d59800:imap.plus.net:A:SendData: Message-ID: 

<[e-mail]>Date: Fri, 30 Apr 2010 22:16:52 +0100From: "Mr. I. M. Williams" <[e-mail]>User-Agent: 

Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.1.9) Gecko/20100317 Thunderbird/3.0.4MIME-Version: 1.0To: @sky.com>Subject: Another 

PhotoContent-Type: multipart/mixed;3856[9a22d00]:  boundary="------------020209060403020901010601"This is a multi-part message in MIME 

format.--------------020209060403020901010601Content-Type: text/plain; charset=ISO-8859-1; format=flowedContent-Transfer-Encoding: 

7bit--------------020209060403020901010601Content-Type: image/jpeg; 
3856[9a22d00]: 9d59800:imap.plus.net:A:SendData: tjixeL5FGFPV9V2Oc17X9dXXLd9EmD+I9Rt7a0lis1+TTd5IJ

EUDGc8k9PT864PxAXUp8pEcjO3U4n+v/66mEVVuo6djojlWHqfFJvyZ//Z--------------020209060403020901010601--3856[9a22d00]: 

9d59800:imap.plus.net:A:SendData: 3856[9a22d00]: ReadNextLine [stream=a3ecd48 nb=0 needmore=1]
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
3856[9a22d00]: 9d59800:imap.plus.net:A:TellThreadToDie: close socket connection
3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: (null)
0[162c140]: creating protocol instance to retry queued url:imap://[e-mail]:143/appendmsgfromfile>.INBOX.Sent
0[162c140]: retrying  url:imap://[e-mail]:143/appendmsgfromfile>.INBOX.Sent
0[162c140]: 1603000:imap.plus.net:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
3856[9a22d00]: ImapThreadMainLoop leaving [this=9d59800]
4796[5623ec0]: ImapThreadMainLoop entering [this=1603000]
4796[5623ec0]: 1603000:imap.plus.net:NA:ProcessCurrentURL: entering
4796[5623ec0]: 1603000:imap.plus.net:NA:ProcessCurrentURL:imap://[e-mail]:143/appendmsgfromfile%3E.INBOX.Sent:  = 

currentUrl
4796[5623ec0]: ReadNextLine [stream=1639888 nb=233 needmore=0]
4796[5623ec0]: 1603000:imap.plus.net:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT 

THREAD=REFERENCES SORT QUOTA IDLE ACL ACL2=UNION] Courier-IMAP ready. Copyright 1998-2008 Double Precision, Inc.  See COPYING for 

distribution information.4796[5623ec0]: 1603000:imap.plus.net:NA:SendData: Logging suppressed for this command (it probably contained 

authentication information)
4796[5623ec0]: ReadNextLine [stream=1639888 nb=16 needmore=0]
4796[5623ec0]: 1603000:imap.plus.net:NA:CreateNewLineFromSocket: 1 OK LOGIN Ok.4796[5623ec0]: 1603000:imap.plus.net:A:SendData: 2 append 

"INBOX.Sent" (\Seen) {5532021}4796[5623ec0]: ReadNextLine [stream=1639888 nb=6 needmore=0]
4796[5623ec0]: 1603000:imap.plus.net:A:CreateNewLineFromSocket: + OK4796[5623ec0]: 1603000:imap.plus.net:A:SendData: Message-ID: 

<[e-mail]>Date: Fri, 30 Apr 2010 22:16:52 +0100From: "Mr. I. M. Williams" <[e-mail]>User-Agent: 

Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.1.9) Gecko/20100317 Thunderbird/3.0.4MIME-Version: 1.0To: @sky.com>Subject: Another 

PhotoContent-Type: multipart/mixed;4796[5623ec0]:  boundary="------------020209060403020901010601"This is a multi-part message in MIME 

format.--------------020209060403020901010601Content-Type: text/plain; charset=ISO-8859-1; format=flowedContent-Transfer-Encoding: 7bit4796

[5623ec0]: --------------020209060403020901010601Content-Type: image/jpeg; name=".jpg"Content-Transfer-Encoding: base644796[5623ec0]: 

Content-Disposition: attachment; filename=".jpg"
4796[5623ec0]: 1603000:imap.plus.net:A:SendData:

EUDGc8k9PT864PxAXUp8pEcjO3U4n+v/66mEVVuo6djojlWHqfFJvyZ//Z--------------020209060403020901010601--4796[5623ec0]: 

1603000:imap.plus.net:A:SendData: 4796[5623ec0]: ReadNextLine [stream=1639888 nb=0 needmore=1]
4796[5623ec0]: 1603000:imap.plus.net:A:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
4796[5623ec0]: 1603000:imap.plus.net:A:TellThreadToDie: close socket connection
4796[5623ec0]: 1603000:imap.plus.net:A:CreateNewLineFromSocket: (null)
0[162c140]: 165c000:imap.plus.net:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
3456[5e68780]: ImapThreadMainLoop entering [this=165c000]
3456[5e68780]: 165c000:imap.plus.net:NA:ProcessCurrentURL: entering
3456[5e68780]: 165c000:imap.plus.net:NA:ProcessCurrentURL:imap://[e-mail]:143/appendmsgfromfile%3E.INBOX.Sent:  = 

currentUrl
4796[5623ec0]: 1603000:imap.plus.net:A:ProcessCurrentURL: aborting queued urls
4796[5623ec0]: ImapThreadMainLoop leaving [this=1603000]
3456[5e68780]: ReadNextLine [stream=1639a68 nb=233 needmore=0]
3456[5e68780]: 165c000:imap.plus.net:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT 

THREAD=REFERENCES SORT QUOTA IDLE ACL ACL2=UNION] Courier-IMAP ready. Copyright 1998-2008 Double Precision, Inc.  See COPYING for 

distribution information.3456[5e68780]: 165c000:imap.plus.net:NA:SendData: Logging suppressed for this command (it probably contained 

authentication information)
3456[5e68780]: ReadNextLine [stream=1639a68 nb=16 needmore=0]
3456[5e68780]: 165c000:imap.plus.net:NA:CreateNewLineFromSocket: 1 OK LOGIN Ok.3456[5e68780]: 165c000:imap.plus.net:A:SendData: 2 append 

"INBOX.Sent" (\Seen) {5532021}3456[5e68780]: ReadNextLine [stream=1639a68 nb=6 needmore=0]
3456[5e68780]: 165c000:imap.plus.net:A:CreateNewLineFromSocket: + OK3456[5e68780]: 165c000:imap.plus.net:A:SendData: Message-ID: 

<[e-mail]>Date: Fri, 30 Apr 2010 22:16:52 +0100From: "Mr. I. M. Williams" <[e-mail]>User-Agent: 

Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.1.9) Gecko/20100317 Thunderbird/3.0.4MIME-Version: 1.0To: @sky.com>Subject: Another 

PhotoContent-Type: multipart/mixed;3456[5e68780]:  boundary="------------020209060403020901010601"This is a multi-part message in MIME 

format.--------------020209060403020901010601Content-Type: text/plain; charset=ISO-8859-1; format=flowedContent-Transfer-Encoding: 7bit3456

[5e68780]: --------------020209060403020901010601Content-Type: image/jpeg; name=".jpg"Content-Transfer-Encoding: base643456[5e68780]: 

Content-Disposition: attachment; filename=""

4n+v/66mEVVuo6djojlWHqfFJvyZ//Z--------------020209060403020901010601--3456[5e68780]: 165c000:imap.plus.net:A:SendData: 3456[5e68780]: 

Tail end:-

3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 

JbpPPaOzOEVl6uRyeTxg8KeBjnmuzs/DGoaVAIpAZnhAjLLyvA528DAJyRkVwRqTlBqqtEzl3496[5623b00]: ReadNextLine [stream=1639748 nb=74 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 

rwljJOVKWh5D4/8AMtbSHThtaCKURxQk/LGAc/KfbtWd8SYL6KRGmLLCu1mjOCcE8EY5z0P+3496[5623b00]: ReadNextLine [stream=1639748 nb=74 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 

ePMxWI9lJe7o9j6rKqcKdJyqPVFbwzaakIY5kj3o88yRvDyrFOwPTIyM80zwrq0620UItGaN3496[5623b00]: ReadNextLine [stream=1639748 nb=74 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 

LgeZLE3CFgclgeuMbfl9vevVlh44bSGsn0Plsdi/bVG1FNP8D04yXUQieSLz/mO5GGQuOefz3496[5623b00]: ReadNextLine [stream=1639748 nb=74 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 7/8A6rgvLaS1DQln2ptcupXBHXrg

+2elVUwUqEfa3u307HHRy/28eWOj7nH3fneVJK28Lkjf3496[5623b00]: ReadNextLine [stream=1639748 nb=74 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: tI/XpVy41vT7OF3ufKKRsZW83G0AcnOTj

+fFccKFO/K1q92eph6tSh7kUnboXdBmd4Tb3ih43496[5623b00]: ReadNextLine [stream=1639748 nb=74 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: hh41b

+LHPI9ciqmmavp2oW8VzavBKJjlXiGBweD35HA/ClhKtOk3De/4GKccbJ68r6nTamdL3496[5623b00]: ReadNextLine [stream=1639748 nb=70 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: ltytyo3MYgEUDGc8k9PT864PxAXUp8pEcjO3U4n

+v/66mEVVuo6djojlWHqfFJvyZ//Z3496[5623b00]: ReadNextLine [stream=1639748 nb=42 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: --------------020209060403020901010601--3496[5623b00]: 

ReadNextLine [stream=1639748 nb=3 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: )3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:STREAM:CLOSE: 

Normal Message End Download Stream
3496[5623b00]: ReadNextLine [stream=1639748 nb=23 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 6 OK FETCH completed.0[162c140]: considering playing queued 

url:imap://[e-mail]:143/folderstatus>.INBOX.Sent
0[162c140]: creating protocol instance to play queued url:imap://[e-mail]:143/folderstatus>.INBOX.Sent
0[162c140]: playing queued url:imap://[e-mail]:143/folderstatus>.INBOX.Sent
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:ProcessCurrentURL: entering
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:ProcessCurrentURL:imap://[e-mail]:143/folderstatus%3E.INBOX.Sent:  = 

currentUrl
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:SendData: 7 noop3496[5623b00]: ReadNextLine [stream=1639748 nb=21 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: 7 OK NOOP completed3496[5623b00]: 604f400:imap.plus.net:S-

INBOX.Sent:SendData: 8 IDLE3496[5623b00]: ReadNextLine [stream=1639748 nb=22 needmore=0]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:CreateNewLineFromSocket: + entering idle mode3188[5e68140]: 

5ff5c00:imap.plus.net:A:SendData: 4 logout4188[5e68780]: 7ad5400:imap.plus.net:S-INBOX:SendData: DONE4188[5e68780]: 

7ad5400:imap.plus.net:S-INBOX:SendData: 8 close4188[5e68780]: 7ad5400:imap.plus.net:S-INBOX:SendData: 9 logout3496[5623b00]: 

604f400:imap.plus.net:S-INBOX.Sent:SendData: DONE3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:SendData: 9 close3496[5623b00]: 

604f400:imap.plus.net:S-INBOX.Sent:SendData: 10 logout3188[5e68140]: 5ff5c00:imap.plus.net:A:TellThreadToDie: close socket connection
3188[5e68140]: ImapThreadMainLoop leaving [this=5ff5c00]
4188[5e68780]: 7ad5400:imap.plus.net:S-INBOX:TellThreadToDie: close socket connection
4188[5e68780]: ImapThreadMainLoop leaving [this=7ad5400]
3496[5623b00]: 604f400:imap.plus.net:S-INBOX.Sent:TellThreadToDie: close socket connection
3496[5623b00]: ImapThreadMainLoop leaving [this=604f400]

Comment 9

[David :Bienvenu]

Oh, yes, you can e-mail it to me - [e-mail]

Comment 10

[WADA:World Anti-bad-Duping Agency]

Mr. I. M. Williams(bug opener), thanks for providing most important part of log data.
Rough flow by your log data is as follows. Error is seen after Tb has passed whole mail data to server(timeout? no response from server within reasonable time?).

> 4 append "INBOX.Sent" (\Seen)
>(snip)
> Content-Type: multipart/mixed; boundary="------------020209060403020901010601"
>(snip)
> --------------020209060403020901010601
> Content-Type: image/jpeg; 
>(snip, base64 enoded image data lines follow)
> --------------020209060403020901010601--
>(above is close boundary line. whole mail data is passed to server at here)
>(snip) 
> 9d59800:imap.plus.net:A:SendData: 3856[9a22d00]: ReadNextLine [stream=a3ecd48 nb=0 needmore=1]
> 3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: clearing
> IMAP_CONNECTION_IS_OPEN - rv = 804b000e
> 3856[9a22d00]: 9d59800:imap.plus.net:A:TellThreadToDie: close socket connection
> 3856[9a22d00]: 9d59800:imap.plus.net:A:CreateNewLineFromSocket: (null)
> 0[162c140]: creating protocol instance to retry queued
> url:imap://[e-mail]:143/appendmsgfromfile>.INBOX.Sent
> 0[162c140]: retrying

By the way, even if you drastically cropped log file, log data is sufficiently large. Please don't paste in such case. Save in text file and attach the file to this bug, please.

Comment 11

[WADA:World Anti-bad-Duping Agency]

Following is log data of bug 538283 comment #27 for same part as yours.
After sending "end of data indicator" at 14:47:30, "9 OK Completed" was returned at 14:47:33. For Tb, it took three minutes at server to return OK after he received whole mail data. CPU 100% looks to have occurred during this three minutes too, even though Tb is merely waiting for "OK" response from IMAP server(waiting at IMAP level. not socket/TCP/IP level).
In your case, error occurred before "OK Completed" from server. 

> 2010-05-01 14:47:29.578000 UTC - 2336[585f440] --------------010004020308040603050400--
> 2010-05-01 14:47:30.250000 UTC - 2336[585f440]: 48b5c00:imap.gmx.net:A:SendData: 
> 2010-05-01 14:47:33.703000 UTC - 2336[585f440]: ReadNextLine [stream=680c0c8
nb=16 needmore=0]
> 2010-05-01 14:47:33.703000 UTC - 2336[585f440]: 48b5c00:imap.gmx.net:A:CreateNewLineFromSocket: 9 OK Completed

Mr. I. M. Williams(bug opener), does your IMAP server use SSL or StartTLS? Is CPU 100% and non-resposiveness observed while large mail data uploading to your IMAP server?
Can you get IMAP log with timestamp and check same part?
(cut all log lines before sending last "close boundary", and check data)

Comment 12

[Mr. I. M. Williams]

Sorry WADA, but I missed the option to attach a file. I didn't notice it at the top! Maybe it should follow this box down.

I attempted to send the edited file (of 15.5Mb) as an attachment but your system will not accept non-patch files greater than 2048Kb in size.
It's a pity you can't even accept WinRAR compressed files which would be down to 4.24Mb, though even that would have been to much.
I shall try other options.

Comment 13

[Mr. I. M. Williams]

Attachment: Short text only e-mail Log

Short text only e-mail log as requested by WADA.

Comment 14

[Mr. I. M. Williams]

Having sent the compressed (4.25Mb) log directly to David I ended up with six copies in Sent. All with the same time. I stopped Thunderbird after waiting a time for the e-mail to appear in Sent. It did not. Thunderbird.exe was not running in "Program Manager". On restarting Sent gradually accumulated more and more despite stopping and restarting Thunderbird another couple of times. After the sixth copy appeared I rebooted the system and have received no further additions to Sent.
The log file generated this time is some 34.7Mb, so will again need some drastic editing.

Comment 15

[Mr. I. M. Williams]

Attachment: Edited Log File of E-mail with 4.25Mb attachment.

Have attached edited copy of log file of 4.25Mb file sent to David.
It is now only 20Kb (from 34.7Mb) so I hope I haven't cut too much out!

Comment 16

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #13)
> Short text only e-mail Log
(In reply to comment #15)
> Edited Log File of E-mail with 4.25Mb attachment.

I've changed Mime-Type of these attachments to text/plain.

Comment 17

[WADA:World Anti-bad-Duping Agency]

(Correction of comment #11)
OK was returned within 3 seconds in bug 538283. 

(In reply to comment #13)
> Short text only e-mail Log

UIDPLUS is enabled.
> 2010-05-02 10:51:14.657000 UTC - (snip) 6 append "INBOX.Sent" (\Seen)
>(snip)
> 2010-05-02 10:51:14.931000 UTC - (snip) 6 OK [APPENDUID 1044278730 1743]
>(snip)
> 2010-05-02 10:51:21.284000 UTC - (snip) * OK [CAPABILITY IMAP4rev1 UIDPLUS
>  CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE ACL ACL2=UNION] Courier-IMAP ready.

(In reply to comment #15)
> Edited Log File of E-mail with 4.25Mb attachment.

From "append" to "close boundary / null line" : 2 minutes and 28 seconds 
From "send null line"(end of data) to error   : 21 seconds 
If simple timeout, 21 seconds looks for me too short.
No response from server at lower level(IP level) due to busy which is caused by big mail? Or caused by similar problem to Bug 559676?
> Bug 559676 nsSocketTRansportServuce::DoPollIteration hogging the CPU
> while uploading a large file to an SSL web server

(log)
> 2010-05-02 11:11:06.664000 UTC - (snip) SendData: 14 append "INBOX.Sent" (\Seen) {5958070}
>(snip)
> 2010-05-02 11:13:34.056000 UTC - (snip) SendData: (snip) --------------000708090909080607090203--
> 2010-05-02 11:13:34.740000 UTC - (snip) SendData: 
> 2010-05-02 11:13:55.453000 UTC - (snip) CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e

Comment 18

[David :Bienvenu]

We have a shorter timeout for the append, since, in theory, the server has been processing the data as it receives it and it just has to send an OK response, which shouldn't take 20 seconds. In other words, the timeout is from when we upload the very last piece of the message. We shortened the timeout because we were running into issues where the fcc was trying to use stale imap connections, and the longer timeout really made things painful.

We've had several issues with servers that miscount the number of bytes appended, and never give us the OK response. For those servers, increasing the timeout won't help.  I could generate a try server build with a larger timeout to see if it helps you.

Comment 19

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #18)
> We have a shorter timeout for the append, since, in theory,
> the server has been processing the data as it receives it
> and it just has to send an OK response, which shouldn't take 20 seconds.

Your theory is not always applicable to server in real world.
IMAP server must guarantee that received mail data won't be lost once he returns OK for append command to IMAP client.
If mail data is saved in Unix Mbox file or per mail folder file, and if mail data base can be recreated from the file for mail data(Same as Tb's way for local mail folder), OK can be returned immediately after receive of last segment. (bug 538283. OK is returned within 3 seconds)
However, if central Data Base is used as mail data repository, OK can be returned only when INSERT of whole mail data and commit of the INSERT  completed after receive of last segment. In such case, "required time to return OK" is never linear to last segment size, and it is often larger than O(whole mail data size). (Gmail like. Gmail IMAP doesn't have issue around it though.)

This bug is which of next case?
  (a) it takes long to return OK
  (b) OK will never be returned
MS Outlook Express 6 has capability to ask user "Wait more? Or cancel?" when timeout is detected. Does Tb have such capability?

Comment 20

[Wayne Mery (:wsmwk)]

wada, what new title would you give to the bug summary?

Comment 21

[Mr. I. M. Williams]

Why is this bug still "Unconfirmed"?
I have occasionally had to send e-mails with larger attachments and still experience the "failed to save" issue.
This morning I have again needed to sent a short e-mail but with an attached file of 2.153 Mb in size and again experienced the fail to save problem.
The e-mail is, as usual, saved in "Sent", though with the usual multiple copies depending upon how often I accept to the "Retry" option, which, from experience, I keep to a minimum and how soon I shut down Thunderbird (V 10.0.2) and the system.

Comment 22

[WADA:World Anti-bad-Duping Agency]

(In reply to Mr. I. M. Williams from comment #21)
> Why is this bug still "Unconfirmed"?

It's simply because that no one could/can see problem you reported to this bug report at B.M.O.

Comment 23

[Mr. I. M. Williams]

To Wada:- Following the data I supplied back in 2010 and the debate which followed, I thought the existence of the problem had been established. You even discussed it three weeks ago.
Has no-one else reported a similar problem even if limited to the same ISP (PlusNet) as myself?
It's not as though the problem is found on just one of my PCs, one version of Windows or even one revision of Thunderbird.
The one option I have yet to try is sending a large e-mail via Thunderbird on a Linux system.

Comment 24

[WADA:World Anti-bad-Duping Agency]

(In reply to Mr. I. M. Williams from comment #23)
> Has no-one else reported a similar problem even if limited to the same ISP (PlusNet) as myself?

As for me, I don't know report like yours at B.M.O and at forums.

Check of differences among following cases may help to know what happens.
(0) Create a big mail in local mail folder.
    Compose, attach big file, Send Later, Move mail in Outbox of "Local Folder"
    to a local mail folder.
(1-a) Tb, without open any IMAP folder, copy big mail from local to IMAP Sent.
Stop any automatic mail folder access, click IMAP account, terminate Tb, restart TB, keep IMAP account selected status(no IMAP folder is selected).
Copy the big mail in local mail folder to IMAP folder via context menu of mail.
(1-b) Tb, with Sent of IMAP opened, copy big mail from local to IMAP Sent.
Stop any automatic mail folder access, click IMAP account, terminate Tb, restart TB, click Sent folder of IMAP account.
Copy the big mail in local mail folder to IMAP folder via context menu of mail.
(2-a) same test as (1-a) by Windows Mail 
(2-b) same test as (1-b) by Windows Mail 

Timeout value of MS's mailer is usually larger than Tb, so server's response time after upload of all mail data may be measured by Windows Mail.
"Long time to return OK response" may be a result of virus scan at server.
If mail scanner of anti-virus software is enabled at PC, it may cause long response time. If proxy type mail scanner at PC, mail scanner may send mail data to IMAP server after he receives all mail data from Tb. If Proxy server is used for IMAP server access, Proxy server may pass mail data to actual IMAP server after he receives all mail data from Tb.

Comment 25

[Wayne Mery (:wsmwk)]

IM seems to be gone

Comment 26

[Mr. I. M. Williams]

I'm sorry that I have not been in touch recently, I have unfortunately had some health issues occupying my attention.
However, since last contact I had been having some exchanges with my ISP (PlusNet) as to what an IMAP server should be capable of doing. I was arguing that the server, as part of the service, (besides storing incoming mail), also stores copies of outgoing mail, (and, also, other folders).

The PlusNet servers do do this, (and the folders are managed in the same way as incoming mail), but the PlusNet technicians insisted that their service does not actually support the feature.
I pursued this for an extended period but failed to persuade them otherwise. They informed me that they were, therefore, not prepared to look into the issue I was experiencing with Thunderbird.

If I am mistaken as to the way IMAP functions do please enlighten me.

During this it slipped my mind to respond to yourselves (the other issues did not help either).

On occasions when I did send a large e-mail I had learnt to ignore the error messages that "save had failed" and simply allowed, (not usually needed but to be certain), two loops before telling Thunderbird to cancel the attempt to save, because the mail was always, in fact, being successfully saved.
Recently, however, (using V 17.0.8) I sent an e-mail of some 1.6Mb without any protests with respect to saving "sent" from Thunderbird.

(To confuse things I do, however, suspect that PlusNet may have modified their systems in some way recently.)