Open Bug 693353 Opened 13 years ago Updated 1 year ago

Message disappears from Inbox after unsuccessful detach operation (Even though APPEND is rejected by NO response, Tb sends mail data to server and is rejected by BAD, and even after NO/BAD, Tb goes ahead to following "UID xx STORE Flags \Deleted" step)

Categories

(MailNews Core :: Networking: IMAP, defect)

x86
All
defect
Not set
critical

Tracking

(Not tracked)

People

(Reporter: digixmax, Unassigned)

References

Details

(Keywords: dataloss)

Attachments

(3 files)

User Agent: Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1
Build ID: 20110928134238

Steps to reproduce:

Tried to detach an attachment from a message still in (IMAP) Inbox.


Actual results:

The detachment operation is unsuccessful (due to Mail server not allowing changes to messages older than, say, 2-3 days), then message disappears from Inbox


Expected results:

The message should be left intact (rather than disappears) after unsuccessful detach operation.
(In reply to digixmax from comment #0)
> Steps to reproduce:
> Tried to detach an attachment from a message still in (IMAP) Inbox.
> 
> Actual results:
> The detachment operation is unsuccessful (due to Mail server not allowing
> changes to messages older than, say, 2-3 days), then message disappears from
> Inbox

Tb's detach/delete operation when IMAP is;
 1. append(upload) of new version of mail without data lines in
    detached/deleted MIME part(s) of mail, with modified headers in the part(s).
 2. uid xxx store Flags (\Deleted), for original mail.
Step 1 is ordinally never "modification of existent mail data" for IMAP server, if ordinal IMAP server. There is no way to replace data of existent mail in protocol named IMAP.
So, "The detachment operation is unsuccessful (due to Mail server not allowing changes to messages older than, say, 2-3 days)" can't occur if ordinal IMAP server, unless IMAP server refuses to accept mail of same Message-ID:, Subject:, From:/To:/CC: etc. with slightly altered mail data lines in part(s) upon the append request(upload request).

What phenomenon or IMAP level flow do you call by your "The detachment operation is unsuccessful (due to Mail server not allowing changes to messages older than, say, 2-3 days)"?
Your description of TB's detach/delete operation is consistent with the explanation I got from our Mail Server folks.  According to them the message is lost because TB still proceeds with step 2, rather than aborts it, even when step 1 fails.
Can you attach(not paste) IMAP log? (timestamp,imap:5)
> https://wiki.mozilla.org/MailNews:Logging
(In reply to digixmax from comment #4)
> Mail Server Log file extract for the failed Detach transaction

[1] Tb opens Inbox
> 20:31:04 yim TLOG xi=17 cm=7 select "INBOX"
> OPENED
> 20:31:04 yim TLOG xi=17 cm=8 getquotaroot "INBOX"
> 20:31:04 yim TLOG xi=17 cm=9 UID fetch 1:* (FLAGS)

[2] Tb deletes UID= 551330
> 20:31:05 yim TLOG xi=17 cm=10 uid store 551330 +Flags (\Seen \Deleted)
> FLAGGED
> 20:31:05 yim TLOG xi=17 cm=11 IDLE

[3] Check for new messages in Inbox. Highest UID=552948, because of fetch 552949:* (FLAGS)"
> 20:32:45 yim TLOG xi=17 cm=12 noop
> 20:32:45 yim TLOG xi=17 cm=13 getquotaroot "INBOX"
> 20:32:45 yim TLOG xi=17 cm=14 UID fetch 552949:* (FLAGS)
> 20:32:45 yim TLOG xi=17 cm=15 IDLE

[4] Tb changes UID=552916 to Read status
> 20:33:54 yim TLOG xi=17 cm=16 uid store 552916 +Flags (\Seen)
> FLAGGED
> 20:33:54 yim TLOG xi=17 cm=17 IDLE

[5] Tb starts upload of modified mail data
> 20:35:00 yim TLOG xi=17 cm=18 append "INBOX" (\Seen) "09-Oct-2011 22:38:33 -0400" {215610}

[6] It seems something wrong happens at server, even sent data is data of appended mail.
> 20:35:00 yim TLOG xi=17 cm=Received: from flpi407.ffdc.sbc.com ([150.234.117.113])
> UNKNOWN COMMAND
> 20:35:00 yim UNKN no=mailpo3 ms=unknown_command cm=from flpi407.ffdc.sbc.com ([150.234.117.113]) xi=17 ip=135.91.66.239

> (many next log pattern lines are snipped)
> (log pattern)
>   " TLOG xi=17 cm={message header line data of appended mail}"
>   => some "UNKN no=mailpo3 ...", some "TLOG xi=17 cm=??"
>      some "ms=unknown_command cm=..."

> 20:35:00 yim TLOG xi=17 cm=UEsDBBQABgAIAAAAIQA1PI0W7QEAAHgMAAATAAgCW0NvbnRlbnRfVHlwZXNdLnhtbCCiBAIooAAC
> (572 lines of "TLOG xi=17 cm=..." for base64 encoded data for pptx file is snipped)

> (many log lines of "TLOG xi=17 cm=..." and "PIPE no=mailpo3 ms=received_SIGPIPE ..." 

[7] Tb seems to execute login again after one second.
> 20:35:01 yim TLOG xi=17 cm=1 capability
> 20:35:01 yim TLOG xi=17 cm=2 authenticate plain
> 20:35:01 yim TLOG ms=sasl_trace co=+  xi=17 ip=135.91.66.239
> 20:35:01 yim TLOG ms=sasl_trace cm=AGhhbgBhbGljaWEt?? xi=17 ip=135.91.66.239
> 20:35:01 yim TLOG ms=sasl_trace co= xi=17 ip=135.91.66.239
> 20:35:01 yim TLOG xi=17 cm=3 ID ("name" "Thunderbird" "version" "7.0.1")
> 20:35:01 yim TLOG xi=17 cm=4 select "INBOX"
> 20:35:01 yim FOPN no=mailpo3 xi=17 to=[ml00000000003055@po100groupb]han@maillennium.att.com ui=2 zf=137 fo=inbox
> 20:35:01 yim TLOG xi=17 cm=5 getquotaroot "INBOX"
> 20:35:01 yim TLOG xi=17 cm=6 UID fetch 1:* (FLAGS)

[8] Tb deletes UID=551337
> 20:35:01 yim TLOG xi=17 cm=7 uid store 551337 +Flags (\Seen \Deleted)
> 20:35:01 yim TLOG xi=17 cm=8 IDLE

[9] Next new mail check. 
    Because "fetch 552949:* (FLAGS)", Tb doesn't know UID of appended mail yet.
> 20:35:31 yim TLOG xi=17 cm=9 noop
> 20:35:31 yim TLOG xi=17 cm=10 getquotaroot "INBOX"
> 20:35:31 yim TLOG xi=17 cm=11 UID fetch 552949:* (FLAGS)
> 20:35:31 yim TLOG xi=17 cm=12 IDLE
> 20:36:35 yim TLOG xi=17 cm=13 uid store 552948 +Flags (\Seen)
> 20:36:35 yim TLOG xi=17 cm=14 IDLE

It looks "detach or delete operation on UID=551337".
Does your server return OK or ERR or BAD to append command?
Or silently kills connection?
Can you attach Tb side IMAP log with timestamp too?

At step [2], delete of UID=551330 is seen during IDLE interval. Do you enable automatic purge of mail by Retention Policy, by option to delete Read mail automatically, and so on?

Does your problem occur even on small mail? (detach/delete of small text/plain mail with an attachment of one line text/plain file)
Can you see your problem with "max cached connections=1"?
(Server Settings/Advanced of Tb, Disable "IDLE command use" too, for ease of problem analysis.)
For ease of problem analysis, show "Order Received" column to know UID of detached/deleted mail and newly uploaded mail. The column value of Tb is UID of mail when IMAP folder.
digixmax, can you reply please?
Severity: normal → major
Whiteboard: [closeme 2012-01-21]
I could see "uid store xx Flag (\Deleted)" by Tb 9 after connection error while moving a mail in IMAP offline-use=off folder to local mail folder by Drag&Drop, during test for bug 522675.
Similar "uid store xx Flag (\Deleted)" perhaps happens when "append of mail data for detach/delete"(similar to moving of mail in IMAP folder to other IMAP server's mail folder).

Setting dependency to bug 522675 for ease of problem analysis.
Depends on: 522675
Sorry Wayne, but it would virtually impossible for me to get new or more server-side diagnostic info/logs (as folks who can do this have other work as their real assignments :-) ).

If there is Tb side diagnostic info/log I can gather, I would be happy to try reproducing the errors and capture the info/log with how-to pointers from you/WADA.
I just experienced another type of message-loss problem: declassifying as "Junk" a message in the Junk folder caused that message to disappear rather than get moved to the Inbox.
Tb side diagnostic info/log you can gather: See bug 402793 comment #28, please.
This is the TB-side log file for a failed Detach transaction.

At TB start-up, the Inbox contained a single message with attachment.  The message's attachment was detached (and was successfully saved to the user-designated location), then the message irrecoverably disappeared from Inbox.
The Junk box message problem I identified in my Comment #11 appear to pertain only to those Junk box messages that contain some attachment(s). Thus the common thread between this problem and the original problem is that the affected messages in both cases all contain attachment(s); the difference is in this case the trigger is a Declassifying of the message's "Junk" status and not a Detach operation on the message's Attachments.
(In reply to digixmax from comment #13)
> Thunderbird log file for a failed Detach transaction

(1) Tb tries APPEND at Inbox for detach'ed mail
(2) Server rejects APPEND by NO, because too old mail
(3) Even though NO response, Tb sends mail data, then server returns BAD
(4) Tb sends LOGOUT, close socket 
(5) Tb opens new connection, SELECT Inbox, and stores \Deleted flag(UID=588694) 
It looks problem like "NO response to APPEND command is not processed well or is ignored".

"Declassifying of the message's Junk status" currently forces "Move unmarked mail from Junk to Inbox", and Tb executes UID COPY(to Inbox) & UID STORE Flags \Deleted at Junk. If server rejects UID COPY by NO response because of "too old mail", same thing may occur.

Recovery operation:
  At Server Settings, set IMAP delete model = Just mark it as deleted,
  Undelete mail, to which \Deleted is wrongly stored, which is shown with
  strike-thru line at thread pane.

(At first socket, 4488[31f7680]: 583f800:, call Socket-1, session #1 starts)
> 2012-01-16 14:49:45.953000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:NA:SendData: 2 authenticate plain
> 2012-01-16 14:49:46.047000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:NA:CreateNewLineFromSocket: 2 OK LOGIN session #1
(At Socket-1/session #1, APPEND to Inbox is executed)
> 2012-01-16 14:49:46.500000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:SendData: 8 UID fetch 1:* (FLAGS)
> 2012-01-16 14:49:46.500000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: * 1 FETCH (UID 588694 FLAGS (\Seen))
> 2012-01-16 14:49:46.500000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: 8 OK UID fetch completed
> 2012-01-16 14:50:06.755000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:ProcessCurrentURL: entering
> 2012-01-16 14:50:06.755000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:ProcessCurrentURL:imap://han@proxy.maillennium.att.com:3143/appendmsgfromfile%3E/INBOX:  = currentUrl
> 2012-01-16 14:50:06.771000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:SendData: 10 append "INBOX" (\Seen) "13-Jan-2012 12:31:50 -0500" {6638}
(However, server rejects it by NO response, because too old mail for server)
( 86400 seconds = 24 hours = 1 day )
> 2012-01-16 14:50:06.771000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: 10 NO APPEND attempt to set internal date back more than 86400 seconds
(Even though NO to APPEND, Tb sends mail data)
> 2012-01-16 14:50:06.771000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:SendData: Received: from alpd052.aldc.att.com ([130.8.42.31])
          by maillennium.att.com (mailgw1) with ESMTP
          id <20120113173014gw100e1il0e>; Fri, 13 Jan 2012 17:30:14 +0000
(snip)
Message-ID: <4F106A86.7040000@maillennium.att.com>
Date: Fri, 13 Jan 2012 12:31:50 -0500
(snip)
> 2012-01-16 14:50:06.771000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:SendData: 
(So, server reject it by BAD response)
> 2012-01-16 14:50:06.786000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: Received: BAD Try 'HELP' - unrecognized
(Tb detects something wrong by BAD, then sends LOGOUT, and close Socket-1. session #1 is closed)
> 2012-01-16 14:50:07.083000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:NA:SendData: 11 logout
> 2012-01-16 14:50:07.083000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:NA:CreateNewLineFromSocket: * BAD Try 'HELP' - unrecognized
> 2012-01-16 14:50:07.083000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:NA:CreateNewLineFromSocket: * ID ("name" "maillennium" "version" "V05.40c++" "os" "os_solaris_bsd" "vendor" "AT&T Labs")
> 2012-01-16 14:50:07.083000 UTC - 4488[31f7680]: 583f800:proxy.maillennium.att.com:NA:TellThreadToDie: close socket connection
> 2012-01-16 14:50:07.083000 UTC - 4488[31f7680]: ImapThreadMainLoop leaving [this=583f800]
(At second socket, 5372[31f8440]: 3fcf800:, call Socket-2, session #1 starts again)
> 2012-01-16 14:50:07.083000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:NA:SendData: 2 authenticate plain
> 2012-01-16 14:50:07.099000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:NA:CreateNewLineFromSocket: 2 OK LOGIN session #1
(At Socket-2/session #1, Tb select Inbox and store \Deleted flag to UID=588694)
> 2012-01-16 14:50:07.099000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:SendData: 6 UID fetch 1:* (FLAGS)
> 2012-01-16 14:50:07.130000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: * 1 FETCH (UID 588694 FLAGS (\Seen))
> 2012-01-16 14:50:07.130000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: 6 OK UID fetch completed
> 2012-01-16 14:50:07.130000 UTC - 0[f0f140]: queuing url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.130000 UTC - 0[f0f140]: considering playing queued url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.130000 UTC - 0[f0f140]: creating protocol instance to play queued url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.130000 UTC - 0[f0f140]: failed creating protocol instance to play queued url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.193000 UTC - 0[f0f140]: considering playing queued url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.193000 UTC - 0[f0f140]: creating protocol instance to play queued url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.193000 UTC - 0[f0f140]: playing queued url:imap://han@proxy.maillennium.att.com:3143/addmsgflags>UID>/INBOX>588694>9
> 2012-01-16 14:50:07.193000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:ProcessCurrentURL: entering
> 2012-01-16 14:50:07.193000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:ProcessCurrentURL:imap://han@proxy.maillennium.att.com:3143/addmsgflags%3EUID%3E/INBOX%3E588694%3E9:  = currentUrl
> 2012-01-16 14:50:07.193000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:SendData: 7 uid store 588694 +Flags (\Seen \Deleted)
> 2012-01-16 14:50:07.224000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: * 1 FETCH (FLAGS (\Deleted \Seen) UID 588694)
> 2012-01-16 14:50:07.224000 UTC - 5372[31f8440]: 3fcf800:proxy.maillennium.att.com:S-INBOX:CreateNewLineFromSocket: 7 OK UID store completed
Confirming per IMAP log.
Status: UNCONFIRMED → NEW
Component: General → Networking: IMAP
Ever confirmed: true
Keywords: dataloss
OS: Windows XP → All
Product: Thunderbird → MailNews Core
QA Contact: general → networking.imap
Summary: Message disappears from Inbox after unsuccessful detach operation → Message disappears from Inbox after unsuccessful detach operation (Even though APPEND is rejected by NO response, Tb sends mail data to server and is rejected by BAD, and even after NO/BAD, Tb goes ahead to following "UID xx STORE Flags \Deleted" step)
> :S-INBOX:SendData: 10 append "INBOX" (\Seen) "13-Jan-2012 12:31:50 -0500" {6638}
> :S-INBOX:CreateNewLineFromSocket: 10 NO APPEND attempt to set internal date back more than 86400 seconds
> ( 86400 seconds = 24 hours = 1 day )

If your server rejects "UID xx COPY Inbox" at other than Inbox if old mail(before 1 day or more) too, your server rejects any of next.
- Copy old mail to Inbox from other folder of same IMAP account 
- Move old mail to Inbox from other folder of same IMAP account
  (Mark as Non-Junk currently forces "Move of the mail from Junk to Inbox")
Is it right?
Yes, Re-marking a message in Junk box as "not Junk" would normally move the message to Inbox.
For NO to APPEND with date/time string.
> 10 append "INBOX" (\Seen) "13-Jan-2012 12:31:50 -0500"
> 10 NO APPEND attempt to set internal date back more than 86400 seconds

(A) Because of SHOULD and not MUST, "NO" response due to old date/time is never RFC violation by server.

(B) "13-Jan-2012 12:31:50 -0500" is perhaps come from Date: header of mail.
> Date: Fri, 13 Jan 2012 12:31:50 -0500
Is append request with "internal date of mail's Date:" mandatory?
What's wrong with no data/time parameter? (current date is set as internal date)

http://tools.ietf.org/html/rfc3501#section-6.3.11
> 6.3.11. APPEND Command
>    Arguments:  mailbox name
>                OPTIONAL flag parenthesized list
>                OPTIONAL date/time string
>                message literal
>(snip) 
>       If a date-time is specified, the internal date SHOULD be set in
>       the resulting message; otherwise, the internal date of the
>       resulting message is set to the current date and time by default.
Whiteboard: [closeme 2012-01-21]
I want to amend my comment #14: I just had two incidents of re-marked Junk box message disappearing in which the lost messages do not contain any attachment nor are the messages over a day old (thereby would be rejected by the IMAP mail server).
Two messages in Junk box, one old and one new, were selected successfully and re-marked as "not Junk", i.e., they got moved into the Inbox.  These same two messages were next re-marked as "Junk": they then disappeared instead of getting moved (back) into Junk box.
FYI. I've opened bug 720919 for issue of comment #19.
(In reply to digixmax from comment #21)
> Thunderbird log file for a failed Junk Re-Marking transaction

(A) UID is not always returned to "uid copy". It looks to depend on Mbox or existent mail.
(A-1) Your server supports UIDPLUS.
> * CAPABILITY IMAP4rev1 AUTH=ANONYMOUS AUTH=CRAM-MD5 AUTH=LOGIN AUTH=NTLM
>   AUTH=PLAIN ID IDLE QUOTA VND.ATT.MIGRATE STARTTLS UIDPLUS XMEXT
(A-2) uid copy to Inbox returns UID. 
> At Junk
> 15 uid copy 589570 "INBOX"
> 15 OK [COPYUID 2 589570 589581] UID COPY complete
(A-3) uid copy to Junk doesn't return UID. 
> At INBOX
> 26 uid copy 589582 "Junk"
> 26 OK UID COPY complete

(B) Your server looks to do nothing for "uid copy from other Mbox" if same mail already exists in copy destination Mbox.
(B-1) At Junk, Mark As Non-Junk, store \Deleted after copy to INBOX
> At Junk
> 16 uid store 589570 +FLAGS (\Deleted \Seen)
> * 7 FETCH (FLAGS (\Deleted \Recent \Seen) UID 589570)
> 16 OK UID store completed
> 25 uid store 576300 +FLAGS (\Deleted \Seen)
> * 2 FETCH (FLAGS (\Answered \Deleted \Seen) UID 576300)
> 25 OK UID store completed
(B-2) At INBOX, Mark As Junk again, copy to Junk, and store \Deleted at INBOX.
      UID is not returned even though UIDPLUS is returned in CAPABILITY response.
> At INBOX
> 26 uid copy 589582 "Junk"
> 26 OK UID COPY complete
> 36 uid copy 589581 "Junk"
> 36 OK UID COPY complete
(B-3) At Junk, Tb request fetch of newest mails in Junk.
      Because highest UID in Junk just before (B-2) was UID=589570,
      Tb requests UID fetch 589571:* (FLAGS), but nothing is returned.
> 28 UID fetch 589571:* (FLAGS)
> * 7 FETCH (UID 589570 FLAGS (\Deleted \Recent \Seen))
> 28 OK UID fetch completed
(B-4) Because OK is returned to copy from INBOX to Junk at (B-2), (B-3) means;
(1) By copy to Junk at (B-2), UID=589571(seq=8), UID=589572(seq=9) is crated.
(2) Between (B-2) and (B-3), UID=589571(seq=8), UID=589572(seq=9) is deleted
    and purged by other IMAP client or IMAP server.
(3) Because "UID 589570 FLAGS (\Deleted \Recent \Seen)" was returned, 
    your server didn't do "Undelete" operation when same mail is copied from
    other Mbox.

Because your IMAP server doesn't return data for copied back mail in Junk even though your server returned OK to uid copy(but without UID even though UIDPLUS enabled), Tb can do nothing.
"OK to uid copy but without UID even though UIDPLUS enabled" of your server may be a phenomenon of "rejection due to too old mail date" in "uid copy".

Above repeated "Mark As Junk, Mark as Non-Junk" is same as repeated "Move a mail from Inbox to Junk, move back the mail from Junk to Inbox, Move back the mail from Inbox to Junk, Move back the mail from Junk to Inbox, ...".
No problem if other mailer when such operation?

Workaround is "Just mark it as deleted" with showing "order Received" column(UID). Even if your servers behaviour is confusing, and even if Tb has bug in "NO to append" processing, deleted mail is shown with strike-thru line at threadd pane of Tb. So, worst "data loss" is avoided.
(bleh - dataloss is ALWAYS critical)
Severity: major → critical
See Also: → 538375
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: