Fails with "bad command" on some mails when syncing O365
mailbox synchronizer
Brought to you by:
ossi
Menu
▾
▴
#63 Fails with "bad command" on some mails when syncing O365
Syncing a mailbox on O365, mbsync fails to sync certain mails with "IMAP error: unexpected tag <meta".
Here is the output of -Dn when syncing the folder (I removed a lot of the FETCH (UID xxx) lines as there were no errors there and to make it easier to get an overview):
Reading configuration file /home/peter/.mbsyncrc Channel speartail-channel-archive Opening far side store speartail-remote... Resolving outlook.office365.com... ok Connecting to outlook.office365.com (40.100.29.210:993)... Opening near side store speartail-local... Connection is now encrypted * OK The Microsoft Exchange IMAP4 service is ready. [UwBHADIAUABSADAAMQBDAEEAMAAxADAAMgAuAGEAcABjAHAAcgBkADAAMQAuAHAAcgBvAGQALgBlAHgAYwBoAGEAbgBnAGUAbABhAGIAcwAuAGMAbwBtAA==] >>> 1 CAPABILITY * CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+ 1 OK CAPABILITY completed. Logging in... Authenticating with SASL mechanism PLAIN... >>> 2 AUTHENTICATE PLAIN <authdata> 2 OK AUTHENTICATE completed. >>> 3 NAMESPACE * NAMESPACE (("" "/")) NIL NIL 3 OK NAMESPACE completed. Opening far side box Archive... >>> 4 SELECT "Archive" Opening near side box archive... * 9489 EXISTS * 0 RECENT * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent) * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags * OK [UNSEEN 44] Is the first unseen message * OK [UIDVALIDITY 255] UIDVALIDITY value * OK [UIDNEXT 9600] The next unique identifier value 4 OK [READ-WRITE] SELECT completed. Loading far side box... >>> 5 UID FETCH 1:9599 (UID FLAGS) Loading near side box... near side: 9536 messages, 2088 recent * 1 FETCH (UID 2 FLAGS (\Seen)) * 2 FETCH (UID 3 FLAGS (\Seen)) * 3 FETCH (UID 4 FLAGS (\Seen)) * 4 FETCH (UID 5 FLAGS (\Seen)) * 5 FETCH (UID 6 FLAGS (\Seen)) <snip> * 9478 FETCH (UID 9587 FLAGS (\Seen)) * 9479 FETCH (UID 9588 FLAGS (\Seen \Answered)) * 9480 FETCH (UID 9589 FLAGS (\Seen)) * 9481 FETCH (UID 9590 FLAGS (\Seen)) * 9482 FETCH (UID 9591 FLAGS (\Seen)) * 9483 FETCH (UID 9592 FLAGS (\Seen)) * 9484 FETCH (UID 9593 FLAGS (\Seen)) * 9485 FETCH (UID 9594 FLAGS ()) * 9486 FETCH (UID 9595 FLAGS ()) * 9487 FETCH (UID 9596 FLAGS ()) * 9488 FETCH (UID 9597 FLAGS ()) * 9489 FETCH (UID 9598 FLAGS ()) 5 OK FETCH completed. far side: 9489 messages, 0 recent Synchronizing... Notice: far side store does not support flag(s) 'P'; not propagating. >>> 6 APPEND "Archive" "06-Dec-2021 09:29:20 +0800" {21411+} <meta BAD Command Error. 10
The "<meta" part is obviously part of the message body which is evident by running with "-DN" (I have cut out a lot of the actual message but hopefully left enough to troubleshoot it):
* 9489 FETCH (UID 9598 FLAGS ())
5 OK FETCH completed.
far side: 9489 messages, 0 recent
Synchronizing...
Notice: far side store does not support flag(s) 'P'; not propagating.
>>> 6 APPEND "Archive" "06-Dec-2021 09:29:20 +0800" {21411+}
>>>>>>>>>
Received: from TYZPR02MB4910.apcprd02.prod.outlook.com (2603:1096:400:5b::11)
by SG2PR02MB3530.apcprd02.prod.outlook.com with HTTPS; Mon, 6 Dec 2021
01:29:19 +0000
=?utf-8?B?cjZRa0ZYc1YxblVRUXJnSlNzZ09HQ3ltL0E9PQ==?=
MIME-Version: 1.0
X-TUID: qIbtM31tb6Y7
<!DOCTYPE html><html><head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8"><title></title></head>
>>>>>>>>>
<meta BAD Command Error. 10
The strange thing is that the problem seems to be introduced by syncing 2 machines. It appears as follows:
- machine A and B are not (yet) syncing the mailbox.
- I start syncing machine A
- reading and sending mails all OK
- syncing works fine
- I then start syncing machine B (exact same configuration)
- after making local changes to the mailbox, the error will start showing on machine B
- I then blow away the local store on machine B and resync
- machine B is now OK, but machine A will start throwing the "BAD command" error
- if I repeat the wipe and resync on machine A, it is now syncing OK but machine B will start with "BAD Command"
I understand that Exchange in general is a pain but it's what we use for $WORK. Anything to try from here?
Setting PipelineDepth 1 as mentioned elsewhere doesn't make any difference.
duplicate of bug #22 (and numerous reports on the mailing list).
nothing to be done about it so far. it appears random, so if you keep retrying, mbsync will complete successfully at some point.
I did see #22 but that error is "unexpected tag" and this is why I opened this ticket instead.
We moved to O365 about 3 months ago. mbsync runs every 10 minutes but at no point during this time did it complete.
Any suggestions for anything to try?
now that you mention it, yes - you can give the contributed wip/exchange-workarounds branch a shot. note that it is a mess and may eat your puppies. also, it's quite outdated - if you want to live even more dangerously, try wip/exchange-workarounds-1.4 (compile-tested only).
I took the easy/safe way out - have mbsync talk to davmail instead as that seems to work.
Just to add one thing - with davmail, syncing is significantly slower but at least it works.