Re: 3.0 to 3.2 sync error

Quoting Lists Nethead <[email protected]>:

> Quoting ellie timoney <[email protected]>:
>
>> Hi,
>>
>> On Sun, 29 Aug 2021, at 8:28 PM, Lists Nethead wrote:
>>> 29392: write(6,"S2 SYNCAPPLY MAILBOX %(UNIQUEID
>>> 6uxzsiuvofrhrf69dfs1uqxq MBOXNAME user.ppgw SYNC_CRC 2538953411
>>> SYNC_CRC_ANNOT 307862686 LAST_UI"...,4096) = 4096 (0x1000)
>>> 29392: write(6,"ATIONS (%(ENTRY /vendor/cmu/cyrus-imapd/thrid USERID
>>> NIL VALUE 87f494ec1d410ff7))) %(UID 18 MODSEQ 194 LAST_UPDATED
>>> 1620897300 F"...,4096) = 4096 (0x1000)
>>> 29392: write(6,"12 LAST_UPDATED 1620897300 FLAGS () INTERNALDATE
>>> 1608458977 SIZE 58108 GUID 03fd1fb95a2083a702fcf679a0e62182698ea1f8
>>> ANNOTATIONS"...,1984) = 1984 (0x7c0)
>>
>> It's hard to see what it might be complaining about, since the "S2  
>> SYNCAPPLY ..." command it's trying to send is 4096+4096+1984 bytes  
>> long, and is heavily abbreviated in the strace output.
>>
>> You can log what's actually going over the wire by enabling  
>> telemetry for the user:  
>> https://www.cyrusimap.org/imap/reference/faqs/o-telemetry.html
>>
>> In this case, you would want to set up telemetry on your replica  
>> server, for the user named by "sync_authname" on your main server.   
>> This will make the replica log all the replication traffic it  
>> receives.
>>
>> If you can reproduce the bad protocol error by replicating just one  
>> test folder for one test user, then that's probably the least-noisy  
>> way to proceed, and without worry about exposing anyone's mail  
>> contents.
>>
>> But if you can't reproduce it with a test folder in a test account,  
>> then it might be something specific to the user or mailbox that's  
>> causing the problem, which will be harder to figure out...
>>
>> Anyway, the first step is capturing some telemetry.
>
> Thanks Ellie.
>
> Here are the last few lines, I am beginning to suspect annotations  
> but not sure how to confirm that.
>
> ANNOTATIONS (%(ENTRY /vendor/cmu/cyrus-imapd/thrid USERID NIL VALUE  
> 7ab060a0e7c08e7b))) %(UID 87 MODSEQ 305 LAST_UPDATED 1630308444  
> FLAGS () INTERNALDATE 1620030552 SIZE 33909 GUID  
> ce481eab9195672b58f75b35b299cdeb78cdde5d ANNOTATIONS (%(ENTRY  
> /vendor/cmu/cyrus-imapd/thrid USERID NIL VALUE 5fbbc74a9afc6c39)))  
> %(UID 88 MODSEQ 307 LAST_UPDATED 1630308444 FLAGS () INTERNALDATE  
> 1629118361 SIZE 33891 GUID bc12963d4fb6657d281a077d8b983450e838ba1e  
> ANNOTATIONS (%(ENTRY /vendor/cmu/cyrus-imapd/thrid USERID NIL VALUE  
> 2de14f<1630308446<dc44df6e6f)))))
>> 1630308446>S5 NO IMAP_PROTOCOL_ERROR Protocol error
> <1630308446<Q01 LOGOUT
>
>

truss output:

55181: fstatat(AT_FDCWD,"/var/spool/imap/user/ppgw/cyrus.index",{  
mode=-rw------- ,inode=211932,size=160,blksize=4096 },0x0) = 0 (0x0)
55181:  
openat(AT_FDCWD,"/var/spool/imap/user/ppgw/cyrus.header",O_RDONLY,00)  
= 13 (0xd)
55181: fstat(13,{ mode=-rw------- ,inode=211933,size=208,blksize=4096  
}) = 0 (0x0)
55181: mmap(0x0,208,PROT_READ,MAP_SHARED,13,0x0) = 34386997248 (0x8019ff000)
55181: munmap(0x8019ff000,208)                   = 0 (0x0)
55181: fcntl(11,F_SETLKW,0x7fffffff9da0)         = 0 (0x0)
55181: fstat(11,{ mode=-rw------- ,inode=510188,size=976,blksize=4096  
}) = 0 (0x0)
55181: fstatat(AT_FDCWD,"/var/imap/mailboxes.db",{ mode=-rw-------  
,inode=510188,size=976,blksize=4096 },0x0) = 0 (0x0)
55181: fcntl(11,F_SETLKW,0x7fffffff9f70)         = 0 (0x0)
55181:  
openat(AT_FDCWD,"/var/spool/imap/user/ppgw/cyrus.annotations",O_RDWR,00) = 14  
(0xe)
55181: fstat(14,{ mode=-rw------- ,inode=211934,size=336,blksize=4096  
}) = 0 (0x0)
55181: mmap(0x0,16384,PROT_READ,MAP_SHARED,14,0x0) = 34394439680 (0x802118000)
55181: fcntl(14,F_SETLKW,0x7fffffff9cb0)         = 0 (0x0)
55181: fstat(14,{ mode=-rw------- ,inode=211934,size=336,blksize=4096  
}) = 0 (0x0)
55181:  
fstatat(AT_FDCWD,"/var/spool/imap/user/ppgw/cyrus.annotations",{  
mode=-rw------- ,inode=211934,size=336,blksize=4096 },0x0) = 0 (0x0)
55181: fcntl(14,F_SETLKW,0x7fffffff9e80)         = 0 (0x0)
55181: __sysctl("kern.hostname",2,0x7fffffff9ce0,0x7fffffff8f88,0x0,0)  
= 0 (0x0)
55181: getpid()                                  = 55181 (0xd78d)
55181: sendto(5,"<179>1 2021-08-30T16:42:25.499504+02:00  
head.h.nethead.se imap 55181 - - SYNCERROR: failed to parse uploaded  
record",115,0,NULL,0) = 115 (0x73)
55181: close(14)



------------------------------------------
Cyrus: Info
Permalink: https://cyrus.topicbox.com/groups/info/Te28e46bb80b596a6-M38d0f7548904e94a5fade194
Delivery options: https://cyrus.topicbox.com/groups/info/subscription