Replication : IMAP_PROTOCOL_ERROR Protocol error

Jean Charles Delépine delepine at u-picardie.fr
Wed Sep 23 11:44:38 EDT 2020


Hello,

I'm on the way to migrate one quite big murder config with Cyrus IMAP  
3.0.8-Debian-3.0.8-6+deb10u4
to Cyrus IMAP 3.2.3-Debian-3.2.3-1~bpo10+1.

My plan is to replicate 3.0.8's backends on 3.2.3 ones. This plan has  
work before for 2.5
to 3.0. migration.

Il can replicate empty mailboxes. So the conf (attached) seems ok.
But if the mailbox isn't empty here's the result (completes traces attached) :

cyrus/sync_client[3082351]: MAILBOX received NO response:  
IMAP_PROTOCOL_ERROR Protocol error
cyrus/sync_client[3082351]: do_folders(): update failed: user.t 'Bad protocol'
cyrus/sync_client[3082351]: IOERROR: do_user_main: Bad protocol for t  
to [no channel] (test-3.2.3)
Error from sync_do_user(t): bailing out!
cyrus/sync_client[3082351]: Error in sync_do_user(t): bailing out!

The destination server says :
    SYNCERROR: failed to parse uploaded record


If I upgrade this test server to 3.2.3-Debian-3.2.3-1~bpo10+1 with  
the same configuration, the same mailbox
can be sync whith the problem being corrected :


APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t  
SYNC_CRC 3435668400 SYNC_CRC_ANNOT 1359939586 LAST_UID 1 HIGHESTMODSEQ  
3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0  
POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION  
default ACL "" OPTIONS P FOLDERMODSEQ 3 SINCE_MODSEQ 3 SINCE_CRC 0  
SINCE_CRC_ANNOT 12345678 RECORD ())
<1600872848<NO IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: MAILBOX received NO response:  
IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: SYNC_NOTICE: CRC failure on sync user.t,  
recalculating counts and trying again

Error but retry.

MAILBOX user.t
> 1600872848>APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl  
> MBOXNAME user.t SYNC_CRC 3435668400 SYNC_CRC_ANNOT 1370712396  
> LAST_UID 1 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE  
> 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY  
> 1600855436 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 3 RECORD  
> ())
<1600872848<NO IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: MAILBOX received NO response:  
IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: CRC failure on sync for user.t, trying full update

Error then full update

FULLMAILBOX user.t
> 1600872848>GET FULLMAILBOX user.t
<1600872848<* MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME  
user.t SYNC_CRC 0 SYNC_CRC_ANNOT 12345678 LAST_UID 1 HIGHESTMODSEQ 3  
RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0  
POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION  
default ACL "" OPTIONS P FOLDERMODSEQ 3 RECORD ())
OK success
cyrus/sync_client[3131948]: user.t: same message appears twice 1 2
MAILBOX user.t
> 1600872849>APPLY MESSAGE (%{default  
> f0eeef2cc42f23884089760cf5de1961b358a498 2627}


)
<1600872849<OK success
> 1600872849>APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl  
> MBOXNAME user.t SYNC_CRC 1009437458 SYNC_CRC_ANNOT 455745080  
> LAST_UID 2 HIGHESTMODSEQ 5 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE  
> 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 5 UIDVALIDITY  
> 1600855436 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 3 RECORD  
> (%(UID 1 MODSEQ 5 LAST_UPDATED 1600872848 FLAGS (\Expunged)  
> INTERNALDATE 1600855652 SIZE 2627 GUID  
> f0eeef2cc42f23884089760cf5de1961b358a498 ANNOTATIONS (%(ENTRY  
> /vendor/cmu/cyrus-imapd/thrid USERID "" MODSEQ 0 VALUE  
> 611d36cdcf46289a))) %(UID 2 MODSEQ 4 LAST_UPDATED 1600872848 FLAGS  
> () INTERNALDATE 1600855652 SIZE 2627 GUID  
> f0eeef2cc42f23884089760cf5de1961b358a498 ANNOTATIONS (%(ENTRY  
> /vendor/cmu/cyrus-imapd/thrid USERID "" MODSEQ 0 VALUE  
> 611d36cdcf46289a)))))
<1600872849<OK success
MAILBOX user.t.Drafts
> 1600872849>APPLY MAILBOX %(UNIQUEID nckzm4o710aom3c22o9ugy6a  
> MBOXNAME user.t.Drafts SYNC_CRC 0 SYNC_CRC_ANNOT 0 LAST_UID 0  
> HIGHESTMODSEQ 2 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0  
> POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 2 UIDVALIDITY  
> 1600855557 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 2 RECORD  
> ())
<1600872849<OK success
> 1600872849>EXIT
<1600872849<OK Finished

Succes.


Is this a known problem corrected after 3.0.9 ?
Is there something I can do to successfully replicate my backends to  
my new servers ?

Sincerly,
     Jean Charles Delépine
-------------- next part --------------
configdirectory: /var/lib/cyrus
proc_path: /run/cyrus/proc
mboxname_lockpath: /run/cyrus/lock
defaultpartition: default
partition-default: /var/spool/cyrus/mail
partition-news: /var/spool/cyrus/news
newsspool: /var/spool/news
altnamespace: no
postuser: share-post
unixhierarchysep: no
lmtp_downcase_rcpt: yes
allowanonymouslogin: no
popminpoll: 1
autocreate_post: yes
autocreate_quota: 0
umask: 077
sieveusehomedir: false
sievedir: /var/spool/sieve
httpmodules: caldav carddav
hashimapspool: true
sasl_auto_transition: no
tls_client_ca_dir:
tls_session_timeout:
tls_versions:
lmtpsocket: /var/run/cyrus/socket/lmtp
idlesocket: /var/run/cyrus/socket/idle
notifysocket: /var/run/cyrus/socket/notify
syslog_prefix: cyrus
admins: mailadmin
metapartition_files: header index cache expunge squat annotations lock dav archivecache
metapartition-default: /var/lib/cyrus/metas
search_engine: xapian
search_index_headers: no
search_batchsize: 8192
defaultsearchtier: t1
t1searchpartition-default: /var/lib/cyrus/search
conversations: 1
allowapop: yes
allowplaintext: yes
sasl_minimum_layer: 0
sasl_pwcheck_method: auxprop
sasl_auxprop_plugin: sasldb
tls_client_ca_file:
tls_server_ca_dir:
tls_require_cert:
tls_client_certs:
tls_imap_require_cert:
tls_server_key:
tls_server_cert:
mupdate_server: test-mupdate
mupdate_username: admin
mupdate_authname: admin
mupdate_password: secret
proxyservers: admin
proxy_authname: admin
proxy_password: secret
serverlist: test-3.0.8
autocreate_inbox_folders: Trash|Templates|Sent|Draft|spam
autocreate_subscribe_folders: Trash|Templates|Sent|Draft|spam
specialuse_extra: Sent Trash Templates Drafts Junk
ldap_uri:
auth_mech: pts
ldap_sasl: 0
pts_module: ldap
ptloader_sock: /var/run/cyrus/socket/ptsock
ldap_filter:
ldap_base: 
ldap_group_base: 
ldap_group_filter:
ldap_member_method:
ldap_member_filter:
ldap_member_attribute:
ldap_member_base:
ldap_size_limit:
unix_group_enable: 1
proxyd_allow_status_referral: 0
sieve_allowreferrals: 0
allowusermoves: 1
duplicatesuppression: 0
allowallsubscribe: 1
anyoneuseracl: 0
idlemethod: 1
rfc3028_strict: 0
sieve_extensions: fileinto reject vacation vacation-seconds imapflags notify         envelope body relational regex subaddress copy date index imap4flags mailbox mboxmetadata servermetadata variables
sync_log: on
sync_log_channels: squatter
sync_host: test-3.2.3
sync_try_imap: 1
sync_authname: admin
sync_password: secret
-------------- next part --------------
cyrus/sync_client[3082351]: auditlog: proxy  sessionid=<cyrus-3082351-1600855733-1-3699875182382045289> remote=<unknown>
>1600855733>COMPRESS DEFLATE
<1600855733<OK DEFLATE active
USER t
>1600855733>GET USER t
<1600855733<OK success
MAILBOX user.t
>1600855733>APPLY MESSAGE (%{default f0eeef2cc42f23884089760cf5de1961b358a498 2627}
Return-Path: <xxxxxxxxxxxxxx at u-picardie.fr>

[... some mail ]

)
<1600855733<OK success
>1600855733>APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t SYNC_CRC 3435668400 SYNC_CRC_ANNOT 1359939586 LAST_UID 1 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION default ACL "" OPTIONS P RECORD (%(UID 1 MODSEQ 3 LAST_UPDATED 1600855676 FLAGS () INTERNALDATE 1600855652 SIZE 2627 GUID f0eeef2cc42f23884089760cf5de1961b358a498 ANNOTATIONS (%(ENTRY /vendor/cmu/cyrus-imapd/thrid USERID NIL VALUE 611d36cdcf46289a)))))
<1600855733<NO IMAP_PROTOCOL_ERROR Protocol error
cyrus/sync_client[3082351]: MAILBOX received NO response: IMAP_PROTOCOL_ERROR Protocol error
cyrus/sync_client[3082351]: do_folders(): update failed: user.t 'Bad protocol'
cyrus/sync_client[3082351]: IOERROR: do_user_main: Bad protocol for t to [no channel] (test-3.2.3)
Error from sync_do_user(t): bailing out!
cyrus/sync_client[3082351]: Error in sync_do_user(t): bailing out!
>1600855733>EXIT
<1600855733<OK Finished
-------------- next part --------------
cyrus/sync_client[3131948]: auditlog: proxy  sessionid=<cyrus-1600872848-3131948-1-16497104278621810399> remote=<unknown>
>1600872848>COMPRESS DEFLATE
<1600872848<OK DEFLATE active
USER t
>1600872848>GET USER t
<1600872848<* MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t SYNC_CRC 0 SYNC_CRC_ANNOT 12345678 LAST_UID 0 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION default ACL "" OPTIONS P CREATEDMODSEQ 3 FOLDERMODSEQ 3)
OK success
cyrus/sync_client[3131948]: skiplist: recovered /var/lib/cyrus/user/t/t.conversations (8 records, 1184 bytes) in 0 seconds
cyrus/sync_client[3131948]: skiplist: checkpointed /var/lib/cyrus/user/t/t.conversations (8 records, 796 bytes) in 0.002 sec
>1600872848>APPLY RESERVE %(PARTITION default MBOXNAME (user.t) GUID (f0eeef2cc42f23884089760cf5de1961b358a498))
<1600872848<* MISSING (f0eeef2cc42f23884089760cf5de1961b358a498)
OK success
MAILBOX user.t
>1600872848>APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t SYNC_CRC 3435668400 SYNC_CRC_ANNOT 1359939586 LAST_UID 1 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 3 SINCE_MODSEQ 3 SINCE_CRC 0 SINCE_CRC_ANNOT 12345678 RECORD ())
<1600872848<NO IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: MAILBOX received NO response: IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: SYNC_NOTICE: CRC failure on sync user.t, recalculating counts and trying again
MAILBOX user.t
>1600872848>APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t SYNC_CRC 3435668400 SYNC_CRC_ANNOT 1370712396 LAST_UID 1 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 3 RECORD ())
<1600872848<NO IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: MAILBOX received NO response: IMAP_SYNC_CHECKSUM Checksum Failure
cyrus/sync_client[3131948]: CRC failure on sync for user.t, trying full update
FULLMAILBOX user.t
>1600872848>GET FULLMAILBOX user.t
<1600872848<* MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t SYNC_CRC 0 SYNC_CRC_ANNOT 12345678 LAST_UID 1 HIGHESTMODSEQ 3 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 3 UIDVALIDITY 1600855436 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 3 RECORD ())
OK success
cyrus/sync_client[3131948]: user.t: same message appears twice 1 2
MAILBOX user.t
>1600872849>APPLY MESSAGE (%{default f0eeef2cc42f23884089760cf5de1961b358a498 2627}
Return-Path: <xxxxxxxxxxxxxxxx at u-picardie.fr>


)
<1600872849<OK success
>1600872849>APPLY MAILBOX %(UNIQUEID 6kjf8ro4032wfjefcdewaqyl MBOXNAME user.t SYNC_CRC 1009437458 SYNC_CRC_ANNOT 455745080 LAST_UID 2 HIGHESTMODSEQ 5 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 5 UIDVALIDITY 1600855436 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 3 RECORD (%(UID 1 MODSEQ 5 LAST_UPDATED 1600872848 FLAGS (\Expunged) INTERNALDATE 1600855652 SIZE 2627 GUID f0eeef2cc42f23884089760cf5de1961b358a498 ANNOTATIONS (%(ENTRY /vendor/cmu/cyrus-imapd/thrid USERID "" MODSEQ 0 VALUE 611d36cdcf46289a))) %(UID 2 MODSEQ 4 LAST_UPDATED 1600872848 FLAGS () INTERNALDATE 1600855652 SIZE 2627 GUID f0eeef2cc42f23884089760cf5de1961b358a498 ANNOTATIONS (%(ENTRY /vendor/cmu/cyrus-imapd/thrid USERID "" MODSEQ 0 VALUE 611d36cdcf46289a)))))
<1600872849<OK success
MAILBOX user.t.Drafts
>1600872849>APPLY MAILBOX %(UNIQUEID nckzm4o710aom3c22o9ugy6a MBOXNAME user.t.Drafts SYNC_CRC 0 SYNC_CRC_ANNOT 0 LAST_UID 0 HIGHESTMODSEQ 2 RECENTUID 0 RECENTTIME 0 LAST_APPENDDATE 0 POP3_LAST_LOGIN 0 POP3_SHOW_AFTER 0 XCONVMODSEQ 2 UIDVALIDITY 1600855557 PARTITION default ACL "" OPTIONS P FOLDERMODSEQ 2 RECORD ())
<1600872849<OK success
>1600872849>EXIT
<1600872849<OK Finished


More information about the Info-cyrus mailing list