[Dovecot] dsync replication errors

[Timo Sirainen]

I did a bunch of dsync fixes today in hg. With the new locking behavior
(and other fixes) you shouldn't be able to break it anymore.

On Fri, 2013-02-01 at 21:53 +0100, Michael Grimm wrote:
> [Sorry Oli for my previous mail to your address, only. Resent here]
> 
> Oli Schacher <dovecot at lists.wgwh.ch> wrote:
> 
> > There still seems to be a problem when changes to both mailboxes at
> > the same time are involved
> 
> I can confirm your observation, although triggered by a different test
> scenario, similar to the one I did use with 2.1 replicator before
> (http://www.dovecot.org/list/dovecot/2012-March/064354.html).
> 
> This is v2.2.beta1 (78bdcb6642c7) with freshly created mailboxes "test"
> at both servers "mx1" and "mx2", and replicator uses ssh for remote
> access. Both servers run a recent postfix, use lmtp for local delivery,
> and "test" is a virtual user.
> 
> Test script to produce local testmails of equal size at mx1:
> | #!/bin/csh
> | set INDEX    = 101
> | set endINDEX = 200
> | while ( $INDEX <= $endINDEX )
> |    echo $INDEX
> |    echo "test" | mail -s $INDEX test at mx1
> |    if ( $INDEX % 1000 == 0 ) then
> |       sleep 1
> |    endif
> |    @ INDEX = $INDEX + 1
> |end
> |exit 0
> 
> Test script to produce testmails of equal size at mx2:
> | #!/bin/csh
> | set INDEX    = 1101
> | set endINDEX = 1200
> | while ( $INDEX <= $endINDEX )
> |    echo $INDEX
> |    echo "test" | mail -s $INDEX test at mx2
> |    if ( $INDEX % 1000 == 0 ) then
> |       sleep 1
> |    endif
> |    @ INDEX = $INDEX + 1
> |end
> |exit 0
> 
> All tests are run with vanilla mailboxes, after restarting dovecot, and
> without imap connections by MUA:
> 
> 1) Simultaneous mailbomb approach: run both scripts simultaneously, and
>   you'll end up with numerous duplicates in mailboxes "test". Very often
>   you'll find multiples.
> 
> 2) Mailbomb approach: run one script at one server only, and all mails
>   will become perfectly well synchronised.
> 
> 3) Mofify both scripts to "( $INDEX % 1 == 0 )" to add a second waiting
>   between every mail injection, and run them simultaneously at both
>   servers, and you'll end up with significantly less duplicates and no
>   more multiples.
> 
> > Feb  1 07:12:52 doco1 dovecot: dsync-local(user1): Error: Mailbox INBOX: Remote didn't send mail GUID=7a30ff22af5b0b510f0c0000960042f4 (UID=211)
> 
> > Feb  1 07:12:54 doco2 dovecot: dsync-local(user1): Error: Importing mailbox INBOX failed
> 
> > Feb  1 07:13:24 doco2 dovecot: dsync-local(user1): Error: Remote command process isn't dying, killing it
> 
> I do see those error messages as well, and in addition numerous of those:
> 
> | dovecot: dsync-local(test): Error: Mailbox INBOX: Unexpected GUID mismatch for UID=7153: 82c5df0a4ffa0b5141e300006a0d5a02 != 29cc9f284ffa0b5141c2000036abecbd
> 
> | doveadm: Error: dsync-remote(test): Error: Mailbox INBOX: Unexpected GUID mismatch for UID=7153: 82c5df0a4ffa0b5141e300006a0d5a02 != 29cc9f284ffa0b5141c2000036abecbd
> 
> | dovecot: lmtp(49752, test): Error: Corrupted index cache file /.../test/mailboxes/INBOX/dbox-Mails/dovecot.index.cache: File too small
> 
> | Feb  1 18:35:16 <mail.err>  mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Error: Mailbox INBOX: Corrupted index, uidvalidity=0
> | Feb  1 18:35:16 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:16 <mail.err>  mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Error: Mailbox INBOX: Corrupted index, uidvalidity=0
> | Feb  1 18:35:16 <mail.err>  mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Error: mdbox /.../test/mailboxes/INBOX/dbox-Mails: Storage keeps breaking
> | Feb  1 18:35:16 <mail.err>  mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Error: Mailbox INBOX: Corrupted index, uidvalidity=0
> | Feb  1 18:35:16 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:16 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: mdbox /.../test/storage: rebuilding indexes
> | Feb  1 18:35:17 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:17 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:17 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: mdbox /.../test/storage: rebuilding indexes
> | Feb  1 18:35:17 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:17 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:17 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: mdbox /.../test/storage: rebuilding indexes
> | Feb  1 18:35:18 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:18 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:18 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: mdbox /.../test/storage: rebuilding indexes
> | Feb  1 18:35:18 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:27 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:27 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: mdbox /.../test/storage: rebuilding indexes
> | Feb  1 18:35:27 <mail.warn> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Warning: fscking index file /.../test/storage/dovecot.map.index
> | Feb  1 18:35:27 <mail.info> mx1 dovecot: imap(test) BXeiKq3UBgBd3DLy: Disconnected: Logged out in=425 out=1100
> 
> JFYI, and regards,
> Michael
>