When attempting to copy or move large numbers of local messages to an IMAP server, it fails without any error or status message

NEW
Unassigned

Status

Thunderbird
Folder and Message Lists
--
major
8 years ago
4 months ago

People

(Reporter: Magritte, Unassigned)

Tracking

(Blocks: 1 bug)

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [has protocol log])

Attachments

(3 attachments)

(Reporter)

Description

8 years ago
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 6.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 6.1; en-US; rv:1.9.1.5) Gecko/20091204 Thunderbird/3.0

I've been attempting to migrate some local mail to Gmail through IMAP. I've been able to move many folders which have a relatively small number of messages (in the few hundreds) but for folders with many messages (eg. over 4000) the move or copy operation simply stops partway through. The number of messages copied will vary between a few dozen, hundred or even a couple of thousand but it will never successfully finish. There is no error message or warning at all, neither as a popup dialog or in the status bar. It just stops trying without any information provided. 

If I select a small number of messages from the folder I can successfully move them.

Furthermore, Thunderbird does not delete local messages that WERE successfully moved. It will only delete local messages if all messages were successfully copied. This makes it impossible to simply keep trying until all the messages have finally been moved successfully, since the copied messages remain in the local folder and therefore just get copied again during the next attempt. Moving or copying all the messages appears to be impossible.

At fist I suspected there may be a Gmail-specific issue. However, I tried installing a local IMAP server (hMailServer) and verified that the same issue occurs even on the local IMAP server. Small numbers of messages may be transferred, but it always quits without warning when attempting to move large amounts of mail.

Reproducible: Always

Steps to Reproduce:
1.Select several thousand email messages (or a folder with several thousand messages)
2.Shift+Drag to IMAP server or right-click, select move-to, then select a folder on the IMAP server. (You may have to first create an empty folder on the IMAP server)
3.Wait as some of the messages are moved, but then it stops transferring the rest without any warning.
Actual Results:  
Only a subset of selected messages are successfully moved to the IMAP server and those messages are not deleted from the local folder.

Expected Results:  
All messages are transfered to the IMAP server and any successfully transfered message is deleted from the local folder (assuming you chose to move rather than copy).

Comment 1

8 years ago
Magritte, does Message|Move to|...   or r-click Move to|... work better?
Component: General → Folder and Message Lists
QA Contact: general → folders-message-lists
(Reporter)

Comment 2

8 years ago
No, I've tried dragging, as well as right-click move to and message move to and they all behave the same. I've also tried using Nostalgy's hotkeys and they didn't work at all. When dragging I've tried dragging files to an existing folder, dragging the folder to the account root, and either simple or shift+drag (Thunderbird has a sad lack of appropriate feedback when dragging and dropping and it's not clear when dragging messages to a folder if it will be a copy or move operation). 

In any case, I just tried again using a local IMAP server and a Thunderbird profile with no extensions installed. Attempting to move a folder with around 9000 messages successfully moved about 4000 before stopping without any indication as to why. The Activity Manager window displays NO information about uploading mail, only downloading/syncing.

Again, because those emails that were uploaded during a move operation were not removed from the original folder, there's no simple way to determine which messages are missing or any easy way to continue from where the operation stopped. Messages should be deleted as they are uploaded, but Thunderbird appears to want to upload all messages first before deleting, and then if the upload is not completed you're left with no messages deleted locally and some subset copied to the server.

Comment 3

8 years ago
thanks for checking that.  is it likely/unlikely that a new message arrived while your message operations were in progression?
(Reporter)

Comment 4

8 years ago
When I tried this using a local IMAP server that would have been impossible. However, I have noticed that it will start syncing to the new messages in the IMAP folder while I'm trying to move my messages into it. So it starts copying then it starts downloading from the server to the local IMAP store, then continues copying, etc. Sometimes the message in the status bar alternates quickly from downloading to copying. It's never been clear to me if uploading and downloading occur simultaneously or not?

Maybe I'll try disabling automatic mail check and IDLE support to see if I can prevent it from checking for new mail while uploading.
(Reporter)

Comment 5

8 years ago
I tried disabling the following server settings:
Check for new messages at startup
Check for new messages every ___ minutes
Use IDLE command if the server supports it
Keep messages for this account on this computer

At first I thought this might work as it got further than ever before: around 8000 of 9000 messages from one folder. However, at that point, it stopped like all the other times and since then no improvement on subsequent attempts even after closing and restarting Thunderbird.

What's worse is at one point I accidentally moved the messages from the local folder to the IMAP folder while Thunderbird was in offline mode. This caused all the messages to be deleted from the local folder and appear in the IMAP folder. However, once I went back to Online mode, it started copying those messages to the IMAP server, and then stopped about half way through. As a result, half the messages never appeared on the IMAP server but did disappear from the local folder.

After restarting Thunderbird it did appear to try again to upload those messages (so I assume they are still cached somewhere) but it again quite after only a couple of hundred messages.

At this point I'm using a local IMAP server for speed and working with a backup of the actual profiles. However, at least in some cases there does appear to be a potential for serious data loss due to this bug if a large move is attempted while in offline mode.

Comment 6

8 years ago
Looks like a duplicate of 381867
Magritte(bug opener), can you please get IMAP log with timestamp and check IMAP level flow, and check at which step "copy of mails to IMAP folder" stops or is interfered.
> https://wiki.mozilla.org/MailNews:Logging
> http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25328
> SET NSPR_LOG_MODULES=timestamp.imap:5
If Tb's fault is seen in log, attach IMAP log file, if all data in log can be opened to public, please.
(Reporter)

Comment 8

8 years ago
I finally got around to making a log. I'm not comfortable uploading it as it's both rather large and contains all the text of many e-mails. I tried to look through it to find the point of failure but couldn't really identify what it was. I tried to upload a folder to a Gmail account. It doesn't help that it tries to download newly uploaded messages. Actually, the first time I tried it synced a mess of messages from the server and the log was over 4 GB in size. Thinking that everything should have been synced up, I tried again. Even then the log is around 700 MB.

Is there anything in particular I can look/search for in the log?

One thing I notice is I select all the files in the folder for moving to the server. When it fails, the selection changes (without any interaction from me) from everything selected to a single message selected.
(Reporter)

Comment 9

8 years ago
(In reply to comment #6)
> Looks like a duplicate of 381867

It seems different. 381867 states that in the endless loop messages are copied multiple times to the server. I have not seen this behaviour. Each message is copied a single time to the server, but Thunderbird is unable to complete the copying if many messages are selected. I initially found this on Gmail, so in principle there could have been an endless loop at the last message copied since Gmail automatically removes duplicates messages. However, I subsequently confirmed the same behaviour using the open source hMailServer IMAP server running on the same local machine and did not find any instances of a single or multiple messages being copied more than once.
(In reply to comment #8)
> I finally got around to making a log. I'm not comfortable uploading it as it's
> both rather large and contains all the text of many e-mails. I tried to look

You can remove the message content. and can anonymize the log, this should make it smaller. If you are still uncomfortable about sharing it publicly you can send it to bienvenu@mozillamessaging.com with a reference to the bug number. But trimming and cleaning the log from personal data and attaching it here is the preferred method.

Comment 11

8 years ago
fwiw my comment 3 refers to bug 458570
(Reporter)

Comment 12

8 years ago
So I wasn't comfortable uploading the log file with real messages and removing personal data didn't seem like a trivial thing to do. Finally I thought of a way to generate a large sample set of messages to use instead: subscribing to individual e-mail updates for a highly active google group. This generated over 5000 messages in about a day which I copied to a local folder then tried to upload (move) to a test gmail account over IMAP. It successfully copied 3099 of 5142 messages before it stopped. Again, there was no error message, all of the messages in the local folder remained highlighted, and none were deleted.

The log file was too large to attach to this bug report, so I've upload it here:
https://docs.google.com/leaf?id=0B4NCPWEUDyRaYzM3ZWY5OWYtZjQ2Zi00ZDM1LWI1MjktYWNkZGFlY2EyNDQz&hl=en

Thanks.

Comment 13

8 years ago
thanks  Magritte
Whiteboard: [has protocol log]
(In reply to Magritte from comment #12)
> It successfully copied 3099 of 5142 messages before it stopped.
> Again, there was no error message, all of the messages in the local folder
> remained highlighted, and none were deleted.

From where does the "3099 of 5142" come from?
Status bar message? Activity manager message? Actually selected & copied mail count?

How many mails were selected at move source folder(local mail folder), and how many mails were actually copied to move target folder?
(As Tb doesn't show total mail count, operation like "Select All", "Mark as Unread" is needed, unless add-on is installed)

If "Order Received" column(if IMAP, value is UID of mail) is shown, you can see UID of mail. 
What is UID of first copied mail? (smallest one in copied mails)
What is UID of last copied mail?  (largest one if additional mail is not added)
Because UID is incremented by one, UID of bulk copied mails are usually continuous, unless new mail arrives while you are uploading many mails.
When sorted by "Order Received" column, do you see non continuous UID?

Gmail IMAP actually returns response like next.
> http://www.google.com/support/forum/p/gmail/thread?tid=166a48b67e267726&hl=en#fid_166a48b67e267726000473da9b2938ae
> host:imap.gmail.com -- port:993 -- 2.47 NO [ALERT] Account exceeded bandwidth limits. (Failure)

No such message in Activity Manager panel?

Gmail doesn't permit duplicated mail data. So, if duplicated mail data is uploaded, Gmail finaly ignores it, although Gmail assigns UID for the dup'ed mail in the uploaded folder. This is same for Tb as "uploaded mail by Tb is deleted & expunged by some one just after Tb uploaded the mail(successful append command)".
Although this can't explain phenomenon of "Selection of all mails remains at move source folder, and mails are never deleted", it can explain some part of of "number of copied mails is smaller than number of mails for which move was requested".
Please surely rule out such case, please.

I uploaded(copied from local mail folder) 10,000 mails(1KB per a mail, 10MB total, never dup of existent mails, no dup in uploaded mails) to Gmail IMAP's newly created folder(starts from UID=1) today using Tb 9.0.1 on Win, for testing of other bug. It took long because of 10MB data, but it normally ended, and UID was continuous.
Bug opener, do you still see your problem with recent Tb release?
Created attachment 586633 [details]
Extracted IMAP log (append command and response only)

(In reply to Magritte from comment #12)
> The log file was too large to attach to this bug report, (snip)
> https://docs.google.com/leaf?id=0B4NCPWEUDyRaYzM3ZWY5OWYtZjQ2Zi00ZDM1LWI1MjktYWNkZGFlY2EyNDQz&hl=en

Yes, your log file is too large. More than 800 MB!
More than half was fetch logs from [Gmail]/All Mail. Why not stop auto mail check etc. even though check with DLE enabled and with Gmail IMAP?

I extracted log line for "append command" and "append response" only, and merged command and response into single line for ease of analysis.
Example of extracted log line(log for last append command).
> 2010-01-10 19:18:22.692000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7142 append "imapsamplemailbox" "09-Feb-2010 15:52:28 -0500" {12544+}
> "2010-01-10 19:18:23.503000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7142 OK [APPENDUID 632907681 3179] (Success)
 
As seen in extracted/merged log, appended mail is assigned UID from 1 to 3179, and all append request is successfull. After it, log for fetch of uploaded maiis from imapsamplemailbox is seen, and all of UID= 1 to 3179 is also successfully fetched, and finaly IMAP session is normally closed because you terminated Tb.
So, "duplicated mail" is not involved in 3179 mails from UID=1 to UID=3179.

(In reply to Magritte from comment #12)
> It successfully copied 3099 of 5142 messages before it stopped.
> Again, there was no error message, all of the messages in the local folder
> remained highlighted, and none were deleted.

Perhaps "3099 of 5142" is status bar message.
Tb doesn't update status bar message upon each append. So smaller number than actually appended mails is shown.
An IMAP task of Tb for upload of mail is perhaps waiting for next request from task for "move mails".

How did you move mails?
Select All + Drag&Drop? or "Move To" context menu? 

IIRC, problem/bug like next existed.
  Move of may mails by Drag&Drop somehow stops at mid of move of may process.
It may be caused by new mail arrival during move of many mails, by other request(s) to same folder which happened at same time.
"Event of Drag&Drop disappers while processing due to other event(s)" like issue may be a cause.
Per attached log data and your report, confirming.
Status: UNCONFIRMED → NEW
Ever confirmed: true
FYI.
Following are bugs for "move of mails by Drag&Drop" found by serch for "move drag" in bug summary.
> Bug 368112 Messages lost when multiple messages moved between local mail folders
>            (not only move/drag&drop but also copy/thru menu)
> Bug 452832 drag and drop multiple messages between folders fails (moves only one)
Both are already FIXED.
"Messages in local move source folder didn't disappear in your case" may be a effect by fix of Bug 368112(see many dups of that bug).
Checked Tb's behavior when offline is forced by pull-off of LAN cable during move mails from local folder to IMAP folder", using Tb 9.0.1 in Win-XP. 

(1) At Tb Window-1, using "Move To", request move of 1000 mails in local mail folder to Gmail IMAP mail folder, Inbox/Inbox3.

> 3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:CreateNewLineFromSocket: 37 OK [APPENDUID 602313603 152] (Success) 
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:SendData: 38 noop 
> [3820] 620[4d87fc0]: ReadNextLine [stream=54ff880 nb=15 needmore=0]
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:CreateNewLineFromSocket: 38 OK Success 
> [3820] 0[100f140]: CopyNextStreamMessage: Copying 10 of 10000
> (End of upload of 10-th mail)

> (Start of upload of mail = 11-th mail)
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:ProcessCurrentURL: entering
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:ProcessCurrentURL:imap://yatter%2Eone%40gmail%2Ecom@imap.gmail.com:993/appendmsgfromfile%3E/INBOX/Inbox3:  = currentUrl
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:SendData: 39 append "INBOX/Inbox3" (\Seen tag-10) "01-Jan-1970 09:09:00 +0900" {938} 
> [3820] 620[4d87fc0]: ReadNextLine [stream=54ff880 nb=12 needmore=0]
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:CreateNewLineFromSocket: + go ahead 
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:SendData: X-Mozilla-Keys: tag-10                                                                           
> (logs for mail body lines are omitted)
> (following is indicator of "End of message data", so Tb waits for OK response to append command)
> [3820] 620[4d87fc0]: 4a9a800:imap.gmail.com:S-INBOX/Inbox3:SendData:  

(2) Pull off LAN cable.

(After 2 seconds, next log was seen, because I used DebugView for logging data)
[MUP]: DfscFsctrlStateTransition invoked.
[MUP]: Flushing pkt cache...
[MUP]: done.

(3) Tb went Work Offline mode, because Tb detected offline status.

(4) At Tb Window-1, following was still shown at status bar,
      Copying Message 11 of 1000 to Inbox3
    and progress par was spinning, and selection of mails were kept.

(5) Plug in LAN cable.
    Tb went back to Work Online mode, because Tb detected online status.

(6) Open Tb Window-2, select Inbox/Inbox3 of Gmail IMAP account.
    Mail of UID=11 was normally shown, because all data was passed to server,
    although Tb couldn't receive OK response.

(7) At Tb Window-1, following was/is shown at status bar,
      Copying Message 11 of 1000 to Inbox3
    and progress bar didn't stop and is still spinning,
    even after "Repair Folder" at Tb window-2.
    Selection of mails were still kept.

When I executed above test first time, error of "unable to connect to imap.gmail.com" was shown at Activity Manaer panel, and spinning at Tb Window-1 didn't occur.
"spinning at Tb Window-1" is perhaps timing dependent phenomenon.
"silent stopping of move operation at middle of bulk move" is perhaps common phenomenon when silent(for Tb) connection loss occurs during bulk move/copy.

Above phenomenon is very similar to phenomenon you saw, although "connection loss actually happend in your case or not" is unknown.
If connection with IMAP server is silently lost, pheomenon similar to above can happen.
As as many untagged response of "* MMM EXPUNGE, * NNN EXISTS" where MMM=NNN or MMM=NNN-1 to append command is seen in your log, you uploaded many dup mails to Gmail IMAP server when you got IMAP log.
  * MMM EXPUNGE = MMM-th mail in existent mails is expunged.
  * NNN EXPUNGE = There is NNN mails, after above expunge.
  When Gmail IMAP above untagged response means;
    MMM-th mail(UID=X) is same as newly appended mail(UID=Y, larger than X),
    so mail of UID=10 is removed, and mail of UID=Y is added.
    MMM=NNN  : Mail of UID=X is mail appended just before this append command.  
    MMM=NNN-1: Mail of UID=X is mail appended by former append command.  
  This is because Gmail does't keep dup mails.
Abnormal condition like above may produces unwanted workload of server. So, silent(for Tb) connection kill by Gmail may happen.

Magritte(bug opener), did silent connection loss occur in your case?
Can you reproduce your problem with recent Tb release?
Created attachment 586765 [details]
IMAP log : Pull off LAN cble while bulk move of mails from local folder to Gmail IMAP folder

(1) 5 mails exist in Gmail IMAP folder, Inbox/Inbox3
  UID=100, Subject: MANYMAILS-000011, Message-ID: <MANYMAILS.000011.000001>
  UID=102, Subject: MANYMAILS-000013, Message-ID: <MANYMAILS.000013.000001>
  UID=104, Subject: MANYMAILS-000015, Message-ID: <MANYMAILS.000015.000001>
  UID=106, Subject: MANYMAILS-000017, Message-ID: <MANYMAILS.000017.000001>
  UID=108, Subject: MANYMAILS-000019, Message-ID: <MANYMAILS.000019.000001>
(2) At local mail folder, request move 10000 mails to the Gmail IMAP folder,
    includeng same 5 mails as existent mails in Gmail IMAP Inbox/Inbox3.
    Because "move/copy from local to IMAP" is done from bottom mail to top mail
    in sorted order at thread pane, mails are sorted in reversed order of
    Subject: to force required append order.
(3) Because of Gmail IMAP, following is returned to append of dup mails.
> Message-ID: <MANYMAILS.000011.000001> => * 1 EXPUNGE, * 15 EXISTS (UID=100 is removed as dup)
> Message-ID: <MANYMAILS.000013.000001> => * 1 EXPUNGE, * 16 EXISTS (UID=102 is removed as dup)
> Message-ID: <MANYMAILS.000015.000001> => * 1 EXPUNGE, * 17 EXISTS (UID=104 is removed as dup)
> Message-ID: <MANYMAILS.000017.000001> => * 1 EXPUNGE, * 18 EXISTS (UID=106 is removed as dup)
> Message-ID: <MANYMAILS.000019.000001> => * 1 EXPUNGE, * 19 EXISTS (UID=108 is removed as dup)
(4) Pull off LAN cable.
Because connection error happend just after send of "noop" in this test, spining at Window-1(where move mails is requesed) was observed.
> 00001693	120.09008026	[5380] 3372[512cc40]: 5dcd000:imap.gmail.com:S-INBOX/Inbox3:SendData: 85 append "INBOX/Inbox3" (\Seen tag-1) {938} 	
> 00001697	120.26193237	[5380] Message-ID: <MANYMAILS.000031.000001> 	
> 00001701	120.26193237	[5380] Subject: MANYMAILS-000031 	
> 00001726	120.59330750	[5380] 3372[512cc40]: 5dcd000:imap.gmail.com:S-INBOX/Inbox3:CreateNewLineFromSocket: * 31 EXISTS 	
> 00001728	120.59339905	[5380] 3372[512cc40]: 5dcd000:imap.gmail.com:S-INBOX/Inbox3:CreateNewLineFromSocket: 85 OK [APPENDUID 602313603 193] (Success) 	
> 00001729	120.59358215	[5380] 3372[512cc40]: 5dcd000:imap.gmail.com:S-INBOX/Inbox3:SendData: 86 noop 	

==> LAN cable was pulled off at here.

> 00001730	121.76026917	[MUP]: DfscFsctrlStateTransition invoked.	
> 00001731	121.76027679	[MUP]: Flushing pkt cache...	
> 00001732	121.76029205	[MUP]: done.	

(5) Plug-in of LAN cable.
Tb went back Online mode automatically, but server access for Inbox/Inbox3 was impossible in this test. Nothing was requested to server for Inbox/Inbox3 via connection for Inbox/Inbox3, even by Repair Folder at newly opened Tb Window-2.
So, I terminated Tb and restarted Tb, to check.

> 00001810	733.12371826	[5380] 6040[5d7d5c0]: ImapThreadMainLoop leaving [this=13006000]
=> Terminate Tb, Restart Tb at here.
> 00001811	821.73992920	[2572] 1160[512cc40]: ImapThreadMainLoop entering [this=5dcd000]	
> 00001812	821.74041748	[2572] 0[100f140]: 5dcd000:imap.gmail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
Created attachment 586864 [details]
Your IMAP log for imapsamplemailbox, after last append(UID=3179)

(1) Last append

> 2010-01-10 19:18:22.692000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:18:22.692000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/appendmsgfromfile%3E/imapsamplemailbox:  = currentUrl
> 2010-01-10 19:18:22.692000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7142 append "imapsamplemailbox" "09-Feb-2010 15:52:28 -0500" {12544+}
> 2010-01-10 19:18:23.503000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 EXISTS
> 2010-01-10 19:18:23.503000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7142 OK [APPENDUID 632907681 3179] (Success)
> 2010-01-10 19:18:23.503000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7143 noop
> 2010-01-10 19:18:23.690000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7143 OK Success

(2) IDLE afterlast appnd
> 2010-01-10 19:18:23.721000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7144 IDLE
> 2010-01-10 19:18:23.893000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: + idling

(3) After 5 minutes of idling, unsol "* 3099 EXISTS", and Tb terminates IDLE 
> 2010-01-10 19:23:29.357000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 EXISTS
> 2010-01-10 19:23:29.357000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: DONE
> 2010-01-10 19:23:29.529000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7144 OK IDLE terminated (Success)

(4) Then Tb request "check", and fetch flag of newly appended mails
> 2010-01-10 19:23:29.529000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:23:29.529000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/select%3E/imapsamplemailbox:  = currentUrl
> 2010-01-10 19:23:29.529000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7145 check
> 2010-01-10 19:23:29.700000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7145 OK Success
> 2010-01-10 19:23:29.716000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7146 getquotaroot "imapsamplemailbox"
> 2010-01-10 19:23:29.888000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7146 OK Success
> 2010-01-10 19:23:29.888000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7147 UID fetch 671:* (FLAGS)
> 2010-01-10 19:23:30.137000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: *  654 FETCH (UID 671 FLAGS (NonJunk))
>                                                                                          (untagged responses is omitted)     |
> 2010-01-10 19:23:30.824000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 FETCH (UID 3179 FLAGS ())
> 2010-01-10 19:23:30.824000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7147 OK Success

(5) And fetch headers of mails
> 2010-01-10 19:23:30.839000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7148 UID fetch 671:3179 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])
> 2010-01-10 19:23:31.104000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 654 FETCH (UID 671 RFC822.SIZE 12412 FLAGS (NonJunk) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)] {321}
> 2010-01-10 19:23:31.104000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:OPEN Size: 12412: Begin Message Download Stream
> 2010-01-10 19:23:31.120000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:CLOSE: Normal Message End Download Stream
>                                                                         (logs after fetch of UID=671, before fetch of UID=3179, are omitted)
> 2010-01-10 19:23:38.093000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 FETCH (UID 3179 RFC822.SIZE 12544 FLAGS (NonJunk) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)] {348}
> 2010-01-10 19:23:38.093000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:OPEN Size: 12544: Begin Message Download Stream
> 2010-01-10 19:23:38.093000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:CLOSE: Normal Message End Download Stream
> 2010-01-10 19:23:38.093000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7148 OK Success

(6) fetch of message body is invoked
> 2010-01-10 19:23:38.140000 UTC - 0[a2d140]: queuing url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.140000 UTC - 0[a2d140]: considering playing queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.140000 UTC - 0[a2d140]: creating protocol instance to play queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.140000 UTC - 0[a2d140]: failed creating protocol instance to play queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.156000 UTC - 0[a2d140]: considering playing queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.156000 UTC - 0[a2d140]: creating protocol instance to play queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.156000 UTC - 0[a2d140]: playing queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>671,673:674
> 2010-01-10 19:23:38.156000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:23:38.156000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/fetch%3EUID%3E/imapsamplemailbox%3E671,673:674:  = currentUrl
> 2010-01-10 19:23:38.156000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 7149 UID fetch 671,673:674 (UID RFC822.SIZE BODY.PEEK[])
> 2010-01-10 19:23:38.390000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 654 FETCH (UID 671 RFC822.SIZE 12412 BODY[] {12412}
> 2010-01-10 19:23:38.390000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:OPEN Size: 12412: Begin Message Download Stream
> 2010-01-10 19:23:38.421000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:CLOSE: Normal Message End Download Stream
> 2010-01-10 19:23:38.452000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 655 FETCH (UID 673 RFC822.SIZE 12587 BODY[] {12587}
> 2010-01-10 19:23:38.452000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:OPEN Size: 12587: Begin Message Download Stream
> 2010-01-10 19:23:38.452000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:CLOSE: Normal Message End Download Stream
> 2010-01-10 19:23:38.577000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 656 FETCH (UID 674 RFC822.SIZE 11998 BODY[] {11998}
> 2010-01-10 19:23:38.577000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:OPEN Size: 11998: Begin Message Download Stream
> 2010-01-10 19:23:38.608000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:CLOSE: Normal Message End Download Stream
> 2010-01-10 19:23:38.608000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 7149 OK Success

(7) "fetch of message body" continues. It looks 2 or 5 mails arerequested by each fetch.

(8) Last continuous "fetch of message body"
> 2010-01-10 19:30:43.810000 UTC - 0[a2d140]: queuing url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.810000 UTC - 0[a2d140]: considering playing queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.810000 UTC - 0[a2d140]: creating protocol instance to play queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.811000 UTC - 0[a2d140]: failed creating protocol instance to play queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.812000 UTC - 0[a2d140]: considering playing queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.812000 UTC - 0[a2d140]: creating protocol instance to play queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.812000 UTC - 0[a2d140]: playing queued url:imap://imapsamplemailbox@gmail.com@imap.googlemail.com:993/fetch>UID>/imapsamplemailbox>2396
> 2010-01-10 19:30:43.812000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:30:43.812000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/fetch%3EUID%3E/imapsamplemailbox%3E2396:  = currentUrl
> 2010-01-10 19:30:43.812000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8230 UID fetch 2396 (UID RFC822.SIZE BODY.PEEK[])
> 2010-01-10 19:30:45.868000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 2331 FETCH (UID 2396 RFC822.SIZE 3257064 BODY[] {3257064}
> 2010-01-10 19:30:45.868000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:OPEN Size: 3257064: Begin Message Download Stream
> 2010-01-10 19:30:58.446000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:STREAM:CLOSE: Normal Message End Download Stream
> 2010-01-10 19:30:58.447000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8230 OK Success

(9) IDLE
> 2010-01-10 19:30:58.781000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8231 IDLE
> 2010-01-10 19:30:58.953000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: + idling

(10) After 1 miutes, while idling at imapsamplemailbox, login for [Gmail]/Drafts occurs
> 2010-01-10 19:31:00.117000 UTC - 0[a2d140]: 8e31800:imap.googlemail.com:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
> 2010-01-10 19:31:00.118000 UTC - 5932[5346a40]: ImapThreadMainLoop entering [this=8e31800]
> 2010-01-10 19:31:00.118000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:ProcessCurrentURL: entering
> 2010-01-10 19:31:00.118000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/select%3E/%5BGmail%5D/Drafts:  = currentUrl
> 2010-01-10 19:31:00.880000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:CreateNewLineFromSocket: * OK Gimap ready for requests from 128.100.240.244 8if1458905yxj.52
> 2010-01-10 19:31:00.880000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:SendData: 1 capability
> 2010-01-10 19:31:00.947000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA XLIST CHILDREN XYZZY
> 2010-01-10 19:31:00.947000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:CreateNewLineFromSocket: 1 OK Thats all she wrote! 8if1458905yxj.52
> 2010-01-10 19:31:00.948000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
> 2010-01-10 19:31:01.489000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4rev1 UNSELECT LITERAL+ IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE
> 2010-01-10 19:31:01.489000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:NA:CreateNewLineFromSocket: 2 OK imapsamplemailbox@gmail.com authenticated (Success)
> 2010-01-10 19:31:01.489000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:A:SendData: 3 COMPRESS DEFLATE
> 2010-01-10 19:31:01.687000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:A:CreateNewLineFromSocket: 3 OK Success
> 2010-01-10 19:31:01.687000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:A:SendData: 4 select "[Gmail]/Drafts"
> 2010-01-10 19:31:01.892000 UTC - 5932[5346a40]: 8e31800:imap.googlemail.com:A:CreateNewLineFromSocket: 4 OK [READ-WRITE] [Gmail]/Drafts selected. (Success)

(11) After 2 minutes from start of IDLE, enter idling again
> 2010-01-10 19:32:41.905000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: DONE
> 2010-01-10 19:32:42.073000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8231 OK IDLE terminated (Success)
> 2010-01-10 19:32:42.073000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:32:42.073000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/folderstatus%3E/imapsamplemailbox:  = currentUrl
> 2010-01-10 19:32:42.073000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8232 noop
> 2010-01-10 19:32:42.255000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8232 OK Success
> 2010-01-10 19:32:42.260000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8233 IDLE
> 2010-01-10 19:32:42.430000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: + idling

(12) After 5 minutes, unsol "* 3099 EXISTS". Gmail looks to send unsol response each 5 minutes.
> 2010-01-10 19:37:47.573000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 EXISTS
> 2010-01-10 19:37:47.723000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: DONE
> 2010-01-10 19:37:47.899000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8233 OK IDLE terminated (Success)
> 2010-01-10 19:37:47.899000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:37:47.900000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/select%3E/imapsamplemailbox:  = currentUrl
> 2010-01-10 19:37:47.900000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8234 check
> 2010-01-10 19:37:48.071000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8234 OK Success
> 2010-01-10 19:37:48.072000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8235 getquotaroot "imapsamplemailbox"
> 2010-01-10 19:37:48.252000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * QUOTAROOT "imapsamplemailbox" ""
> 2010-01-10 19:37:48.252000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * QUOTA "" (STORAGE 65702 7600203)
> 2010-01-10 19:37:48.252000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8235 OK Success
> 2010-01-10 19:37:48.252000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8236 UID fetch 3180:* (FLAGS)
> 2010-01-10 19:37:48.436000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 FETCH (UID 3179 FLAGS (NonJunk))
> 2010-01-10 19:37:48.436000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8236 OK Success

(13) Enter idling again
> 2010-01-10 19:37:48.485000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8237 IDLE
> 2010-01-10 19:37:48.663000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: + idling

(14) After 5 minutes, unsol "* 3099 EXISTS". Gmail looks to send unsol response each 5 minutes.
> 2010-01-10 19:42:53.816000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 EXISTS
> 2010-01-10 19:42:53.817000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: DONE
> 2010-01-10 19:42:53.986000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8237 OK IDLE terminated (Success)
> 2010-01-10 19:42:53.986000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL: entering
> 2010-01-10 19:42:53.986000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:ProcessCurrentURL:imap://imapsamplemailbox%40gmail%2Ecom@imap.googlemail.com:993/select%3E/imapsamplemailbox:  = currentUrl
> 2010-01-10 19:42:53.986000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8238 noop
> 2010-01-10 19:42:54.154000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8238 OK Success
> 2010-01-10 19:42:54.155000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8239 getquotaroot "imapsamplemailbox"
> 2010-01-10 19:42:54.396000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * QUOTAROOT "imapsamplemailbox" ""
> 2010-01-10 19:42:54.396000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * QUOTA "" (STORAGE 65702 7600204)
> 2010-01-10 19:42:54.397000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8239 OK Success
> 2010-01-10 19:42:54.397000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8240 UID fetch 3180:* (FLAGS)
> 2010-01-10 19:42:54.592000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: * 3099 FETCH (UID 3179 FLAGS (NonJunk))
> 2010-01-10 19:42:54.592000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: 8240 OK Success

(15) Enter idling again
> 2010-01-10 19:42:54.671000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8241 IDLE
> 2010-01-10 19:42:54.846000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:CreateNewLineFromSocket: + idling

(16) Termination of Tb
> 2010-01-10 19:45:42.295000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: DONE
> 2010-01-10 19:45:42.296000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8242 close
> 2010-01-10 19:45:42.296000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:SendData: 8243 logout
> 2010-01-10 19:45:42.326000 UTC - 5932[5346a40]: ImapThreadMainLoop leaving [this=8e31800]
> 2010-01-10 19:45:42.326000 UTC - 4472[5346540]: ImapThreadMainLoop leaving [this=800f400]
> 2010-01-10 19:45:42.326000 UTC - 5664[5345640]: 73e0800:imap.googlemail.com:S-imapsamplemailbox:TellThreadToDie: close socket connection
> 2010-01-10 19:45:42.326000 UTC - 5664[5345640]: ImapThreadMainLoop leaving [this=73e0800]
> 2010-01-10 19:45:42.328000 UTC - 6100[5347800]: ImapThreadMainLoop leaving [this=73e3c00]
> 2010-01-10 19:45:42.328000 UTC - 3592[53458c0]: ImapThreadMainLoop leaving [this=5cba000]
Attachment #586633 - Attachment description: Extracted IMAP log 8append command and response only) → Extracted IMAP log (append command and response only)
For your case.

No connection error existed in your case, because any request/response to/from IMAP server is normally written in the IMAP log after last append command. So, if problem exists in copy process(number of appended mail is less than number of requested mail), it's never due to issue like connection loss while IMAP processing in your case.  

As "* 3099 EXISTS" is returned from server to last append(UID=3179) command and while idling, actual number of mails in imapsamplemailbox is 3099.
As seen in Attachment #586633 [details], UID=1 to UID=3179 is added by append command in your case(fortunately, Gmail IMAP supports UIDPLUS.) 
These means number of appended mails was 3179, and, before appending, no mail existed in imapsamplemailbox at server(it's correct because you created the IMAP folder just before test.) And difference between 3179(highest UID) and 3099(number of mails in the folder) is due to duplicated mails in your case.

Where does "5142" in your "It successfully copied 3099 of 5142 messages before it stopped" come from?
5142 mails actually existed in move source folder(local mail folder) before you requested move but append was requested by Tb for only 3172 mails when you got the IMAP log?

If Tb 9, log like "CopyNextStreamMessage: Copying 8 of 10000" is written by Tb in IMAP log. If possible, execute duplucation test with Tb 9, please, with stopping auto mail check of any IMAP mail folder to exclude unwanted log for [Gmail]/All Mail.
(After removal of log for [Gmail]/All Mail, your 800MB log file was reduced to 240MB. Until removal of log for [Gmail]/All Mail, log analysis was nearly impossible due to too large log file and excess log lines for [Gmail]/All Mail, even though Script was used to extract required log lines.)

Because "move mails" == "copy mails to target folder"(bulk copy) + "delete mails from source folder"(mass delete), delete step of "move many mails" is highly affected by problem like bug 538378.
Is there no problem in "manual delete of 3179 mails" or "manual delete of 5142 mails" at the local mail folder?

By the way, because Gmail IMAP is special IMAP as seen in "upload of dup mails" case, please be careful in testing and reporting Tb's bug at B.M.O.
If problem was "only 3099 mails in Gmail IMAP folder after move of 3179 mails in local folder", it's apparently INVALID in your case.
(In reply to Magritte from comment #5)
> What's worse is at one point I accidentally moved the messages from the
> local folder to the IMAP folder while Thunderbird was in offline mode. This
> caused all the messages to be deleted from the local folder and appear in
> the IMAP folder.

This is already improved by recent Tb such as Tb 9.
For both offline-use=on folder and both offline-use=off folder, offline-store file is used for move/copy to IMAP folder while Work Offline mode. And moved mails are not deleted from local mail folder by the move operation while Work Offline mode.
When go back to Online mode, copied mails at thread pane of the IMAP folder disappears at thread pane once(when first uid fetch 1:* flags, temporary uid of copied mails doesn't exists, so disappears), then appended to the IMAP mbox, and by re-syc of mails, all copied mails are shown again.
After successfull upload of copied mails, mails in move source folder(local folder) is deleted.
So, "move from local to IMAP while Offline mode" is already safer than before.

> However, at least in some cases there does appear to be a potential for serious
> data loss due to this bug if a large move is attempted while in offline mode.

Move/delete while Work Offline mode still has many issues.
  Even in Tb 9, mismatch for user surely exists :
    Mails are moved to other IMAP folder, but they still remain in local mail
    folder, even though user *MOVED" mails.   
  If compact happens on local/move-source mail folder, delete from the local
  folder perhaps fails to find the moved mails, because offset of mails are
  changed by Compact.
  If multiple Thunderbird accesse same IMAP mbox, any Tb can go Offline mode
  and any Tb can do move of mails between IMAP folders during Offline mode.
  In such case, how consistency of multiple mail moves at multiple Tb intances
  can be kept, without any confusion by users?
  (Work Offline mode of Tb is not designed for shared access of IMAP Mbox)
  (by multiple Tb instances, but many users actually shares an IMAP Mbox )
  (by multiple IMAP clients including multiple Tb instances.             )
Some of above are perhaps already reported to other bug.
Please open separate bug for issues around "Work Offline mode", after search for already opened bugs for it well.
Please keep "one prolem per a bug".
I believe this bug is for next;
(a) Copy step of move mails(append) looks to stop somehow at mid of copy of mails,
    even though IMAP level error/TCP level error never occurs.
    Number of appended mails < Number of mails move is requested.
(b) And, it seems that UI freezes for a while.
(c) Even after UI freeze disappears, nothing happen on move source folder.
    At Tb window where move mails is requested, selection of all mails is still
    kept.
(d) No mail is deleted from move source folder even though some of requested
    mails are already uploaded to server successfully.

I guess (b) is due to fetch of all appended mails from [Gmail]/All Mail which is executed concurrently.
You probably didn't disable auto mail check or you opened [Gmail]/All Mail with DLE enabled when you tested, with setting offline-use=on for Gmail IMAP folder(auto-sync tries to whole mail data of all mails when new mail is detected).
Because Gmail IMAP holds data of all mails in [Gmail]/All Mail, append of a mail to imapsamplemailbox generates a new mail in [Gmail]/All Mail. If new mail check is done or if the new mail is notified via IDLE, Tb knows about the new mail and Tb invokes auto-sync process for [Gmail]/All Mail sooner or later, concurrently with append process for "move mails".
And, if offline-use=on is set for imapsamplemailbox, auto-sync for imapsamplemailbox is invoked concurrently with with append process for "move mails", because IMAP connection for the imapsamplemailbox is not locked for "move mails" process only.
Because auto-sync is "download of whole mail data", it takes long, and because IMAP task is currently executed under UI process, short freeze of UI may occur in your test.

(c) is same as phenomenon after connection loss while appending mails for bulk move. Because no connection error happened in your case, issue of (a) is perhaps cause of this phenomenon.

(d) is probably a simple result of "current move mails" = "bulk copy" + "mass delete".  

If (a) actually occurred in your case, I guess contention between next processes is relevant to problem.
(1) Continuous "append" for mails requested to move.
(2) Header fetch for newlly appended mails.
(3) New mail check when unsol "* nnn EXIST" while idling.
    (Gmail IMAP looks to send it each 5 minutes.
(4) New mail check by enabled "automatic new mail check" for the IMAP folder.
(5) Auto-sync for the IMAP folder, because Tb knows about new mails by (1) to (49.
(6) Filter copy/move to the IMAP folder can occur if new mail check is enabled.
(7) MsgPurge by retention policy may occur on the IMAP folder at same time.
(8) Auto-compact may participate to the contention.

Even though "use of connection for the IMAP folder" is properly serialized by tasks like above, tasks for above may interfere each other.
As seen in my IMAP log, log of "CopyNextStreamMessage: Copying NNN of 10000" is written after successful append of NNN-th mail.
The log is written by next code.
> http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapMailFolder.cpp#6748
> 6731 nsImapMailFolder::CopyNextStreamMessage(bool copySucceeded, nsISupports *copyState)
> 6732 {
> 6733   //if copy has failed it could be either user interrupted it or for some other reason
> 6734   //don't do any subsequent copies or delete src messages if it is move
> 6735   if (!copySucceeded)
> 6736     return NS_OK;
> 6737   nsresult rv;
> 6738   nsCOMPtr<nsImapMailCopyState> mailCopyState = do_QueryInterface(copyState, &rv);
> 6739   if (NS_FAILED(rv))
> 6740   {
> 6741     PR_LOG(IMAP, PR_LOG_ALWAYS, ("QI copyState failed:%lx\n", rv));
> 6742     return rv; // this can fail...
> 6743   }
> 6744 
> 6745   if (!mailCopyState->m_streamCopy)
> 6746     return NS_OK;
> 6747 
> 6748   PR_LOG(IMAP, PR_LOG_ALWAYS, ("CopyNextStreamMessage: Copying %ld of %ld\n", mailCopyState->m_curIndex, mailCopyState->m_totalCount));

Because there is no log for next append after last append(for UID=3179) in your IMAP log, it looks for me that next copy(append) was not requested to IMAP code due to one of unexpected conditions in above code.
"Connection loss while appending" perhaps produces one of unexpected conditions in above code.

As written in comment of above code, Tb stops further "move mails" process if such condition occurs.
So, cause of such condition is clear in connection loss case.
What did produce such condition in your case?
FYI.
I've opened bug 716461 for phenomenon of comment #18 and comment #19 when LAN cable is pulled off while uploading mails to IMAP server.
Bug 717016 may be relivant to your problem.
> Bug 717016 pending URI queue management is problematic

Another concern, Auto-Compact, because move/copy from local mail folder.
Mail in local mail folder is pointed by url style path like next. 
                    +-- mail.server.serverN.userName
                    |   +-- mail.server.serverN.hostname
                    |   |     +-- folder name
                    |   |     |     +-- offset of mail data in mail folder file
                    V   V     V     V
  mailbox-message://x@x.x.x/Inbox#23579
(a) If this offset value is obtained upon "Select All" and is passed to "Move/Copy" task at once, and (b) if Auto-Compact occurs while move/copy is running and offset of mails is changed, and (c) if offset change is not notified to move/copy task or move/copy task doesn't care for offset change notification, (d) move/copy may fail due to offset change(mail is not found at the requested offset).
And, (e) if a mail is shifted by Auto-Compact to known offset of other mail, and (f) if length of the shifted mail is same as the known other mail(already shifted to different offset by Compact), (g) wrong mail may be uploaded(or wrong mail is deleted if delete step of Move).

When "delete of old draft by save as draft", (d) in above is "(h) old draft is not deleted" and (g) in above is "(i) wrong draft is deleted", and both (h) & (i) actually occurs in Tb. So, I think (d) & (g) can occur.
If (d) occurs, move/copy of subsequent mails may continue, but move/copy of subsequent mails may stop.
Blocks: 720158

Comment 26

4 years ago
i can wath this problem for years now! the problem, that copy a lot of mails including folders and subfolders stops without any error, is present for years now! i had never success with moving larger amount of mails or folders from one to another (not-local) mailbox. that is very painful! 

also, for example, empty trash is not showing in status-bar while it is still working somehow! when i empty the trash which contains many folders (i deleted them, because the copy-process was not completed correctly), i can see that every second or something like that, there is deleted one folder after another on my imap-server, long time ago after the deleting-process was done in thunderbird.

this makes thunderbird in this situation totally useless! i was searching for addons (import-export, copy folder) but they dont help me either. import-export does not give an option to export to filesystem while keeping folder-structure, copy folder has the same problem than thunderbird by itselfe. there is no way to get the mails from the local pop3-mailbox to the new imap-mailbox... i could copy them directly with scp and put them at the right place on our mailserver, but because i cannot export to filesystem with keeping folder-structure this is impossible.

...it would be a great help, if this problem could be really fixed in the future! 
bug 601900 was about the same problem and the bug was closed as fixed, but it isn't till today!

please, dear thunderbird team, it would be a very great help to see this fixed! 
this is more important then releasing one version and new feature after another!

if i can help you somehow with tests and logfiles, please let me know!

Comment 27

4 years ago
some additional: right now i copy about 100 folders from a customer "by hand" - means i select 3 folders and move them by drag&drop to the imap-mailbox. 
and even with that small amount (the folders does contain only 10-20 mails for example) the process fails sometimes and only the first folder contains mails...

Comment 28

4 years ago
This problem is still present now and in my case could be described as follows:
Using Thunderbird connected by IMAP to two accounts.
One Account is a Microsoft Exchange Account.
One Account is a Gmail Account.
Task: Copy all the contents of a message folder containing about 3000 emails from the Gmail Account to the Exchange Account.
Method tried:  Highlight all the emails. Right click and select Copy To and select the Folder in the Exchange Account.
Result: Only a few emails are copied.
If repeat then destination shows duplicates of same emails.

Is there any solution?
(In reply to DT from comment #28)
> Using Thunderbird connected by IMAP to two accounts.
> One Account is a Microsoft Exchange Account.
> One Account is a Gmail Account.
> Task: Copy all the contents of a message folder containing about 3000 emails
> from the Gmail Account to the Exchange Account.
> Method tried:  Highlight all the emails. Right click and select Copy To and
> select the Folder in the Exchange Account.
> Result: Only a few emails are copied.

Did you get IMAP log and check IMAP level flow?
All mails were normally uploaded to MS Exchange server(append mail data), but only two mails are shown as "number of mails" or only two mails was shown at Thread pane, weren't it?  

> If repeat then destination shows duplicates of same emails.

Did you actually check actual mail number in Mbox of MS Exchange server after first "copy of all mails", before second "copy of all mails"?

Did "network error" or "NO response to append comman" etc. occur during first ""copy of all mails"?
Is "copy source Mbox of Gmail" and "copy target box of MS Exchange" Offline-UseOn folder?
If Offline-Use=On folder and some error happemed during first "copy of all mails", it may be following.
1. first copy is executed with utilizing Offline-Store file.
2. After copy of two mail, some eroor happened.
3. Before execution "append for second copy of all mails", uploading for failed mails whlee "first copy of all mails" is retried, and is normally uploaded.
4. Second "copy of all mails" is normally executed.

Comment 30

4 years ago
some additional information: after doing the hand-copy-job a hole day thunderbird was not able to copy even a single mail! we found out that the cause of this was a full hdd! 

you should implement some error-recognition for the move-command and catch this with try{} catch{} ...

this should be the first step for this problem, or not?

of course this is not the only reason, because in all other cases, the hdd had have enough space...

Comment 31

4 years ago
Same problem over here and considering how important this functionality could be it is absolutely mind boggling and frustrating to say the least that it hasn't been fixed in over 4 years.  

I am experiencing the exact symptoms as the above mentioned posts and problem persists in tb 24.5.0

Comment 32

3 years ago
It seems to be a problem with mails that have an attachment of more than 5MB.

Comment 33

3 years ago
Hey all, don't forget to vote for this bug if you are interested in a solution! I think, this is very important in order to increase the probability, that someone will work on this!

Comment 34

2 years ago
I'm having the same problems described above when trying to move emails between a set of local folders and an IMAP email account. However, I see this happening also for small numbers of emails. The only case in which it doesn't fail is if I move all the messages one by one, which is obviously not practical. If I drag (or copy, or move, etc.) any known number of emails, in many cases only a subset of the selected emails actually reaches the destination. No warnings or errors are generated so unless one is carefully checking the result of the operation, the risk of missing messages is very high.

Comment 35

2 years ago
1) My platform is Linux.
2) I'm copying from IMAP to local folder.
3) Small numbers (25 or so) seem to copy fine.

Comment 36

2 years ago
Also, My version of Thunderbird is 31.2.0

Comment 37

2 years ago
Solution:

I had similar problem and it seems to be solved now by the following:
- In Tools > Options > Advanced > Disk space, I increased cash to max 1024 MB.
- In Tools > Options > Advanced > General, I opened Config Editor, I searched for 'timeout' and I increased usually by x10 the time settings for about 20 positions which to my naive understanding seemed relevant.

Comment 38

2 years ago
Solution (additional info):
After making changes, restart Thunderbird.

Comment 39

2 years ago
AL, thanks for your answer.

Anyway, this is not an solution, it is an workaround! the System should show a error-message if there is a problem while transfer mails from one to another account!

the bug is open for over 5 years, has over 6 votes right now and still nobody is working on it - would be nice if this would change in nearby future ;-)

Comment 40

a year ago
Confirming that this extremely annoying bug still exists in Thunderbird 45.4.0 running on Win7 x64.  Discovered bug and found this thread after attempting to migrate multiple Yahoo accounts to Outlook and Gmail after recently hearing of the massive hacks on Yahoo in 2014 and trying to shut down all of my Yahoo accounts.  However, this bug is not specific to Yahoo.  Moving large quantities of Gmail to Outlook or Outlook to Gmail produces the same result:  Thunderbird stops the move midway with no warning or error message and then goes into a kind of "limp mode" where any successive attempts to move anything cease to work - and don't even report any progress - until I close and restart Thunderbird and try again.  Upon doing so, the move operation fails again and again.  There are spurious copies of emails in the source folder each of which should have been deleted during its move to the destination folder, but Thunderbird won't delete anything until the entire move operation completes successfully, which never happens.

Comment 41

a year ago
Same problem over here with Thunderbird 45.5.0 and Mac OSX 10.11.6. 

Need to move 2000 messages from one IMAP account to another. Not possible to move more than 100-300 at once, then the process fails. Very time intensive and frustrating!

Comment 42

10 months ago
others related to imap -> local folders: bug 842267, bug 1272681, bug 763390, bug 1290669, Bug 775008

Comment 43

10 months ago
and bug 1115328,

Comment 44

4 months ago
Can't believe it!  This bug is open more than 8 years and still no solution.
I stopped using Thunderbird because of this failure, but now I've had to use TB again at work and the problem is still here!

Please, someone should fix this!  It would be very nice if at least you could continue the operation where it previously failed, but it's impossible because it does not delete e-mails that already have been copied to the IMAP folder. That's insane!  The atomic operation here should be moving ONE e-mail, so after it is copied to the IMAP folder it should be removed from the source folder so in case of failure you can just move the rest of e-mails.
You need to log in before you can comment on or make changes to this bug.