sync_client errors

Tue Feb 25 06:39:04 EST 2014

Dear Friends,

On Mon, Feb 24, 2014 at 01:17:30PM +0100, Willy Offermans wrote:
> Dear cyrus Friends,
> 
> I'm testing the replication option of cyrus. I have rebooted the ``master''
> several times yesterday, but for reasons __not__ related to cyrus. Today I
> figured out that replication was not working as expected. I tried to
> restart replication by ``service imapd restart'' on both servers. I noticed
> some action, but replication stopped once more. I found the following in my
> logs.
> 
> A snippet from my logs:
> 
> <snip>
> ...
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22755 modseq:38813 last_updated:1393151348 internaldate:1393144202 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22755 modseq:38809 last_updated:1393167405 internaldate:1393144202 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22756 modseq:38813 last_updated:1393151348 internaldate:1393144788 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22756 modseq:38809 last_updated:1393167405 internaldate:1393144788 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22757 modseq:38813 last_updated:1393151348 internaldate:1393145814 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22757 modseq:38809 last_updated:1393167405 internaldate:1393145814 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:4057 modseq:38831 last_updated:1393167452 internaldate:1348384486 flags:( Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:4057 modseq:6809 last_updated:1348464157 internaldate:1348384486 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22222 (75fa289b62e23664f3cc00a11254191f65e50163)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22378 modseq:38842 last_updated:1393187494 internaldate:1392368284 flags:( Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22378 modseq:38160 last_updated:1392369039 internaldate:1392368284 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22742 (639836573eacee96d0a61c086b39c155e63b6dfa)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22743 modseq:38813 last_updated:1393151348 internaldate:1393095204 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22743 modseq:38809 last_updated:1393167405 internaldate:1393095204 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22744 (c85e24343dd16d5fd655ac674067382572318e29)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22745 (6df887eaa626a616e19def3affe42078d57d498b)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22746 (0698384acd5a6a8a06eae3cce1d279e0057f1935)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22747 (29d274001b7040613246d44d6848087df431f716)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22748 (e1860bb01952383639b74fb02ccc9f50674a3077)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22749 (439b4c69a007cf092c005e481dfa30bc3e1c2d95)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22750 (4da4738844df0aa502b33b392dc974954c0be05f)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22751 (40b39f7b075fec8288da1a63d63e83fc11c42b50)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22752 (c8428171c53dc75194e87fa14e9e2749b6bb95d4)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22753 (19d7127f51a9f54db9dc5c5caa49d1bfbc86bb07)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22754 (c99fde22cfb9fdd85c20f24b9154059f8c2c97f7)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22755 modseq:38813 last_updated:1393151348 internaldate:1393144202 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22755 modseq:38809 last_updated:1393167405 internaldate:1393144202 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22756 modseq:38813 last_updated:1393151348 internaldate:1393144788 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22756 modseq:38809 last_updated:1393167405 internaldate:1393144788 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: record mismatch with replica: user.username more recent on master
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: master uid:22757 modseq:38813 last_updated:1393151348 internaldate:1393145814 flags:(\Seen)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCNOTICE: replica uid:22757 modseq:38809 last_updated:1393167405 internaldate:1393145814 flags:(Old)
> Feb 24 13:02:20 MyClient sync_client[74031]: SYNCERROR: only exists on replica user.username 22758 (6455f52ef18c488d48a3bc0feddfeff39eb7a119)
> Feb 24 13:07:24 MyClient imaps[74049]: DENYDB_ERROR: opening /var/imap/user_deny.db: cyrusdb error
> Feb 24 13:07:24 MyClient imaps[74049]: imapd:Loading hard-coded DH parameters
> Feb 24 13:07:24 MyClient imaps[74049]: starttls: TLSv1 with cipher DHE-RSA-AES128-SHA (128/128 bits new) no authentication
> Feb 24 13:07:24 MyClient imaps[74049]: OTP unavailable because can't read/write key database /etc/opiekeys: Permission denied
> Feb 24 13:07:28 MyClient imaps[74049]: badlogin: squid.vpn.offrom.nl [10.168.0.72] DIGEST-MD5 [SASL(-13): authentication failure: client response doesn't match what we generated (tried bogus)]
> Feb 24 13:07:31 MyClient imaps[74049]: login: squid.vpn.offrom.nl [10.168.0.72] username plaintext+TLS User logged in SESSIONID=<MyClient.offrom.nl-74049-1393243644-1>
> Feb 24 13:07:31 MyClient imaps[74049]: OTP unavailable because can't read/write key database /etc/opiekeys: Permission denied
> Feb 24 13:07:52 MyClient imaps[74049]: Expunged 1 messages from user.username
> Feb 24 13:07:53 MyClient sync_client[74031]: Error in do_sync(): bailing out!  Bad protocol
> Feb 24 13:07:53 MyClient sync_client[74031]: Processing sync log file /var/imap/sync/log-74031 failed: Bad protocol
> ...
> </snip>
> 
> What does it mean and how can I solve it?
> 
> 

Has anyone a clue? Replication needs to be really reliable. Otherwise it
makes no sense to use it.

-- 
Met vriendelijke groeten,
With kind regards,
Mit freundlichen Gruessen,

Willy

*************************************
 W.K. Offermans
Home:   +31 45 544 49 44
Mobile: +31 681 15 87 68
e-mail: Willy at Offermans.Rompen.nl