[Dovecot] dsync replication errors

[Michael Grimm]

[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