410692 - Bulk Move and Delete operations result in duplicate messages when connection longer than 60s

Status: RESOLVED FIXED

(MailNews Core :: Networking: IMAP, defect)

Description

[David Mitchell]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.11) Gecko/20071204 Ubuntu/7.10 (gutsy) Firefox/2.0.0.11
Build Identifier: version 3.0a1pre (2008010304)

Attempting to move large numbers of email messages to a different folder results in massive multiplication of messages. This problem affects me most often with Delete operations, but those are implemented as moving messages to the Trash folder and both operations are affected.

Historically, I have had problems with Thunderbird not being able to delete large numbers of messages at once. Attempting to delete more than 100 or so at a time would result in a pop up window saying that the server had timed out and the operation would cancel. Annoying, but not critical. In the current version, it appears that the old behavior was improved by automatically retrying the 'failed' operation. Since a 'move' or 'delete' is really just a copy operation followed by an update of the flags the result is a huge number of messages in the destination folder. In my case, an attempt to delete 1,000 messages result in over 175,000 messages in my Trash folder.

Reproducible: Always

Steps to Reproduce:
1. Select over 200 or so messages
2. Press delete
3. Wait several minutes
4. Enjoy your rapidly filling Trash folder
Actual Results:  
I'm not sure how many times Thunderbird will attempt to retry the copy operation before giving up. Each attempt creates another copy of the message set in the destination folder. My initial attempt, which I left running overnight, created at least 175,000 messages in the Trash as a result of trying to delete about 1,000 messages.

I've done packet traces, and it goes something like this. I would attach the traces, but they contain my authentication information.

Time 0 sec.) 339 uid copy 172773:173052 "Trash"
Time 66 sec.) Thunderbird closes the socket, client sends FIN packet
Time 94 sec.) IMAP Server sends 339 OK [COPY UID blah blah] response to now closed socket.
Time 66) Thunderbird opens new connection to server, authenticates and reissues the COPY command
Time 131) Thunderbird closes the second socket
Time 220) IMAP Server sends reponse OK [COPYID blah blah] to second copy command

This cycles repeats over and over again. Each cycle results in yet another copy of the messages. Thunderbird does check the flags on all the messages when it opens each new session, but since it never issued the command to set the /delete flag it keeps copying the messages anew.

Yes, I know I appear to have a **** IMAP server which takes over 60 seconds to move only a couple hundred email messages. It's a commercial product. I don't run the IMAP server, so I don't know the exact version or hardware information. 

Expected Results:  
A single copy of the selected messages should end up in the destination folder.

Comment 1

[Magnus Melin [:mkmelin]]

Can you attach an imap protocol log?
<http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap>

Comment 2

[David Mitchell]

Attachment: Packet capture file attached in libpcap format.

Shows a sample attempt to delete a few hundred messages, with the looping 'copy trash' command send in several sessions.

Comment 3

[David Mitchell]

I've attached a packet capture. Our mail admin has also heard back from the IMAP vendor, and this issue has also been addressed by them in the latest version:

--quote--
This was addressed in CGPro 5.2c4 
<http://www.stalker.com/CommuniGatePro/History52.html>:

* IMAP: the Send 'Running' option is implemented.

It should reply with 'Running' from time to time while copying thus 
preventing Thunderbird from disconnecting.
--end quote--

Given that a fix is available, I'm not sure how urgent it is for Thunderbird to have some kind of workaround developed. On the other hand, the current behavior of retrying the 'copy' command repeatedly seems like it could cause problems in a lot of edge cases. Perhaps just rolling back to the old behavior of throwing up a dialog box is best?

Comment 4

[Wayne Mery (:wsmwk)]

~  
accidentally confirmed the bug

Comment 5

[Dennis Gesker]

I've had two users using Thunderbird 2.0.0.9 report the creation of a large number/multiple of duplicate of messages when moving a block of messages (> 4k messages) to a new folder. The issue was brought to my attention when the mail store drive consumed 110GB in one morning. We are running courier-imap 0.57.0.

Comment 6

[Dennis Gesker]

I should have mentioned in the post above that the users are on Windows XP. The server (Courier) is of course running Linux.

Comment 7

[Wayne Mery (:wsmwk)]

Magnus, did you have a look at the libpcap log? 
or do you need the mozilla log

dennis, can you attach an mozilla imap protocol log. instructions https://wiki.mozilla.org/MailNews:Logging

Comment 8

[Magnus Melin [:mkmelin]]

Comment on attachment 295422 [details]
Packet capture file attached in libpcap format.

At least an IMAP log should be easier to read.

Comment 9

[David :Bienvenu]

yes, an imap protocol log would be a lot easier to read. I see we're issuing the same copy, but I can't tell why from that log.

Comment 10

[Dennis Gesker]

Output log was to large to upload. I've compressed the file (7z) and email directly to [e-mail].

Method:

version 2.0.0.16 (20080708) on Vista SP1

Created two new folders using Thunderbird; __Temp1 and _Temp2
At the server seeded __Temp1 with 28966 messages
Launched Thunderbird from bat file:

set NSPR_LOG_MODULES=imap:1
set NSPR_LOG_FILE=c:\temp\imap.log
"C:\Program Files\Mozilla Thunderbird\thunderbird.exe"

Opened folder __Temp1 in Thunderbird and allowed message headers to populate.
Selected all messages in _Temp1 and tried to move to _Temp2

Stopped application when ~/Maildir/__Temp2/tmp reached a file count of 44169 messages (messages had begun to duplicate) but no messages had yet been written to ~/Maildir/__Temp2/cur

Output file was quite large at 76MB+. Compressed file (2116kb) but file was still too large to upload. Emailed compressed file ()directly to [e-mail].

Comment 11

[David :Bienvenu]

Can you send it to me, or give Wayne permission to forward it to me? I'll be the one looking at the code...

Comment 12

[Dennis Gesker]

David:

The logging output is on its way. 

Dennis

Comment 13

[David :Bienvenu]

We should only be retrying the copy once, according to my understanding of the code, but I may be missing something. It's probably safest not to retry copies of multiple messages at all, though we will run into failure cases where we've lost the connection to the server so it never saw the copy protocol at all.

We could try increasing the timeout for large copies but that just pushes the problem away...

Comment 14

[Wayne Mery (:wsmwk)]

xref bug 403603.
shall we dupe to that?

Comment 15

[Michael Baffoni]

I'm seeing this bug as well.  

As a potential way to fix, couldn't we break up bulk copies into smaller chunks?  So if we need to copy 1000 messages, how about we send a move/copy for 100 messages, then when complete the next 100, etc.?  If you _really_ want to get fancy, you could have the code start small - say 25 - then based on the time to return, ratchet up the number of messages moved/copied until the copy size is within a specific fraction of the timeout (say no more than 30% of timeout).

Comment 16

[Michael Baffoni]

I've just discovered a real NASTY side effect of this bug in Thunderbird3:  since TB3 now stores folder commands like move/delete on a per folder basis, and since it _does not remove those stored commands on failure_, any move/delete that times out is now _repeated_ every time you visit that folder.  It does not appear that hitting "stop" will remove the stored command from the folder's history, and acts like a failed attempt (however, I don't know if that is intentional or a separate bug).  The grand effect here however is that everytime I visit a specific folder, it attempts again to do a very large move, which fails, and never gets popped off the stack for that folder.  

Is there a work-around to clear the move command from the folder?  I now have a folder with many thousands of duplicate messages.  I now wish that the remove duplicate add-on worked in TB3.

Which occurs to me now why it exists; I'm sure that this bug pops up so often that someone had to come up with an add-on to clean up the mess it created (although not really attacking the source reason for it).

Comment 17

[David :Bienvenu]

rebuilding the index will remove the stored command.

Comment 18

[Michael Baffoni]

Thanks for that work around!!!!

Comment 19

[David Mitchell]

I find it interesting that while some folks work on this bug, there are other people (or the same ones?) committing code which makes the retry code more aggressive/persistent. Over time, the code for handling failures has gone from:

1) try once, and throw a dialog on timeout
2) keep trying indefinitely on timeout until the user quits
3) keep trying indefinitely, and save the command so you can retry after a restart.

Whomever is writing and committing that code needs to me made aware of the fact that the server may simply be busy processing their request. Their attempts at improvement are making Thunderbird a downright dangerous and destructive program for some users. Sorry if that sounds strong, but not all users know how to clean up the mail flooding mess this can make.

Comment 20

[David :Bienvenu]

this is fixed in 3.0 trunk builds by the patch in bug 409259