sync_client errors

Wed Feb 26 03:09:04 EST 2014

Dear Marcus,

On Tue, Feb 25, 2014 at 08:20:39PM +0100, Marcus Schopen wrote:
> Am Dienstag, den 25.02.2014, 12:39 +0100 schrieb Willy Offermans:
> > 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.
> 
> Hi Willy,
> 
> I'm new in the cyrus replication world too. I use the good old Cyrus
> lady for several setups over the last 13 years, but never did the step
> to replication. But since two weeks I'm building up a master/slave setup
> for my own mailsytem. Therefore I'm very interested in a well working
> sync between master and relica slave. And you are right: a non working
> sync does not make any sense at all. For me it's a kind of hot stand by
> backup. I asked on the cyrus list a few days ago how to proof if master
> and replica are in good sync. See Bron's answer to "replication
> questions - best practice?" last week. This isn't really enterprise, but
> I don't want to move to postfix and dovcot right now. Hey, let's keep in
> touch and replicate experience ;)
> 
> What does "/var/imap/sync/log-74031" file says. 
> 
> Did you try a to run a "sync_client -u" on each user on the
> master server or just to the mailbox that is the problem?
> 
> Cheers from Bielefeld + Mit freundlichen Gruessen ;)
> Marcus
> 
> 

We will stay in contact. My story is quite similar to yours: I'm also using
cyrus for years now and I was only using the IMAP server part. I was and am
very pleased with cyrus IMAP. Now I want to make the step to replication and 
eventually to cyrus murder, if possible.

Thank you for pointing out "/var/imap/sync/log-74031". I was not aware it
was created on the client. Though the content was not very appealing:

cat /var/imap/sync/log-74031:
MAILBOX user.MyName
MAILBOX user.MyName

I do not know what to do with this info, since it is quite obvious to me.

Yesterday I have restarted the imap server on the client and the service is
seemingly running without any problems so far. I stress the word seemingly,
since I did not check if the replication is successful and I did not do
anything else than restarting the service. So if there were inconsistencies
before, then I have no clue if they were resolved. To me, there should be
some kind of mechanism to check if replication is successful. My idea would
be to create snapshots, calculate checksums and compare client with master.
If error than rebuild, else continue. Though I admit that I have no idea
how to put this into code. I could stop the cyrus imap services, calculate
the checksums and do the comparisons myself. However I'm not sure how to
stop the services without disturbing the replication mechanism. Regarding
my previous experiences, this is not trivial. Maybe someone can point out
how to stop sync_client in a secure way.

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

Willy

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