[Dovecot] dsync replication errors

[Oli Schacher]

On Sat, 16 Feb 2013 17:20:22 +0200
Timo Sirainen <tss at iki.fi> wrote:

> 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.
> 

Thanks for the fixes, Timo! 

I can confirm I'm no longer able to break anything
with the tests I've mentioned so far(mass appending, simultaneous
append and delete on both mailboxes), no more errors, no more dupes.

I can also confirm the doveadm-server crash  I reported in
http://dovecot.markmail.org/thread/fb3qjnsdhtcpirg3 is now gone.

There seems to be an issue left when expunging a large amount of
messages from the Trash. I managed to get it twice so far by expunging
~3k messages. I'll try to create a reproducible test script for this
scenario. I can currently only provide my "clicking around" log output.
Version is current hg, e63d1cf19ec7.

First time it happened:
Feb 16 18:49:48 doco2 dovecot: imap(user1): Warning: Maildir /mailstore/user1/maildir/.Trash: Expunged message reappeared, giving a new UID (old uid=1221, file=1361035457.M728795P6220.doco1,S=2476,W=2555:2,Sa)
Feb 16 18:49:48 doco2 dovecot: imap(user1): Warning: Maildir /mailstore/user1/maildir/.Trash: Expunged message reappeared, giving a new UID (old uid=1222, file=1361035458.M501466P6220.doco1,S=2477,W=2556:2,Sa)
Feb 16 18:49:48 doco2 dovecot: imap(user1): Warning: Maildir /mailstore/user1/maildir/.Trash: Expunged message reappeared, giving a new UID (old uid=1223, file=1361035458.M988177P6220.doco1,S=2520,W=2599:2,Sa)
Feb 16 18:49:48 doco2 dovecot: imap(user1): Warning: Maildir /mailstore/user1/maildir/.Trash: Expunged message reappeared, giving a new UID (old uid=1224, file=1361035459.M254031P6220.doco1,S=2483,W=2562:2,Sa)
Feb 16 18:49:49 doco2 dovecot: imap(user1): Warning: Maildir /mailstore/user1/maildir/.Trash: Expunged message reappeared, giving a new UID (old uid=1225, file=1361035459.M431911P6220.doco1,S=2490,W=2569:2,Sa)
Feb 16 18:49:49 doco2 dovecot: imap(user1): Warning: Maildir /mailstore/user1/maildir/.Trash: Expunged message reappeared, giving a new UID (old uid=1226, file=1361035459.M959244P6220.doco1,S=2482,W=2561:2,Sa)
Feb 16 18:50:14 doco2 dovecot: doveadm: Error: dsync-remote(user1): Error: Couldn't lock /mailstore/user1/.dovecot-sync.lock: Interrupted system call
Feb 16 18:50:14 doco2 dovecot: doveadm: Error: dsync-remote(user1): Error: dsync(local): Received unexpected input S != H
Feb 16 18:50:14 doco2 dovecot: dsync-local(user1): Error: read(vmail at 192.168.23.61) failed: EOF
Feb 16 18:50:14 doco2 dovecot: dsync-local(user1): Error: Remote command returned error 75
Feb 16 18:50:44 doco2 dovecot: doveadm: Error: dsync-remote(user1): Error: Couldn't lock /mailstore/user1/.dovecot-sync.lock: Interrupted system call
Feb 16 18:50:44 doco2 dovecot: doveadm: Error: dsync-remote(user1): Error: dsync(local): Received unexpected input N != H
Feb 16 18:50:44 doco2 dovecot: dsync-local(user1): Error: read(vmail at 192.168.23.61) failed: EOF
Feb 16 18:50:44 doco2 dovecot: dsync-local(user1): Error: Remote command returned error 75


2nd time: (no "reappeared" messages this time)
Feb 16 19:08:13 doco2 dovecot: imap-login: Login: user=<user1>, method=PLAIN, rip=192.168.23.130, lip=192.168.23.62, mpid=4794, session=<DZ8RYNvVyADAqBeC>
Feb 16 19:08:44 doco2 dovecot: doveadm: Error: dsync-remote(user1): Error: Couldn't lock /mailstore/user1/.dovecot-sync.lock: Interrupted system call
Feb 16 19:08:44 doco2 dovecot: doveadm: Error: dsync-remote(user1): Error: dsync(local): Received unexpected input S != H
Feb 16 19:08:44 doco2 dovecot: dsync-local(user1): Error: read(vmail at 192.168.23.61) failed: EOF
Feb 16 19:08:44 doco2 dovecot: dsync-local(user1): Error: Remote command returned error 75


A while later on the other server:
Feb 16 19:13:08 doco1 dovecot: doveadm: Error: dsync-remote(user1): Panic: file mail-transaction-log-view.c: line 72 (mail_transaction_log_view_set): assertion failed: (min_file_seq <= max_file_seq)
Feb 16 19:13:08 doco1 dovecot: doveadm: Error: dsync-remote(user1): Error: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0(+0x5dc2a) [0x7f305f325c2a] -> /usr/lib64/dovecot/libdovecot.so.0(default_fatal_handler+0x32) [0x7f305f325d12] -> /usr/lib64/dovecot/libdovecot.so.0(+0x1f80a) [0x7f305f2e780a] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_log_view_set+0x580) [0x7f305f64e3f0] -> /usr/bin/doveadm() [0x43786b] -> /usr/bin/doveadm(dsync_transaction_log_scan_init+0x8c) [0x43791c] -> /usr/bin/doveadm(dsync_brain_sync_mailbox_open+0x5e) [0x42724e] -> /usr/bin/doveadm(dsync_brain_slave_recv_mailbox+0x123) [0x427c63] -> /usr/bin/doveadm(dsync_brain_run+0x178) [0x425ff8] -> /usr/bin/doveadm() [0x4265d1] -> /usr/bin/doveadm() [0x4357f0] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x36) [0x7f305f334bd6] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0xa7) [0x7f305f335c67] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x28) [0x7f305f334b78] -> /usr/bin/doveadm() [0x424294] -> /usr/bin/doveadm() [0x40ffaf] -> /usr/bin/doveadm() [0x4107dd] -> /usr/bin/doveadm(doveadm_mail_try_run+0x141) [0x410d01] -> /usr/bin/doveadm(main+0x3f1) [0x417d21] -> /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f305ef53cdd] -> /usr/bin/doveadm() [0x40f999]
Feb 16 19:13:08 doco1 dovecot: dsync-local(user1): Error: read(vmail at 192.168.23.62) failed: EOF
Feb 16 19:13:08 doco1 dovecot: dsync-local(user1): Error: Remote command returned error 255


-- 
message transmitted on 100% recycled electrons