sync_client -r stops working after several minutes

[Olaf Frączyk]

Hi,

cyrus-imapd 3.0.13, CentOS 8

replication over IMAP, no sync_server

I try to find out why rolling replication is failing in my case. They 
sync_client -A works fine.

I have enabled logging for cyrus_admin in /var/lib/imap/log/cyrus_admin

On the replica side /var/lib/imap/log/cyrus_admin:

 >1588340782>S8 OK success
<1588340782<S9 SYNCRESTART
 >1588340782>S9 OK Restarting
<1588341098<S10 SYNCGET MAILBOXES (navi.pl!user.info.Junk)
 >1588341098>* MAILBOX %(UNIQUEID 7f969c134bd149a0 MBOXNAME 
navi.pl!user.info.Junk SYNC_CRC 1665461165 SYNC_CRC_ANNOT 0 LAST_UID 
67313 HIGHESTMODSEQ 158640 RECENTUID 67252 REC
ENTTIME 1588266136 LAST_APPENDDATE 1588339875 POP3_LAST_LOGIN 0 
POP3_SHOW_AFTER 0 UIDVALIDITY 1272007072 PARTITION default ACL 
"info at navi.pl      lrswipkxtecda   " OPTIONS P
ANNOTATIONS (%(ENTRY /specialuse USERID info at navi.pl VALUE {5}
\Junk)))
S10 OK success
<1588341098<S11 SYNCRESTART
 >1588341098>S11 OK Restarting
<1588341098<N01 NOOP

On the master side:

The end of strace -f /usr/local/cyrus-3.0.13/sbin/sync_client -r:

stat("/var/local/imapd_sync_stop", 0x7ffe1a0106b0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log-run", 0x7ffe1a0105c0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log", 0x7ffe1a0105c0) = -1 ENOENT (No such file 
or directory)
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe1a010630) = 0
stat("/var/local/imapd_sync_stop", 0x7ffe1a0106b0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log-run", 0x7ffe1a0105c0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log", 0x7ffe1a0105c0) = -1 ENOENT (No such file 
or directory)
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe1a010630) = 0
stat("/var/local/imapd_sync_stop", 0x7ffe1a0106b0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log-run", 0x7ffe1a0105c0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log", 0x7ffe1a0105c0) = -1 ENOENT (No such file 
or directory)
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe1a010630) = 0
stat("/var/local/imapd_sync_stop", 0x7ffe1a0106b0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log-run", 0x7ffe1a0105c0) = -1 ENOENT (No such 
file or directory)
stat("/var/lib/imap/sync/log", {st_mode=S_IFREG|0600, st_size=61, ...}) = 0
rename("/var/lib/imap/sync/log", "/var/lib/imap/sync/log-run") = 0
openat(AT_FDCWD, "/var/lib/imap/sync/log-run", O_RDWR) = 11
fcntl(11, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, 
l_len=0}) = 0
fcntl(11, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, 
l_len=0}) = 0
read(11, "APPEND navi.pl!user.info.Junk\nMA"..., 4096) = 61
read(11, "", 4096)                      = 0
write(8, 
"\27\3\3\0A\t*\315\322y\376XR\"\203\234\335\1\346-\v\21\231\36\30\232Q\233\272\264\370\275"..., 
70) = 70
rt_sigprocmask(SIG_BLOCK, [INT QUIT ALRM TERM CHLD], [], 8) = 0
pselect6(9, [8], NULL, NULL, {tv_sec=0, tv_nsec=0}, {[], 8}) = 0 (Timeout)
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
getpid()                                = 32350
sendto(9, "<179>May  1 15:51:38 sync_client"..., 103, MSG_NOSIGNAL, 
NULL, 0) = 103
write(8, 
"\27\3\3\0\"I\26*2S\3548>\n\375\338\30\333\334\334%\3417\350eR\227\35\305\201W"..., 
39) = 39
getpid()                                = 32350
sendto(9, "<179>May  1 15:51:38 sync_client"..., 101, MSG_NOSIGNAL, 
NULL, 0) = 101
getpid()                                = 32350
sendto(9, "<179>May  1 15:51:38 sync_client"..., 86, MSG_NOSIGNAL, NULL, 
0) = 86
getpid()                                = 32350
sendto(9, "<179>May  1 15:51:38 sync_client"..., 113, MSG_NOSIGNAL, 
NULL, 0) = 113
close(11)                               = 0
write(8, 
"\27\3\3\0\33\375R\225I\325\271\215~\24\311\224\272\235g\326\206$?\226\203\261\23\247\24\206\270n", 
32) = 32
shutdown(8, SHUT_RD)                    = 0
close(8)                                = 0
close(7)                                = 0
munmap(0x7fe2e72dc000, 16384)           = 0
close(6)                                = 0
munmap(0x7fe2e72be000, 40960)           = 0
close(4)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

 From /var/log/messages:

May  1 15:37:43 skink1 sync_client[32113]: Processing sync log file 
/var/lib/imap/sync/log-run failed: Bad protocol
May  1 15:46:21 skink1 sync_client[32350]: auditlog: proxy 
sessionid=<skink1.local.navi.pl-32350-1588340781-1-1476878003266237912> 
remote=<unknown>
May  1 15:46:21 skink1 sync_client[32350]: Reprocessing sync log file 
/var/lib/imap/sync/log-run
May  1 15:51:38 skink1 sync_client[32350]: IOERROR: zero length response 
to MAILBOXES (idle for too long)
May  1 15:51:38 skink1 sync_client[32350]: IOERROR: zero length response 
to RESTART (idle for too long)
May  1 15:51:38 skink1 sync_client[32350]: Error in do_sync(): bailing 
out! Bad protocol
May  1 15:51:38 skink1 sync_client[32350]: Processing sync log file 
/var/lib/imap/sync/log-run failed: Bad protocol

What can I do more to find what causes this problem?

Best regards,

Olaf


-- 
NAVI Sp. z o.o.
Promienista 5/1
60-288 Poznań

mobile: +48609769035
phone: +48616622881
fax: +48616622882
http://www.navi.pl