892424 - Incomplete messages when copying then moving with a filter (When "Copy to Local folder, Move to IMAP folder" is executed on multiple mails, "uid MOVE(copy+store \Deleted) uid1:uidN IMAP" is issued just after "uid fetch uid1 body.peek[]" for first mail)

Status: NEW

(MailNews Core :: Networking: IMAP, defect)

Description

[123456isnotavailable]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0 (Beta/Release)
Build ID: 20130625173050

Steps to reproduce:

1. Create a filter that copies all incoming mail to a local folder, then moves it to a remote folder.
2. Switch to offline mode to prevent Thunderbird receiving each new message individually.
3. Send yourself several (four or five) emails.
4. Switch to online mode.
5. Check email.


Actual results:

Thunderbird appears to move the messages without waiting for the copying to finish, leaving incomplete versions of the messages in the local folder. This only occurs when several messages are received at once. Splitting the actions into two separate filters has no effect. I'm using 17.0.7 on GNU/Linux.


Expected results:

Thunderbird should have waited for copying to complete before performing any operation that would interfere.

Comment 1

[WADA:World Anti-bad-Duping Agency]

(In reply to 123456isnotavailable from comment #0)
> Actual results:
> This only occurs when several messages are received at once.

Does it mean "if only one new mail per a download, no problem occurs"?

> Thunderbird appears to move the messages without waiting for the copying to finish, (sip)

Are you sure?

> leaving incomplete versions of the messages in the local folder.

Which mail is shown as copied mail at Thread pane/message pane?
Which mail's data is written(appended) to local mail folder file?
(if folder name="FolderX", file of FolderX instead of FolderX.msf)
What is written in message filter log? 

What occurs with following?
(1) Filter rule, upon download, 
    "one action per a rule" for ease of analysis.
    If(xxx), Copy to local Folder-A
    If(xxx), Copy to IMAP  Folder-B   <= newly added for test
    If(xxx), Move to IMAP  Folder-C
(2) Send multiple mails which will hit "If(xxx)", as you did

If "Move" is executed before copy completion for "Copy to local Folder-A", "Copy to IMAP Folder-B" should also be interfered by "Move".

If MaildirStore, phenomenon of bug 856519 is observed by "Copy from IMAP to local".
1. mail-1 to mail-N is written to tmp/xxx-1 to tmp/xxx-N
2. only tmp/xxx-N(last mail) is moved to cur/xxx-N
3. because cur/xxx-1 to cur\xxx-(n-1) doesn't exist,
   empty directry of cur/xxx-1 to cur\xxx-(n-1) is generated.
Step-1 corresponds to "uid fetch xxx-N body[]" to file of FolderX.
Step-2 corresponds to flush, close, fish, like operation in "mail downloading".
Above phenomenon with MaildirStore indicates:
  Step-1 is executed for each mail.
  Step-2 is not executed for each mail.
  Step-2 is executed after end of download of all mails,
  then flush, close, fish, like operation is executed on last mail only.
"Fetch from IMAP server for Copy" part is not different from BerkleyStore, so similar issue to bug 856519 may occur on BerkleyStor case.

Comment 2

[WADA:World Anti-bad-Duping Agency]

FYI.
Bug 791966 is also for problem in "move IMAP to local" which is relevant to MaildirStore. Bug 791966 Comment #5 pointed out;
> FinishNewMessage is not being correctly called after more than one IMAP message is copied
"flush, close, fish, like operation" which I called is this "FinishNewMessage" in the comment.

Comment 3

[123456isnotavailable]

> Does it mean "if only one new mail per a download, no problem occurs"?

Correct.

> Which mail is shown as copied mail at Thread pane/message pane?
> Which mail's data is written(appended) to local mail folder file?
> (if folder name="FolderX", file of FolderX instead of FolderX.msf)

Every message shows up in the local directory, and every message is added to the "FolderX" file, but some of them are incomplete. Incomplete messages usually look like:
        From - Fri Jul 12 09:14:21 2013
        X-Mozilla-Status: 0001
        X-Mozilla-Status2: 00000000
        X-Mozilla-Keys:

There's no pattern I can discern to which emails are incomplete. Of the four messages I have been testing with, sometimes all of them will copy completely, sometimes just the last, sometimes just the first, sometimes two out of four, etc.

> What is written in message filter log?

The filter log is always normal, and for each message shows something like:
Applied filter "A" to message from John Doe <[e-mail]> - SubjX at 07/12/13 19:04:28 copied message id = CAPKM-8tbM21tJPRTj5i3XYbCx+Ny=eR7zS2pTdVxCE=[e-mail] to mailbox://nobody@Local%20Folders/TestFolder

Applied filter "B" to message from John Doe <[e-mail]> - SubjX at 07/12/13 19:04:28 copied message id = CAPKM-8tbM21tJPRTj5i3XYbCx+Ny=eR7zS2pTdVxCE=[e-mail] to imap://[e-mail]/IMAPTestFolder

Applied filter "C" to message from John Doe <[e-mail]> - SubjX at 07/12/13 19:04:28 moved message id = CAPKM-8tbM21tJPRTj5i3XYbCx+Ny=eR7zS2pTdVxCE=[e-mail] to imap://[e-mail]/[Gmail]/Bin


> What occurs with following?
> (1) Filter rule, upon download,
>     "one action per a rule" for ease of analysis.
>     If(xxx), Copy to local Folder-A
>     If(xxx), Copy to IMAP  Folder-B   <= newly added for test
>     If(xxx), Move to IMAP  Folder-C
> (2) Send multiple mails which will hit "If(xxx)", as you did
> If "Move" is executed before copy completion for "Copy to local Folder-A",
> "Copy to IMAP Folder-B" should also be interfered by "Move".

You're right. I get a complete copy in Folder-B, but not in Folder-A. However, if I turn off the final step, so that the filter list looks like:

If(xxx), Copy to local Folder-A
If(xxx), Copy to IMAP  Folder-B

The problem does not occur.

> If MaildirStore, phenomenon of bug 856519 is observed by "Copy from IMAP to
> local".
> 1. mail-1 to mail-N is written to tmp/xxx-1 to tmp/xxx-N
> 2. only tmp/xxx-N(last mail) is moved to cur/xxx-N
> 3. because cur/xxx-1 to cur\xxx-(n-1) doesn't exist,
>    empty directry of cur/xxx-1 to cur\xxx-(n-1) is generated.
> Step-1 corresponds to "uid fetch xxx-N body[]" to file of FolderX.
> Step-2 corresponds to flush, close, fish, like operation in "mail
> downloading".
> Above phenomenon with MaildirStore indicates:
>   Step-1 is executed for each mail.
>   Step-2 is not executed for each mail.
>   Step-2 is executed after end of download of all mails,
>   then flush, close, fish, like operation is executed on last mail only.
> "Fetch from IMAP server for Copy" part is not different from BerkleyStore,
> so similar issue to bug 856519 may occur on BerkleyStor case.

As far as I can tell, I am not experiencing this bug. Copying from IMAP to local works. Moving from IMAP to local works. Copying and moving multiple messages from IMAP to local works. Only copying then moving in a filter (or two filters) causes the issue.

Comment 4

[WADA:World Anti-bad-Duping Agency]

(In reply to 123456isnotavailable from comment #3)
> However, if I turn off the final step, so that the filter list looks like:
> If(xxx), Copy to local Folder-A
> If(xxx), Copy to IMAP  Folder-B
> The problem does not occur.

It sounds interfere by "Move" step.

By filter, following occurs:
(1) Inbox: copy to local Folder-A :
       uid fetch a,b,c body.peek[], or uid fetch for each mail
(2) Inbox: copy to IMAP Folder-B :
       uid copy a,b,c Folder-B, or uid copy for each mail
(3) Inbox: move to IMAP Folder-C
       uid copy a,b,c Folder-C, uid store a,b,c \Deleted
       or uid copy /store flag \Deleted for each mail.
    This may be by "move" command, if "MOVE" extetion is supported.
       uid move a,b,c Folder-C, or uid move for each mail.
And, following may occur at same time.
(4) If Inbox is Offline-Use=On folder, at Inbox,
    "uid fetch a,b,c body.peek[]" may be issued before (1).
(5) If new mail alert by Biff is enabled(defalt=enabled),
    "uid fetch a,b,c body.peek[]<0.2048>" may be issued for previewText
    during executing (1) to (4).

Step (2) and step (3) are requested serially and are surely execued serially at server, because OK response at step (2) is returned after completion of "uid copy" at server. So, even if "move step" is executed by Tb before completion of "copy step", "copy to IMAP folder-B" is not interfered by "move".

Can you check IMAP flow?

Get IMAP log, with disabling all IMAP server access except required server access for test, and check log by Text Editor.
See bug 402793 comment #28 for getting IMAP log.
Get with following parameter first, please.
> timestamp,imap:5,msgbiff:5,ImapAutoSync:5,MsgCopyService:5,IMAPOFFLINE:5,MsgPurge:5,MSGDB:5

Comment 5

[WADA:World Anti-bad-Duping Agency]

Attachment: IMAP log with Yahoo! IMAP for Copy to Local-A, Copy to IMAP-B, Move to IMAP-C, by message filter

Quick check result with Yahoo! IMAP(supports UIDPLUS).

Test procedure:
Same as yours, but with minimum configuration.
(0) auto-sync=disabled.
    New mail check is disabled.
    IDLE command use is disabled.
    IMAP delete model : "Just mark it as deleted"
       in order to see "mail marked as \Deleted" mails.
(1) Select IMAP accunt at Folder Pane, Terminate Tb.
(2) Send 3 mails which will be filtered by;
    - If subject begins with local-copy, Copy to local Local-A
    - If subject begins with local-copy, Copy to IMAP  IMAP-B
    - If subject begins with local-copy, Copy to IMAP  IMAP-B
    In my　test, some other new mails which will be kept in Inbox are sent too.
(3) Restart Tb => Account is selected. Inbox is not opened.
    Click Inbox => Inbox is opened, and new mails are fetched.
    UID of filtered mails : 
      mail-1 : UID=875, mail-2 : UID=877, mail-3 : UID=879

Following is log at connection for S-INBOX.
 11 UID fetch 875 (UID RFC822.SIZE BODY.PEEK[]) <= For Copy to Local-A, mail-1
(12 is not seen. Eaten by someone?)
 13 uid copy 875:879 "IMAP-C"                   <= For Move to IMAP-C, 3 mails
 14 uid store 875:879 +FLAGS (\Deleted \Seen)
(15 is not seen. Eaten by someone?)
 16 uid copy 877 "IMAP-B"                       <= For Copy to IMAP-B, mail-2
 17 UID fetch 877 (UID RFC822.SIZE BODY.PEEK[]) <= For Copy to Local-A, mail-2
(18 is not seen. Eaten by someone?)
 19 uid copy 879 "IMAP-B"                       <= For Copy to IMAP-B, mail-3
 20 UID fetch 879 (UID RFC822.SIZE BODY.PEEK[]) <= For Copy to Local-A, mail-3

(A) As you say, "Move" looks executed without waiting for "Copy" completion.
(B) Because "moved mail in Inbox" is merely "marked as \Deleted" mail in IMAP,
    even when "Copy to Local-A" and "Copy to IMAP-B" is executed after
    "Move to IMAP-C",  
(B-1) "uid copy xxx IMAP-B" is normally executed, although \Deleted flag is
      copied too.
(B-2) "uid fetch xxx body.peek[]" is normally executed, and mail data is
      normally saved in Local-A.
(C) Log for "Copy mail-1(UID=875) to IMAP-B" is not seen in log.
    However, all　3 mails are normally returned from server by "Repair Folder".
    This indicates "uid copy command was issued but IMAP log is not
    written due to some errors while executing Copy to IMAP-B".

If IMAP delete model of "Move to trash" or "Remove it immediately", msgDBHdr for "mail marked as \Deleted" is removed immdiately when Tb detects "\Deleted flag is stored in a mail".
If "detection of \Deleted flag" occurs just before issuing "uid fetch xxx body.peek[]" for "Copy to Local-A", "Copy to Local-A" step may fail at mid of downloading mail data.

If "MOVE" extention is supported, Tb may use "move" command. If "uid x:y move IMAP-C" is used, moved mails are perhaps expunged immediately in INBOX at server. This is applicable to "mail marked ad \Deleted" in Gmail IMAP with auto-expunge=On.

Do you see your problem with "Just mark it as deleted"?
Does your server support "MOVE" extension?

Comment 6

[123456isnotavailable]

Yes, Gmail supports the move extension, and no, the problem does not arise with "Just mark it as deleted".

As you suggest, the log shows Thunderbird fetching the first message (3982) successfully, then immediately moving all four (3892,3893,3894,3895).

imap.gmail.com:S-INBOX:SendData: 31 uid move 3982:3985 "[Gmail]/Bin"
imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 31 OK [COPYUID 5 3982:3985 4582:4585] (Success)

Afer that, all attempts to copy obviously result in no data.

imap.gmail.com:S-INBOX:SendData: 32 UID fetch 3983 (UID RFC822.SIZE BODY.PEEK[])
imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 32 OK Success

Comment 7

[WADA:World Anti-bad-Duping Agency]

> imap.gmail.com:S-INBOX:SendData: 31 uid move 3982:3985 "[Gmail]/Bin"
> imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
> imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
> imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
> imap.gmail.com:S-INBOX:CreateNewLineFromSocket: * 5 EXPUNGE
> imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 31 OK [COPYUID 5 3982:3985 4582:4585] (Success)
> Afer that, all attempts to copy obviously result in no data.
> imap.gmail.com:S-INBOX:SendData: 32 UID fetch 3983 (UID RFC822.SIZE BODY.PEEK[])
> imap.gmail.com:S-INBOX:CreateNewLineFromSocket: 32 OK Success

Oh, Gmail IMMAP case, who supports "Move", and default of Auto-expunge is On...
Gmail looks to do "expunge" operation by "move", but Gmail looks to still keep UID of the expunged mail after "move"...
(This is seen in other tests o mail \Deleted flag is stored. It looks design/Implementaion of auto-expunge=On) 

Do you see difference among followings with Gmail IMAP?
("MOVE" extesion always works)
- Non "Just mark it as deleted", auto-expunge=On   (perhaps, comment #0)
- Just mark it as deleted,       auto-expunge=On   (perhaps, comment #6)
- Just mark it as deleted,       auto-expunge=Off  <= new case

Comment 8

[123456isnotavailable]

Actually, auto-expunge has been switched off until now, but there are three sub-options: Archive the message (default); Move the message to the Bin; Immediately delete the message forever. 

No matter what option is chosen, Thunderbird moves all messages partway through the process, resulting in empty emails. If I change the final filter action to delete instead of move to bin, turn auto-expunge off, and set "Just mark it as deleted", I get complete copies of the messages in the local folder, but the remote copies don't actually delete, even after compacting, closing TB, etc.

Comment 9

[WADA:World Anti-bad-Duping Agency]

"Delete" of message filter has big problem of Bug 695671. Don't use "action=Delete", please.

Comment 10

[WADA:World Anti-bad-Duping Agency]

If before "Move" command support, auto-expunge=Off(and "Just mark it as deleted") might be workaround of this bug, but Gmail IMAP already　supports "Move" extension and Tb uses "move" command always for "Move" opertion when "Move" extension is supported.
If Gmail IMAP, best workaround of this bug is;
  Simply use already-available/easy-to-use "server side message filter".

Comment 11

[WADA:World Anti-bad-Duping Agency]

I checked IMAP log for "queuing url".
   queuing : onlinecopy>UID>/INBOX>875>/IMAP-B
   queuing : fetch>UID>/INBOX>875
   queuing : onlinemove>UID>/INBOX>875,877,879>/IMAP-C
     Without waiting for completion of all of "bulk copy to IMAP-B"
     and "bulk copy to Local-A", "bulk move to IMAP-C" is requested.
   10 uid copy 875 "IMAP-B"              <= Copy to IMAP-B,  mail-1
   queuing : onlinecopy>UID>/INBOX>877>/IMAP-B
   11 UID fetch 875 ( ... BODY.PEEK[])   <= Copy to Local-A, mail-1
   queuing : fetch>UID>/INBOX>877
   13 uid copy 875:879 "IMAP-C"          <= Move to IMAP-C, all mails
   14 uid store 875:879 +FLAGS (\Deleted \Seen) <= Move to IMAP-C 
   16 uid copy 877 "IMAP-B"              <= Copy to IMAP-B,  mail-2
   queuing : onlinecopy>UID>/INBOX>879>/IMAP-B
   17 UID fetch 877 ( ... BODY.PEEK[])   <= Copy to Local-A, mail-2
   queuing : fetch>UID>/INBOX>879
   19 uid copy 879 "IMAP-B"              <= Copy to IMAP-B,  mail-3
   20 UID fetch 879 ( ... BODY.PEEK[])   <= Copy to Local-A, mail-3

Main task looks to expect "bulk copy to IMAP-B" and "bulk copy to Local-A" is executed by single IMAP command. So, after invoking job for "bulk copy to IMAP-B" and job for "bulk copy to Local-A" , Main task immediately queues 'onlinemove>UID>/INBOX>875,877,879>/IMAP-C' request.
However, "bulk copy" splits it to multiple "uid copy/fetch", and queues "a uid copy/fetch for a mail", and after each "uid/copy" request is scheduled and executed, queues "a uid copy/fetch for next mail".

If "bulk copy" is executed by single IMAP command, by 'uid copy 875:879 "IMAP-B"' and 'uid fetch 875:879 ( ... BODY.PEEK[])', problem won't occur.

Fault in "Main task" side? Or fault in "bulk copy" side?
Affected by implementation changes in "bulk copy"?

Comment 12

[Seb]

UserAgent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 Thunderbird/52.6.0
Application Build ID 	2018012318594

As a simple user of Thunderbird for many years, up to version 56.6.0 (32 bits) I confirm this unexpected and detrimental body message loss when the described copy+move filter is applied on more than 1 message.

From a user perspective, when more several message pile up on an IMAP box, then opening Thunderbird and applying this filter (manually or automatically) results in immediate dataloss (the body of the messages) for all the targeted messages except the first one.
Best regards

Comment 13

[Seb]

Attachment: 6 screen copies showing the copy+move filter unexpected dataloss

The PDF describes in 6 screen copies what an user experiences when using a copy+move filter between Local Folders and and IMAP account.

Comment 15

[Etienne URBAH]

I confirm that this issue is systematic since the availability of maildir under Thunderbird :

I am using Thunderbird with a 'Copy to local, then Move to imap' filter since at least 2014.

Before maildir was available, I never observed data loss when several messages arrive at once in my imap Inbox.

But as soon maildir has been available, I switched to maildir.

Since then, up to current version 91.8.1 (64-bit), each time several messages arrive at once in my imap Inbox, all copied messages but the first one are empty.

Thank you in advance for correcting this issue.

Comment 16

[Etienne URBAH]

See Also: → 589092

Comment 17

[Etienne URBAH]

567119 and 1265697 are probably duplicates of this issue.

Comment 18

[Etienne URBAH]

Workaround :

• Once : For each mail account, for each filter :
  • Uncheck the 'Getting New Mail' checkbox,
  • Check the 'Manually Run' checkbox.
• From time to time, AFTER the Inbox of a mail account has finished downloading the mail contents, click on Menu 'Tools / Run Filters on Folder'.

Suggestion for code fixing :
Can the code trigger the 'Getting New Mail' filters of a mail account only AFTER its Inbox has finished downloading the mail contents ?
Thank you in advance for your work.

Comment 19

[Thilo [:ThiloteE]]

Problem is not unique to maildir. I tested with mbox and all filters were similarly failing.

Tests were done on Thunderbird Daily 107.0a1 (2022-09-28) (64-Bit) Linux Mint (Cinnamon) and a soft-fork of Thunderbird called Betterbird; Version 102.3.0-bb17 (64-bit) connecting via IMAP and by moving/copying 5 messages that fulfill filter conditions at the same time from local folder to Imap Inbox.

Summary of results:

Filter (A) fails with

1. Copy the matching message to Imap Sub-Folder
2. Move the matching message to Local Folder

--> All mails are moved to Local Folder and the body is fine, but only ONE (the first) mail was copied to imap Sub-Folder

Filter (B) fails with

1. Copy the matching message to Local Folder
2. Move the matching message to imap Sub-Folder

--> All mails are copied to Local Folder, but all mails lack body, except first mail. All mails are moved correctly to imap Sub-Folder.

Filter (C) fails with

1. Move the matching message to Local Folder
2. Copy the matching message to imap Sub-Folder

--> All mails are moved to Local Folder and the body is fine, but only ONE (the first) mail was copied to imap Sub-Folder

Comment 20

[Thilo [:ThiloteE]]

Missing body when moving from local to imap might potentially be fixed by Bug 1787963

Comment 21

[Thilo [:ThiloteE]]

I am currently on the softfork Betterbird 102.4.0

Solution?:

I found a fix using the "Move later" filter action provided by the Filtaquilla Addon

Following actions in the given order work without dataloss:

1. "Move later" the matching message to Imap Sub-Folder
2. Copy the matching message to Local Folder

To Do:

Test

• if this creates problems with additional other filter actions.
• what happens, if switching to offline mode, sending messages, running filters and then switching into online mode.

How to fix regular Thunderbird?

Maybe Thunderbirds code could be adapted to fall back to "move later" behaviour, if both the move and copy filter actions are set at the same time (such as described in comment 19)?

Comment 22

[Thilo [:ThiloteE]]

Since we are dealing with data loss, I would like to ask for a fix in Thunderbird core.

Additionally, once this is fixed, I think adding this case to unit tests to prevent future regressions would be nice.