#87 Failing to fetch complete mailbox from Yahoo!

[John Smith]

I'm using the current master at e13b939.

After fetching 2064 messages, I got booted from the server for exceeding the rate limit:

  far side: 72624 messages, 0 recent
  Synchronizing...
  Warning from IMAP server: [LIMIT] Rate limit hit.
  IMAP error: unexpected BYE response: IMAP4rev1 Server logging out         
  Channels: 1    Boxes: 1    Far: +0 *0 #0 -0    Near: +2064 *0 #0 -0

So I restarted mbsync, expecting it to resume the process gracefully. However, although it identified correctly again the grand total of 72624 on the far side, it proceeded to only pull 2000 messages:

 Loading near side box...
 near side: 2064 messages, 925 recent
 far side: 72624 messages, 0 recent
 Synchronizing...
 C: 0/1  B: 0/20  F: +0/0 *0/0 #0/0 -0/0  N: +28/2000 *2064/2064 #0/0

At this point, something seemed wrong, so I interrupted the process by issuing <C-c>. I then restarted mbsync one more time, and the behavior was changed. Instead of resuming the fetching process, it proceeded instead to update a \Delete flag on messages on the Far side, which had been fetched previously. When I realised what was going on, I quickly interrupted the process again, then restarted it again and turned debugging on. The flag updates continued as seen below:

  F: * 1 EXPUNGE
  F: Callback enter expunged message 10964
  F: Callback leave expunged message 10964
  F: * 72589 EXISTS
  F: 7 OK UID STORE completed
  F: [ 9] Callback enter set_msg_flags, sts=0
  -> log: * 10964 35 48 (pushed flags ST; were S)
  F: [ 9] Callback leave set_msg_flags
  F: >>> 8 UID STORE 10965 +FLAGS.SILENT (\Deleted)^M

Several dozens emails have been deleted in this way from the remote server, because Yahoo! auto-expunges in response to the \Delete flag.

My ~/.mbsyncrc is below:

 23 CopyArrivalDate yes
 22 SyncState *
 21
 20 IMAPAccount [redacted]
 19 Host export.imap.mail.yahoo.com
 18 Port 993
 17 User [redacted]
 15 Pass [redacted]
 14 TLSType IMAPS
 13 PipelineDepth 1
 12 
 11
 10 IMAPStore [redacted]-remote
  9 Account [redacted]
  8
  7 MaildirStore [redacted]-local
  6 SubFolders Verbatim
  5 Path ~/mail/[redacted]/
  4 Inbox ~/mail/[redacted]/Inbox
  3
  2 Channel [redacted]
  1 Far :[redacted]-remote:
  0 Near :[redacted]-local:
  1 Pattern *

[Oswald Buddenhagen]

this sounds bad.
it seems that it thinks that the downloads were completed, so it treats the missing mails as deletions. and it somehow fails to see 70k+ messages.

to debug this, i need the full log (with -D) of both the initial sync attempt and the destructive followup. that means that you need to start from scratch locally. do the second run with --dry-run, which should be good enough without causing actual damage.
you can mail me the logs in private.

[John Smith]

I've been unable to reproduce it using Dry Run. After several attempts, it always finishes with:

Channels: 1    Boxes: 20    Far: +0 *0 #0 -0    Near: +122976 *0 #0 -0

Which looks like the correct grand total for the entire remote store (i.e inclusive of other folders, besides INBOX). So I haven't been able to reproduce the weird cap at 2000, or the message deletions.

Some more context:

I was originally using version 1.4.4-5. Over the course of a dozen or so attempts to synchronise the entire Yahoo! store from scratch, I noticed the same odd N: .../2000 occuring on a number of occasions (it was always 2000). When it was occurring was unpredictable. For example, I could be pulling about ~3000 messages per run (before being rate limited), with several successive runs going fine (so pulling a large percentage of the remote store over several iterations), and then I would suddenly get that strange cap at 2000. Once those final 2000 messages would be pulled, mbsync would stop pulling any remaining messages (even after restarting it), although it was still reporting the grand total correctly on the far side. Unfortunately, I don't have debug logs for this.

So since I could never pull the entire remote store, I decided to use the latest version and see if the issues went away. So that's what happened before the informatoin in the first post.

Since dry run didn't reproduce the problem after writing the first post, I decided to run it normally and watch the logs. After 43 incremental runs (due to rate limiting), I was still unable to reproduce the sudden 2000 cap. However, I think I was able reproduce the sudden message deletions. On the 44th run, I noticed it started adding \Delete flags again, for an unkown reason. I spot it in time and stopped it after a few dozen messages.

In addition, I also have the debug log for the first time this happened (when I wrote the first post). I will be sending those to you now in private.

[Oswald Buddenhagen]

the culprit is the server returning partial fetch responses, which are tagged with [LIMIT] . this obviously completely derails isync.

yahoo is attempting to standardize (a slightly more advanced version of) this behavior in rfc9738. to cite from this awesome document:

If the server has a
MESSAGELIMIT of 1000, the client will only be able to download 1000
of the most recent messages; the client will not understand why, will
not be prepared to recover from the situation, and will act as if it
is interacting with a broken server.

yeah, d'oh. 🤦‍♂️

top priority is to make isync recognize limited fetch responses and bail out.

further down the line, a workaround can be implemented by chunking the queries. we already chop up the queries under some circumstances, so some of the infrastructure is already there.