Sync_client fails after upgrade 2.3.16 to 2.4.4
Chris Conn
cconn at abacom.com
Mon Nov 29 09:52:33 EST 2010
> As for your earlier errors...
>
> There is a bug with sync_crc calculation in 2.4.4, so I would recommend
> waiting for 2.4.5 before upgrading again. I'm hoping we can release
> 2.4.5 very soon, and Kolab will be building their RPMs pretty quickly
> too I imagine.
Hello,
I'm hoping that this version will fix my issue with replication I posted
to the list a few days back. I am going to build 2.4.5 today.
What I am seeing is that replication goes bonkers at 04:02 when the
servers replicating to each other send their logrotate messages, I start
having CRC check issues, no mailbox found errors and everything barfs.
Both servers are sending that inane log scan message to the same
mailbox, whatever the root alias is.
What is most interesting is that the replication seems stuck on a
message it sync'ed hours ago, trying to append to the existing file that
from what I can tell is identical on both servers. Reconstructing does
nothing, I have to unlink manually the file in the mailbox in question,
reconstruct, and then things start working again.
master:
Nov 29 04:02:23 node1 syncserver[2920]: Unlinking files in mailbox user.user
Nov 29 04:02:23 node1 syncserver[2920]: IOERROR: failed to parse
/var/spool/imap/sync./2920/397912d729863f46f208e21bdfe6e71d44293f9c
Nov 29 04:02:23 node1 syncserver[2920]: Failed to append file user.user 12
Nov 29 04:02:23 node1 syncserver[2920]: Unlinking files in mailbox user.user
Nov 29 04:02:23 node1 syncserver[2920]: IOERROR: failed to parse
/var/spool/imap/sync./2920/397912d729863f46f208e21bdfe6e71d44293f9c
Nov 29 04:02:23 node1 syncserver[2920]: Failed to append file user.user 12
Nov 29 04:02:23 node1 syncserver[2920]: Unlinking files in mailbox user.user
Nov 29 04:02:45 node1 sync_client[4111]: MAILBOX received NO response:
IMAP_MAILBOX_CRC Checksum Failure
Nov 29 04:02:45 node1 sync_client[4111]: CRC failure on sync for
user.user, trying full update
Nov 29 04:02:45 node1 sync_client[4111]: FETCH received NO response:
IMAP_MAILBOX_NONEXISTENT No Such Mailbox
Nov 29 04:02:45 node1 sync_client[2867]: process 4111 exited, signaled
to death by 6
reconstruct, and restart;
Nov 29 04:14:25 node1 syncserver[14811]: IOERROR: failed to parse
/var/spool/imap/sync./14811/397912d729863f46f208e21bdfe6e71d44293f9c
Nov 29 04:14:25 node1 syncserver[14811]: Failed to append file user.user 12
Nov 29 04:14:25 node1 syncserver[14811]: IOERROR: failed to parse
/var/spool/imap/sync./14811/397912d729863f46f208e21bdfe6e71d44293f9c
Nov 29 04:14:25 node1 syncserver[14811]: Failed to append file user.user 12
Nov 29 04:16:17 node1 reconstruct[14815]: user.cconn: updating sync_crc
F1B0079E => CD1D60AD
Nov 29 04:16:17 node1 reconstruct[14815]: user.user uid 21 found - adding
Nov 29 04:16:36 node1 sync_client[14786]: MAILBOX received NO response:
IMAP_MAILBOX_CRC Checksum Failure
Nov 29 04:16:36 node1 sync_client[14786]: CRC failure on sync for
user.user, trying full update
Nov 29 04:16:36 node1 sync_client[14786]: RECORD MISMATCH WITH REPLICA:
more recent on master
Nov 29 04:16:36 node1 sync_client[14786]: master uid:21 modseq:41
last_updated:1291022177 internaldate:1291021330 flags:()
Nov 29 04:16:36 node1 sync_client[14786]: replica uid:21 modseq:40
last_updated:1291021330 internaldate:1291021330 flags:()
Nov 29 04:16:36 node1 sync_client[14786]: FETCH received NO response:
IMAP_MAILBOX_NONEXISTENT No Such Mailbox
Nov 29 04:16:36 node1 sync_client[14785]: process 14786 exited, signaled
to death by 6
Nov 29 04:17:54 node1 reconstruct[14825]: user.user uid 21 future modseq
44 found
Nov 29 04:17:54 node1 reconstruct[14825]: user.user: updating sync_crc
1C12D0ED => 704AAD12
slave:
Nov 29 04:02:32 node2 lmtpunix[30017]: duplicate_check:
<201011290902.oAT92E6B029971 at node2.voip.b2b2c.ca> user.user 0
Nov 29 04:02:32 node2 lmtpunix[30017]: Delivered:
<201011290902.oAT92E6B029971 at node2.voip.b2b2c.ca> to mailbox: user.user
Nov 29 04:02:32 node2 lmtpunix[30017]: duplicate_mark:
<201011290902.oAT92E6B029971 at node2.voip.b2b2c.ca> user.user
1291021352 23
Nov 29 04:02:33 node2 lmtpunix[30017]: USAGE user user: 0.024996 sys:
0.029995
Nov 29 04:02:33 node2 sendmail[30157]: oAT92Un4030155:
to=<root at node2.voip.b2b2c.ca>, delay=00:00:02, xdelay=00:00:01,
mailer=cyrusv2, pri=120873, relay=localhost, dsn=2.0.0, stat=Sent
Nov 29 04:02:45 node2 syncserver[28463]: higher modseq on replica
user.user - 40 < 42
reconstruct and restart;
Nov 29 04:16:04 node2 reconstruct[7875]: reconstructing user.cconn
Nov 29 04:16:04 node2 reconstruct[7875]: user.cconn: updating sync_crc
F1B0079E => CD1D60AD
Nov 29 04:16:04 node2 reconstruct[7875]: reconstructing user.cconn.Sent
Nov 29 04:16:04 node2 reconstruct[7875]: reconstructing user.cconn.Trash
Nov 29 04:16:05 node2 reconstruct[7875]: reconstructing user.cconn2
Nov 29 04:16:05 node2 reconstruct[7875]: reconstructing user.cyrus
Nov 29 04:16:05 node2 reconstruct[7875]: reconstructing user.user
Nov 29 04:16:36 node2 syncserver[7865]: higher modseq on replica
user.user - 41 < 43
Nov 29 04:19:07 node2 sync_client[17881]: MAILBOX received NO response:
IMAP_MAILBOX_CRC Checksum Failure
Nov 29 04:19:07 node2 sync_client[17881]: do_folders(): update failed:
user.user 'Mailbox format corruption detected'
Nov 29 04:19:07 node2 sync_client[17881]: MAILBOX received NO response:
IMAP_MAILBOX_CRC Checksum Failure
Nov 29 04:19:07 node2 sync_client[17881]: CRC failure on sync for
user.user, trying full update
Nov 29 04:19:07 node2 sync_client[17881]: IOERROR: opening
/var/spool/imap/u/user/user/22.: No such file or directory
Nov 29 04:19:07 node2 sync_client[17880]: process 17881 exited, signaled
to death by 6
reconstruct and start again;
Nov 29 04:19:20 node2 syncserver[17904]: IOERROR: failed to parse
/var/spool/imap/sync./17904/3a4cfcd97496017d40cb8be29682920eef0da4e7
Nov 29 04:19:20 node2 syncserver[17904]: Failed to append file user.user 16
Nov 29 04:21:16 node2 sync_client[27906]: MAILBOX received NO response:
IMAP_MAILBOX_CRC Checksum Failure
Nov 29 04:21:17 node2 sync_client[27906]: CRC failure on sync for
user.cconn, trying full update
Nov 29 04:21:17 node2 sync_client[27906]: MAILBOX received NO response:
IMAP_MAILBOX_CRC Checksum Failure
Nov 29 04:21:17 node2 sync_client[27906]: CRC failure on sync for
user.user, trying full update
Nov 29 04:21:17 node2 sync_client[27906]: FETCH received NO response:
IMAP_MAILBOX_NONEXISTENT No Such Mailbox
Nov 29 04:21:17 node2 sync_client[27905]: process 27906 exited, signaled
to death by 6
meanwhile on the master;
Nov 29 04:21:16 node1 syncserver[2525]: higher modseq on replica
user.cconn - 433 < 434
Nov 29 04:21:17 node1 syncserver[2525]: higher modseq on replica
user.user - 45 < 46
Nov 29 04:21:44 node1 sync_client[2501]: MAILBOX received NO response:
System I/O error
Nov 29 04:21:44 node1 sync_client[2501]: do_folders(): update failed:
user.user 'The remote Server(s) denied the operation'
Nov 29 04:21:52 node1 sync_client[2501]: MAILBOX received NO response:
System I/O error
Nov 29 04:21:52 node1 sync_client[2501]: do_folders(): update failed:
user.user 'The remote Server(s) denied the operation'
Nov 29 04:21:52 node1 sync_client[2501]: IOERROR: The remote Server(s)
denied the operation
Nov 29 04:21:52 node1 sync_client[2501]: Error in do_sync(): bailing
out! The remote Server(s) denied the operation
Nov 29 04:21:52 node1 sync_client[2501]: Processing sync log file
/var/lib/imap/sync/log-2500 failed: The remote Server(s) denied the
operation
Nov 29 04:21:52 node1 sync_client[2500]: process 2501 exited, status 1
Nov 29 04:23:32 node1 syncserver[12603]: higher modseq on replica
user.user - 45 < 46
Nov 29 04:23:39 node1 sync_client[12580]: MAILBOX received NO response:
System I/O error
Nov 29 04:23:39 node1 sync_client[12580]: do_folders(): update failed:
user.user 'The remote Server(s) denied the operation'
Nov 29 04:23:46 node1 sync_client[12580]: MAILBOX received NO response:
System I/O error
Nov 29 04:23:46 node1 sync_client[12580]: do_folders(): update failed:
user.user 'The remote Server(s) denied the operation'
Nov 29 04:23:46 node1 sync_client[12580]: IOERROR: The remote Server(s)
denied the operation
Nov 29 04:23:46 node1 sync_client[12580]: Error in do_sync(): bailing
out! The remote Server(s) denied the operation
Nov 29 04:23:46 node1 sync_client[12580]: Processing sync log file
/var/lib/imap/sync/log-12579 failed: The remote Server(s) denied the
operation
Nov 29 04:35:52 node1 reconstruct[10397]: user.user uid 16 not found
Nov 29 04:36:09 node1 reconstruct[10399]: user.user: updating sync_crc
00000000 => 482C1C6F
so my only solution was to delete the 16. file under user.user, which
was an email that was successfully replicated at 00:15 am that same day.
So is this the same bug?
In any case, this happens every day when the logrotate emails get sent
from master to slave and slave to master, as they are sending a
different email to the same mailbox roughly at the same time. Hopefully
running 2.4.5 will avoid this?
Chris
More information about the Info-cyrus
mailing list