sync_client errors

Wed Feb 26 03:18:21 EST 2014

Hello Bron and Cyrus Friends,

On Wed, Feb 26, 2014 at 08:41:15AM +1100, Bron Gondwana wrote:
> Sorry, on holiday. Phone only.
> 
> Looks like you might have corruption at one end, try reconstructing both ends. Also make sure you're not changing things on the replicas.
> 
> On Tue, Feb 25, 2014, at 10:39 PM, Willy Offermans wrote:
> > 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.
> > 
> > -- 

I have to admit that I ``messed'' around with the mails on the master
(replication side). I had a look into some of them and I deleted an older
one. You might blame for that, but I needed to figure out how robust the
system is. Though I do not know if the error message are related to my
``messing'' or the sudden reboot was the cause. I cannot relate the error
messages to my actions yet. Maybe I will introduce some more errors, but
one by one, to figure out how the system will react.

Can you elaborate on what will happen if one deletes a mail message on the
master and not on the client? If this is so critical, one might consider to
set the files read-only on the master, so that it is already a warning to
the user that it is not a good idea to delete one or the other file.

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

Willy

*************************************
 W.K. Offermans