[Dovecot] 1.1.4 and trouble over NFS

[Igor Colombi]

Hello, I have some trouble with the current setup (it's a testing 
environment):

2 server with Dovecot 1.1.4 from source (OS Debian testing 2.6.26) 
(name: "exim" and "exim2")
1 NFS server (OS Debian testing 2.6.26)

I use NFS v.4, indexes shared over NFS. The relavant part of Dovecot 
configuration:

dotlock_use_excl = yes
mail_nfs_storage = yes
mail_nfs_index = yes
mmap_disable = yes
lock_method = dotlock

Maildir format.

/etc/exports on NFS server:

/mnt 192.168.0.0/24(rw,sync,no_root_squash,no_subtree_check,fsid=0)
/mnt/vexim 192.168.0.0/24(rw,sync,no_root_squash,no_subtree_check)

/etc/fstab on the clients:

192.168.0.71:/vexim /mnt/nfs1 nfs4 rw 0 0

When I access a mailbox with 2 different clients (for example Outlook 
Express that uses "exim" and Thunderbird that uses "exim2") and in the 
same time some message is delivered to the mailbox (the smtp is served 
by Exim 4.69) Dovecot has some trouble as you can see:

*** Log from machine "exim"

Oct  7 20:00:20 exim dovecot: IMAP(postmaster at minnie.tld): 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot-uidlist: file size 
changed unexpectedly after write
Oct  7 20:00:20 exim dovecot: IMAP(postmaster at minnie.tld): Broken file 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot-uidlist line 3: Invalid 
data:
Oct  7 20:00:21 exim dovecot: IMAP(postmaster at minnie.tld): 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot-uidlist: Duplicate file 
entry at line 6: 1223402420.H172077P24365.exim.bnscr.it:2, (uid 16919 -> 
16922)
Oct  7 20:00:23 exim dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=10612 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Append with UID 
16925, but next_uid = 16926
Oct  7 20:00:23 exim dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=10724 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Extension record 
update for invalid uid=16926
Oct  7 20:00:23 exim dovecot: IMAP(postmaster at minnie.tld): 
Synchronization corrupted index header: 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:00:23 exim dovecot: IMAP(postmaster at minnie.tld): fscking index 
file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:00:23 exim dovecot: IMAP(postmaster at minnie.tld): Fixed index 
file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: 
first_recent_uid 16927 -> 16926
Oct  7 20:00:24 exim dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=11140 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Extension record 
update for invalid uid=16928
Oct  7 20:00:24 exim dovecot: IMAP(postmaster at minnie.tld): fscking index 
file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:01:00 exim dovecot: imap-login: Login: 
user=<postmaster at minnie.tld>, method=PLAIN, rip=127.0.0.1, 
lip=127.0.0.1, secured
Oct  7 20:02:00 exim dovecot: imap-login: Login: 
user=<postmaster at minnie.tld>, method=PLAIN, rip=127.0.0.1, 
lip=127.0.0.1, secured
Oct  7 20:02:26 exim dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=11628 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Append with UID 
16929, but next_uid = 16930
Oct  7 20:02:26 exim dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=11756 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Extension record 
update for invalid uid=16930
Oct  7 20:02:26 exim dovecot: IMAP(postmaster at minnie.tld): fscking index 
file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:15:23 exim dovecot: Panic: IMAP(postmaster at minnie.tld): 
Message count decreased
Oct  7 20:15:23 exim dovecot: IMAP(postmaster at minnie.tld): Raw 
backtrace: imap [0x80d6781] -> imap [0x80d6802] -> imap [0x80d6199] -> 
imap [0x8069711] -> imap [0x805e98b] -> imap [0x805ea40] -> imap 
[0x809c9af] -> imap(io_loop_handle_timeouts+0xe9) [0x80ddb19] -> 
imap(io_loop_handler_run+0x82) [0x80de3d2] -> imap(io_loop_run+0x20) 
[0x80dd8c0] -> imap(main+0x46a) [0x806b5aa] -> 
/lib/i686/cmov/libc.so.6(__libc_start_main+0xe5) [0xb7df2455] -> imap 
[0x805c9f1]

*** Log from machine "exim"

Oct  7 20:00:20 exim2 dovecot: IMAP(postmaster at minnie.tld): 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot-uidlist: Duplicate file 
entry at line 5: 1223402419.H453623P30627.exim2.bnscr.it:2, (uid 16919 
-> 16920)
Oct  7 20:00:22 exim2 dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=10496 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Extension record 
update for invalid uid=16925
Oct  7 20:00:22 exim2 dovecot: IMAP(postmaster at minnie.tld): fscking 
index file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:00:25 exim2 dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=11324 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Append with UID 
16928, but next_uid = 16929
Oct  7 20:00:25 exim2 dovecot: IMAP(postmaster at minnie.tld): Log 
synchronization error at seq=3,offset=11528 for 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: Extension record 
update for invalid uid=16929
Oct  7 20:00:26 exim2 dovecot: IMAP(postmaster at minnie.tld): 
Synchronization corrupted index header: 
/mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:00:26 exim2 dovecot: IMAP(postmaster at minnie.tld): fscking 
index file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:00:26 exim2 dovecot: IMAP(postmaster at minnie.tld): Fixed index 
file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index: 
first_recent_uid 16930 -> 16929
Oct  7 20:00:26 exim2 dovecot: IMAP(postmaster at minnie.tld): fscking 
index file /mnt/nfs1/minnie.tld/postmaster/Maildir/dovecot.index
Oct  7 20:01:49 exim2 dovecot: IMAP(postmaster at minnie.tld): 
Disconnected: Logged out bytes=80/583
Oct  7 20:01:49 exim2 dovecot: IMAP(postmaster at minnie.tld): 
Disconnected: Logged out bytes=20304/276528
Oct  7 20:03:06 exim2 dovecot: imap-login: Login: 
user=<postmaster at minnie.tld>, method=PLAIN, rip=192.168.0.199, 
lip=192.168.0.72
Oct  7 20:03:09 exim2 dovecot: IMAP(postmaster at minnie.tld): Maildir 
/mnt/nfs1/minnie.tld/postmaster/Maildir: Expunged message reappeared, 
giving a new UID (old uid=16930, 
file=1223402424.H796471P30658.exim2.bnscr.it:2,)
Oct  7 20:03:09 exim2 dovecot: IMAP(postmaster at minnie.tld): Maildir 
/mnt/nfs1/minnie.tld/postmaster/Maildir: Expunged message reappeared, 
giving a new UID (old uid=16931, 
file=1223402425.H483603P24395.exim.bnscr.it:2,)
Oct  7 20:03:09 exim2 dovecot: IMAP(postmaster at minnie.tld): Maildir 
/mnt/nfs1/minnie.tld/postmaster/Maildir: Expunged message reappeared, 
giving a new UID (old uid=16932, 
file=1223402425.H824041P30664.exim2.bnscr.it:2,)

I know that with Dovecot < 1.1 the use on multiple computer when users 
are connected randomly was discouraged, but with version 1.1.x this 
setup is safe.

I can try to move indexes on the local disk, the trouble with 
dovecot.index disappear but I have again problem with dovecot-uidlist.

I can reproduce this kind of problem easly: 2 clients on the same 
mailbox connected to two different imap server and a simple bash script 
that send 2 email every 1 second to the mailbox.

There is some option/configuration that I can try to change?