#22 Unexpected tags interrupt sync when talking to outlook.com's IMAP servers

[Clément Pit-Claudel]

Hi,

I'm using the latest git master (46e792c3dfc5b81a0bf54d95a0b43429013a224d) to sync an outlook.com IMAP account with a local Maildir. Here's my configuration:

Expunge None
Create Both

MaildirStore local
Path ~/Mail/
Trash Trash

IMAPStore my-username@live.com
Host imap-mail.outlook.com
User my-username@live.com
Pass my-password
CertificateFile /etc/ssl/certs/ca-certificates.crt
Port 993
SSLType IMAPS

Channel my-username@live.com
Master :my-username@live.com:
Slave :local:my-username@live.com

The first run of mbsync -a timed out after a few messages. Subsequent runs all had issues with tags:

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Maildir notice: no UIDVALIDITY, creating new.
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +18/294 *0/0 #0/0
Socket error on imap-mail.outlook.com (207.46.11.202:993): timeout.
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +18/294 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 276 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/276 *0/0 #0/0
IMAP error: unexpected tag 100070
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/276 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 247 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/247 *0/0 #0/0
IMAP error: unexpected tag 100100
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/247 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 218 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/218 *0/0 #0/0
IMAP error: unexpected tag 100129
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/218 *0/0 #0/0

Running with the -D option shows a normal-looking trace, until the final few messages:

32 OK FETCH Completed
  -> new UID 132 on slave
* 133 FETCH (UID 100133 BODY[] {4680}
)
33 OK FETCH Completed
  -> new UID 133 on slave
* 134 FETCH (UID 100134 BODY[] {5072}
)
34 OK FETCH Completed
  -> new UID 134 on slave
100135 BAD Bad command.
IMAP error: unexpected tag 100135

How can I help debug this issue further?

[Clément Pit-Claudel]

I noticed one thing: the number of messages downloaded before crashing is always 29:

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 154 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/155 *0/0 #0/0
IMAP error: unexpected tag 100193
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/155 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 126 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/126 *0/0 #0/0
IMAP error: unexpected tag 100222
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/126 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 97 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/97 *0/0 #0/0
IMAP error: unexpected tag 100251
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/97 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 68 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/68 *0/0 #0/0
IMAP error: unexpected tag 100280
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/68 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 39 pulled message(s)
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +29/39 *0/0 #0/0
IMAP error: unexpected tag 100309
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +29/39 *0/0 #0/0

$ mbsync -a
C: 0/1  B: 0/1  M: +0/0 *0/0 #0/0  S: +0/0 *0/0 #0/0
Warning: lost track of 10 pulled message(s)
C: 1/1  B: 1/1  M: +0/0 *0/0 #0/0  S: +10/10 *0/0 #0/0

Exept in the first case where the S: counter reports 29, but the lost track of message reports a difference of 28 (154 to 126).

Does this make sense?

[Evgenij Smirnov]

Hi,

I am seeing this as well when trying to sync FROM a local MailDir store TO an on-premise Exchange 2013 server. Running mbsync 1.2.1 on Debian 8.

Anything I can contribute to the solution? Logs, Exchange settings, whatever?

Thanks

Evgenij

[Oswald Buddenhagen]

exchange is the only server this is happening with, and it's happening pretty consistently, for no apparent reason whatsoever. that's pretty good evidence that the server is simply broken.
it seems to have botched input buffering, either skipping or duplicating part of the data sent to it. if you find a way to dump raw data as seen by the server at different layers (socket, decrypted ssl, command tokenizer) and can correlate it with the corresponding logs from mbsync/your client machine, you may be able to deduce where to look for knobs to work around the issue. i'd be interested in the results as well.

[Matthieu Ov.]

For us the problem has been 'solved' by adding PipelineDepth 1 to the IMAPAccount section of our configuration file, in order to disable concurrent IMAP commands.

[Rostislav]

The trick with PipelineDepth helped to me as well.

[North Year]

Yes can confirm this tricks work for me. Despite that have no reason why before my mbsync worksed completely fine with (PipelineDepth = 50) and all of a sudden it does not work until I set it to 1

[Oswald Buddenhagen]

fwiw, the wip/exchange-workarounds-1.* branches contain prospective solutions to the issue(s).

[googlebleh]

thanks, I rebased wip/exchange-workarounds-1.4 onto master and it solves this for me

not sure if that's the most recent version of exchange workarounds. the code in -1.4 looks similar, but distinct from what's in -1.5

[Dominic Rodriguez]

I'm still experiencing this on 1.4.4, on NixOS with Microsoft 365, Exchange Online.

However, the tag errors actually look more like XML or HTML elements in debugging.

Anyone else experiencing this - or should I open a new bug?