If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

Sent mail error copying the message to large sent folder since upgrading to TB3.0 (Warning message at Activity Manager is required for unexpected/undefined untagged/unsolicit response from server to IMAP commands)

NEW
Unassigned

Status

MailNews Core
Networking: IMAP
--
enhancement
8 years ago
2 years ago

People

(Reporter: mlecha, Unassigned)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [has protocol log])

Attachments

(1 attachment)

219.90 KB, application/octet-stream
Details
(Reporter)

Description

8 years ago
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 (.NET CLR 3.5.30729)
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.7) Gecko/20100111 Thunderbird/3.0.1

This is an IMAP account.

Since upgrading to Thunderbird 3.0 I frequently (~70%) get the error "There was an error copying the message to the sent folder. Retry?" when I send mail. Typically it tries for about 30 seconds before failing.

Thunderbird 1.x and 2.x worked fine with the same mail server.

The mail is sent via SMTP fine, and received fine.

Often a copy of the mail IS copied to my sent folder. If I keep trying, I might see 3-5 copies of the same email in my sent folder.



IMAP account:
[CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ IDLE UIDPLUS NAMESPACE CHILDREN MAILBOX-REFERRALS BINARY UNSELECT ESEARCH WITHIN SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND] User mlecha authenticated

Reproducible: Sometimes

Steps to Reproduce:
1. compose email
2. send
3. email is sent fine

4. with compose window still open in the background, the send dialog stays onscreen with "Sending login information..." with 100% on the progress bar, then after about 5 minutes eventually changes to "There was an error copying the message to the sent folder. Retry?" - OK, Cancel


Actual Results:  
5. the mail us sent and a copy of the email is in the sent folder


Some SMTP and IMAP log:

2010-01-12 20:03:11.454000 UTC - 3252[59b96c0]: 6421000:mail.artengine.ca:A:CreateNewLineFromSocket: 5 OK STATUS completed

2010-01-12 20:03:12.329000 UTC - 3252[59b96c0]: 6421000:mail.artengine.ca:A:ProcessCurrentURL: entering
2010-01-12 20:03:12.329000 UTC - 3252[59b96c0]: 6421000:mail.artengine.ca:A:ProcessCurrentURL:imap://mlecha@mail.artengine.ca:143/folderstatus%3E/Sent:  = currentUrl
2010-01-12 20:03:12.391000 UTC - 3252[59b96c0]: 6421000:mail.artengine.ca:A:SendData: 6 STATUS "Sent" (UIDNEXT MESSAGES UNSEEN RECENT)

2010-01-12 20:03:25.891000 UTC - 0[1826140]: SMTP Connecting to: mail.magma.ca
2010-01-12 20:03:26.063000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.063000 UTC - 0[1826140]: SMTP Response: 220 mail.primus.ca mail-02.primus.ca ESMTP Daemon - Outbound2
2010-01-12 20:03:26.063000 UTC - 0[1826140]: SMTP entering state: 14
2010-01-12 20:03:26.063000 UTC - 0[1826140]: SMTP Send: EHLO [192.168.1.101]

2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP Response: 250-mail-02.primus.ca Hello [192.168.1.101] [216.129.216.15]
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP Response: 250-SIZE 104857600
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP Response: 250-PIPELINING
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP Response: 250-AUTH PLAIN LOGIN
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP Response: 250-STARTTLS
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP Response: 250 HELP
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 4
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 21
2010-01-12 20:03:26.109000 UTC - 0[1826140]: SMTP entering state: 16
2010-01-12 20:03:26.125000 UTC - 0[1826140]: Logging suppressed for this command (it probably contained authentication information)
2010-01-12 20:03:26.203000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.203000 UTC - 0[1826140]: SMTP Response: 235 Authentication succeeded
2010-01-12 20:03:26.203000 UTC - 0[1826140]: SMTP entering state: 18
2010-01-12 20:03:26.203000 UTC - 0[1826140]: SMTP entering state: 3
2010-01-12 20:03:26.203000 UTC - 0[1826140]: SMTP Send: MAIL FROM:<mlecha@artengine.ca> SIZE=444

2010-01-12 20:03:26.250000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.250000 UTC - 0[1826140]: SMTP Response: 250 OK
2010-01-12 20:03:26.250000 UTC - 0[1826140]: SMTP entering state: 5
2010-01-12 20:03:26.250000 UTC - 0[1826140]: SMTP Send: RCPT TO:<mlechasseur@culturalhrc.ca>

2010-01-12 20:03:26.484000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.484000 UTC - 0[1826140]: SMTP Response: 250 Accepted
2010-01-12 20:03:26.484000 UTC - 0[1826140]: SMTP entering state: 6
2010-01-12 20:03:26.484000 UTC - 0[1826140]: SMTP Send: DATA

2010-01-12 20:03:26.547000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.547000 UTC - 0[1826140]: SMTP Response: 354 Enter message, ending with "." on a line by itself
2010-01-12 20:03:26.547000 UTC - 0[1826140]: SMTP entering state: 7
2010-01-12 20:03:26.547000 UTC - 0[1826140]: SMTP entering state: 8
2010-01-12 20:03:26.547000 UTC - 0[1826140]: SMTP Send: .

2010-01-12 20:03:26.859000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.859000 UTC - 0[1826140]: SMTP Response: 250 OK id=1Ng1ja-0005EK-1r
2010-01-12 20:03:26.859000 UTC - 0[1826140]: SMTP entering state: 9
2010-01-12 20:03:26.859000 UTC - 0[1826140]: SMTP Send: QUIT

2010-01-12 20:03:26.859000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.906000 UTC - 0[1826140]: SMTP entering state: 0
2010-01-12 20:03:26.906000 UTC - 0[1826140]: SMTP Response: 221 mail-02.primus.ca closing connection
2010-01-12 20:03:26.906000 UTC - 0[1826140]: SMTP entering state: 10
2010-01-12 20:03:26.969000 UTC - 0[1826140]: 75a0400:mail.artengine.ca:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
2010-01-12 20:03:26.969000 UTC - 0[1826140]: SMTP entering state: 12
2010-01-12 20:03:26.984000 UTC - 1856[59bae80]: ImapThreadMainLoop entering [this=75a0400]
2010-01-12 20:03:26.984000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:ProcessCurrentURL: entering
2010-01-12 20:03:26.984000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:ProcessCurrentURL:imap://mlecha@mail.artengine.ca:143/appendmsgfromfile%3E/Sent:  = currentUrl
2010-01-12 20:03:27.109000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=162 needmore=0]
2010-01-12 20:03:27.109000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] paik.artengine.ca IMAP4rev1 2007b.404 at Fri, 12 Feb 2010 15:03:27 -0500 (EST)

2010-01-12 20:03:27.109000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:SendData: 1 STARTTLS

2010-01-12 20:03:27.172000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=25 needmore=0]
2010-01-12 20:03:27.172000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:CreateNewLineFromSocket: 1 OK STARTTLS completed

2010-01-12 20:03:27.172000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:SendData: 2 capability

2010-01-12 20:03:27.391000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=234 needmore=0]
2010-01-12 20:03:27.391000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ IDLE UIDPLUS NAMESPACE CHILDREN MAILBOX-REFERRALS BINARY UNSELECT ESEARCH WITHIN SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND SASL-IR LOGIN-REFERRALS AUTH=PLAIN AUTH=LOGIN

2010-01-12 20:03:27.391000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=27 needmore=0]
2010-01-12 20:03:27.391000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:CreateNewLineFromSocket: 2 OK CAPABILITY completed

2010-01-12 20:03:27.391000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:SendData: 3 authenticate plain

2010-01-12 20:03:27.453000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=4 needmore=0]
2010-01-12 20:03:27.453000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:CreateNewLineFromSocket: + 

2010-01-12 20:03:27.453000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2010-01-12 20:03:27.516000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=219 needmore=0]
2010-01-12 20:03:27.516000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:NA:CreateNewLineFromSocket: 3 OK [CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ IDLE UIDPLUS NAMESPACE CHILDREN MAILBOX-REFERRALS BINARY UNSELECT ESEARCH WITHIN SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND] User mlecha authenticated

2010-01-12 20:03:27.531000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:SendData: 4 append "Sent" (\Seen) {444+}

2010-01-12 20:03:27.531000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:SendData: Message-ID: <4B75B40D.10400@artengine.ca>

Date: Fri, 12 Feb 2010 15:03:25 -0500

From: Michael Lechasseur <mlecha@artengine.ca>

User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.7) Gecko/20100111 Thunderbird/3.0.1

MIME-Version: 1.0

To: mlechasseur@culturalhrc.ca

Subject: Will this get copied to my sent folder?

Content-Type: text/plain; charset=ISO-8859-1; format=flowed

2010-01-12 20:03:27.531000 UTC - 1856[59bae80]: Content-Transfer-Encoding: 7bit



I wonder?

2010-01-12 20:03:27.531000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:SendData: 

2010-01-12 20:03:42.859000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=88 needmore=0]
2010-01-12 20:03:42.859000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 300 seconds...

2010-01-12 20:03:57.921000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=88 needmore=0]
2010-01-12 20:03:57.921000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 285 seconds...

2010-01-12 20:04:10.592000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=28 needmore=0]
2010-01-12 20:04:10.592000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: * OK Timeout in 30 minutes

2010-01-12 20:04:10.592000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: DONE

2010-01-12 20:04:10.654000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=22 needmore=0]
2010-01-12 20:04:10.654000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 18 OK IDLE completed

2010-01-12 20:04:10.654000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:ProcessCurrentURL: entering
2010-01-12 20:04:10.654000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:ProcessCurrentURL:imap://mlecha@mail.artengine.ca:143/select%3E/INBOX:  = currentUrl
2010-01-12 20:04:10.654000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 19 noop

2010-01-12 20:04:10.732000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=22 needmore=0]
2010-01-12 20:04:10.732000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 19 OK NOOP completed

2010-01-12 20:04:10.732000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 20 UID fetch 208531:* (FLAGS)

2010-01-12 20:04:10.795000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=41 needmore=0]
2010-01-12 20:04:10.795000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: * 1095 FETCH (UID 208530 FLAGS (\Seen))

2010-01-12 20:04:10.795000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=27 needmore=0]
2010-01-12 20:04:10.795000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 20 OK UID FETCH completed

2010-01-12 20:04:10.811000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 21 IDLE

2010-01-12 20:04:10.873000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=20 needmore=0]
2010-01-12 20:04:10.873000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: + Waiting for DONE

2010-01-12 20:04:13.060000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=88 needmore=0]
2010-01-12 20:04:13.060000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 270 seconds...

2010-01-12 20:04:28.294000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=88 needmore=0]
2010-01-12 20:04:28.294000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 255 seconds...

2010-01-12 20:04:36.934000 UTC - 3252[59b96c0]: ReadNextLine [stream=5d2ab08 nb=64 needmore=0]
2010-01-12 20:04:36.934000 UTC - 3252[59b96c0]: 6421000:mail.artengine.ca:A:CreateNewLineFromSocket: * STATUS Sent (MESSAGES 12576 RECENT 0 UNSEEN 0 UIDNEXT 12710)

2010-01-12 20:04:36.934000 UTC - 3252[59b96c0]: ReadNextLine [stream=5d2ab08 nb=23 needmore=0]
2010-01-12 20:04:36.934000 UTC - 3252[59b96c0]: 6421000:mail.artengine.ca:A:CreateNewLineFromSocket: 6 OK STATUS completed

2010-01-12 20:04:36.934000 UTC - 0[1826140]: 187fc00:mail.artengine.ca:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
2010-01-12 20:04:36.934000 UTC - 4088[182aec0]: ImapThreadMainLoop entering [this=187fc00]
2010-01-12 20:04:36.934000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:ProcessCurrentURL: entering
2010-01-12 20:04:36.934000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:ProcessCurrentURL:imap://mlecha@mail.artengine.ca:143/select%3E/Sent:  = currentUrl
2010-01-12 20:04:49.199000 UTC - 1856[59bae80]: ReadNextLine [stream=742a528 nb=0 needmore=1]
2010-01-12 20:04:49.199000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
2010-01-12 20:04:49.199000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:TellThreadToDie: close socket connection
2010-01-12 20:04:49.199000 UTC - 1856[59bae80]: 75a0400:mail.artengine.ca:A:CreateNewLineFromSocket: (null)
2010-01-12 20:04:49.199000 UTC - 0[1826140]: creating protocol instance to retry queued url:imap://mlecha@mail.artengine.ca:143/appendmsgfromfile>/Sent
2010-01-12 20:04:49.199000 UTC - 1856[59bae80]: ImapThreadMainLoop leaving [this=75a0400]
2010-01-12 20:04:50.934000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=162 needmore=0]
2010-01-12 20:04:50.934000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] paik.artengine.ca IMAP4rev1 2007b.404 at Fri, 12 Feb 2010 15:04:47 -0500 (EST)

2010-01-12 20:04:50.934000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:SendData: 1 STARTTLS

2010-01-12 20:04:50.996000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=25 needmore=0]
2010-01-12 20:04:50.996000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:CreateNewLineFromSocket: 1 OK STARTTLS completed

2010-01-12 20:04:50.996000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:SendData: 2 capability

2010-01-12 20:04:51.199000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=234 needmore=0]
2010-01-12 20:04:51.199000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ IDLE UIDPLUS NAMESPACE CHILDREN MAILBOX-REFERRALS BINARY UNSELECT ESEARCH WITHIN SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND SASL-IR LOGIN-REFERRALS AUTH=PLAIN AUTH=LOGIN

2010-01-12 20:04:51.199000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=27 needmore=0]
2010-01-12 20:04:51.199000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:CreateNewLineFromSocket: 2 OK CAPABILITY completed

2010-01-12 20:04:51.199000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:SendData: 3 authenticate plain

2010-01-12 20:04:51.262000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=4 needmore=0]
2010-01-12 20:04:51.262000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:CreateNewLineFromSocket: + 

2010-01-12 20:04:51.262000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2010-01-12 20:04:51.371000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=219 needmore=0]
2010-01-12 20:04:51.371000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:NA:CreateNewLineFromSocket: 3 OK [CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ IDLE UIDPLUS NAMESPACE CHILDREN MAILBOX-REFERRALS BINARY UNSELECT ESEARCH WITHIN SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND] User mlecha authenticated

2010-01-12 20:04:51.371000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:SendData: 4 select "Sent"

2010-01-12 20:04:51.840000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=61 needmore=0]
2010-01-12 20:04:51.840000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox is open by another process, access is readonly

2010-01-12 20:05:07.167000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=88 needmore=0]
2010-01-12 20:05:07.167000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 300 seconds...

2010-01-12 20:05:10.870000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=28 needmore=0]
2010-01-12 20:05:10.870000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: * OK Timeout in 30 minutes

2010-01-12 20:05:10.886000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: DONE

2010-01-12 20:05:10.933000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=22 needmore=0]
2010-01-12 20:05:10.933000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 21 OK IDLE completed

2010-01-12 20:05:10.933000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:ProcessCurrentURL: entering
2010-01-12 20:05:10.933000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:ProcessCurrentURL:imap://mlecha@mail.artengine.ca:143/select%3E/INBOX:  = currentUrl
2010-01-12 20:05:10.948000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 22 noop

2010-01-12 20:05:11.011000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=22 needmore=0]
2010-01-12 20:05:11.011000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 22 OK NOOP completed

2010-01-12 20:05:11.011000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 23 UID fetch 208531:* (FLAGS)

2010-01-12 20:05:11.073000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=41 needmore=0]
2010-01-12 20:05:11.073000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: * 1095 FETCH (UID 208530 FLAGS (\Seen))

2010-01-12 20:05:11.073000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=27 needmore=0]
2010-01-12 20:05:11.073000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 23 OK UID FETCH completed

2010-01-12 20:05:11.089000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 24 IDLE

2010-01-12 20:05:11.152000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=20 needmore=0]
2010-01-12 20:05:11.152000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: + Waiting for DONE

2010-01-12 20:05:22.292000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=88 needmore=0]
2010-01-12 20:05:22.292000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 285 seconds...

2010-01-12 20:05:37.354000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=88 needmore=0]
2010-01-12 20:05:37.354000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 270 seconds...

2010-01-12 20:06:11.149000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=28 needmore=0]
2010-01-12 20:06:11.149000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: * OK Timeout in 30 minutes

2010-01-12 20:06:11.149000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: DONE

2010-01-12 20:06:11.227000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=22 needmore=0]
2010-01-12 20:06:11.227000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 24 OK IDLE completed

2010-01-12 20:06:11.227000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:ProcessCurrentURL: entering
2010-01-12 20:06:11.227000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:ProcessCurrentURL:imap://mlecha@mail.artengine.ca:143/select%3E/INBOX:  = currentUrl
2010-01-12 20:06:11.227000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 25 noop

2010-01-12 20:06:11.290000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=22 needmore=0]
2010-01-12 20:06:11.290000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 25 OK NOOP completed

2010-01-12 20:06:11.290000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 26 UID fetch 208531:* (FLAGS)

2010-01-12 20:06:11.352000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=41 needmore=0]
2010-01-12 20:06:11.352000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: * 1095 FETCH (UID 208530 FLAGS (\Seen))

2010-01-12 20:06:11.352000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=27 needmore=0]
2010-01-12 20:06:11.352000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: 26 OK UID FETCH completed

2010-01-12 20:06:11.368000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:SendData: 27 IDLE

2010-01-12 20:06:11.430000 UTC - 1968[4d36540]: ReadNextLine [stream=4c96888 nb=20 needmore=0]
2010-01-12 20:06:11.430000 UTC - 1968[4d36540]: 4f9ac00:mail.artengine.ca:S-INBOX:CreateNewLineFromSocket: + Waiting for DONE

2010-01-12 20:06:58.959000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=16 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * 12577 EXISTS

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=12 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * 1 RECENT

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=51 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * OK [UIDVALIDITY 1265135083] UID validity status

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=41 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * OK [UIDNEXT 12711] Predicted next UID

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=72 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * FLAGS ($Forwarded $MDNSent \Answered \Flagged \Deleted \Draft \Seen)

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=42 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * OK [PERMANENTFLAGS ()] Permanent flags

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=88 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 255 seconds...

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=35 needmore=0]
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:A:CreateNewLineFromSocket: 4 OK [READ-ONLY] SELECT completed

2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:ProcessSelectedStateURL: current folder read only
2010-01-12 20:06:58.975000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:SendData: 5 UID fetch 1:* (FLAGS)

2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=34 needmore=0]
2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:CreateNewLineFromSocket: * 1 FETCH (UID 63 FLAGS (\Seen))

2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=34 needmore=0]
2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:CreateNewLineFromSocket: * 2 FETCH (UID 64 FLAGS (\Seen))

2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=34 needmore=0]
2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:CreateNewLineFromSocket: * 3 FETCH (UID 65 FLAGS (\Seen))

2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=34 needmore=0]
2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:CreateNewLineFromSocket: * 4 FETCH (UID 66 FLAGS (\Seen))

2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=34 needmore=0]
2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: 187fc00:mail.artengine.ca:S-Sent:CreateNewLineFromSocket: * 5 FETCH (UID 67 FLAGS (\Seen))

2010-01-12 20:06:59.178000 UTC - 4088[182aec0]: ReadNextLine [stream=18122e8 nb=34 needmore=0]
(Reporter)

Comment 1

8 years ago
Created attachment 426721 [details]
SMTP and IMAP log with timestamp

Hope this helps. Trying to remove the log pasted into the main bug report...
Component: General → Networking: IMAP
Product: Thunderbird → MailNews Core
QA Contact: general → networking.imap
Whiteboard: [has protocol log]
Version: unspecified → 1.9.1 Branch
(Reporter)

Comment 2

8 years ago
This bug seems to be caused by having too large an IMAP sent folder. Under advice of another user, I copied the bulk of my sent folder to another IMAP folder, compacted my sent mail folder, and now mail I send is copied to the Sent folder without issue. But the bug should still be corrected, or at the very least better error notification to the end user made.

ORIGINAL
-rw-------  1 mlecha   503 395816431 2010-02-17 08:34 Sent

UPDATED
-rw-------  1 mlecha   503  40620973 2010-02-17 08:43 Sent
(In reply to comment #1)
> Hope this helps. Trying to remove the log pasted into the main bug report...

Impossible to remove pasted dat. Close as INVALID, open new bug, attach log to new bug, is better if too huge log was pasted, but probably no need of it, because this bug is readable.

Following is IMAP server response while Tb is uploading sent mail data.
> 2010-01-12 20:03:42.859000 UTC - * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 300 seconds...
> 2010-01-12 20:03:57.921000 UTC * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 285 seconds...
It's never Tb's bug.
As you say, I think "better error notification to the end user" is required.
It's enhancement request. Same as already requested ones?
xref
Bug 102030 - No "Copy to Sent folder failed" error, copy in Sent is hdr only - Out of Disk Space
bug 598104 - Local Sent folder allowed to grow past 4GB
etc
Summary: Sent mail error copying the message to the sent folder since upgrading to TB3.0 → Sent mail error copying the message to large sent folder since upgrading to TB3.0
Whiteboard: [has protocol log] → dupme [has protocol log]
wada, mlecha
one of these bugs?

- https://bugzilla.mozilla.org/buglist.cgi?type1-0-0=substring&list_id=2157390&short_desc=error%20messag&field0-0-0=short_desc&type0-0-1=substring&field0-0-1=component&type1-0-1=allwordssubstr&resolution=---&classification=Client%20Software&classification=Components&query_format=advanced&short_desc_type=substring&value0-0-1=imap&type0-0-0=anywordssubstr&value0-0-0=imap&field1-0-0=short_desc&product=MailNews%20Core&product=Thunderbird&field1-0-1=short_desc

...
> Bug 102030 - No "Copy to Sent folder failed" error, copy in Sent is hdr only
> - Out of Disk Space
> bug 598104 - Local Sent folder allowed to grow past 4GB
> etc
(In reply to Wayne Mery (:wsmwk) from comment #5)
> one of these bugs?

No.
This bug is;
  Server doesn't return required tagged rsponse to "append" yet.
  Untagged response(unsol resp if IDLE responce) only is returned from server.
  "100% on the progress bar" indicates "Tb already sent all mail data".
  Because no required tagged response(OK, NO, BAD), timeout occurs. 

> 2010-01-12 20:03:42.859000 UTC * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 300 seconds...
> 2010-01-12 20:03:57.921000 UTC * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 285 seconds...

Because NNN of "in NNN seconds..." is reduced, it looks "Server is executing Compress like operation on Sent folder". If so, this is not server's bug. If so, larger tcptimeout value of Tb may be a workaround, because it's merely "append process is taking long at server".

It's never Tb's bug.
However, if server returns tagged response of "NO" to tell "please retry append again after a while", other problem may occur because Tb has bug 693353.
For untagged "* NO Mailbox /home/members/mlecha/mail/Sent is locked, ..." response by the server.

http://tools.ietf.org/html/rfc3501#section-7.2
> 7.2. Server Responses - Server and Mailbox Status
> These responses are always untagged.  This is how server and mailbox
> status data are transmitted from the server to the client.  Many of
> these responses typically result from a command with the same name.

"Starting untagged response with command name" is not "MUST". So starting untagged response with 'NO' is never RFC violation.

Untagged response to APPEND command is not defined by RFC 3501, but it is not explicitly prohibited. So, the untagged response to APPEND is not apparent RFC violation.

I think Tb is better to show warning message in Activity Manager for such unexpected untagged(unsol) status response.
In this bug's case, if user can know about following message and about "remaining time is constantly decreasing",
> 2010-01-12 20:03:57.921000 UTC * NO Mailbox /home/members/mlecha/mail/Sent is locked, will override in 285 seconds...
user can increase tcptimeout value.
Severity: normal → enhancement
Status: UNCONFIRMED → NEW
Ever confirmed: true
OS: Windows XP → All
Hardware: x86 → All
Summary: Sent mail error copying the message to large sent folder since upgrading to TB3.0 → Sent mail error copying the message to large sent folder since upgrading to TB3.0 (Warning message at Activity Manager is required for unexpected/undefined untagged/unsolicit response from server to IMAP commands)
Whiteboard: dupme [has protocol log] → [has protocol log]
Version: 1.9.1 Branch → Trunk
See Also: → bug 718384
You need to log in before you can comment on or make changes to this bug.