Re: [Dovecot] Various uidlist and index errors with 1.1 on NFS

28 Nov 2007

      Thanks so much Timo, all of the errors below seem when using 1.1beta9
and a shared index on NFS.  Great!
On Tue, Nov 06, 2007 at 03:57:24PM -0500, Adam McDougall wrote:
Two nights ago I took a leap and extended my testing of dovecot 1.1 by
replacing 1.0 for the approx 15 users I had on 1.0.  At that time I also
for the first time tried dovecot 1.1 in a load balanced 2 server configuration
with indexes on NFS.  I was hoping I did this right, using the mail_nfs params
and 1.1 so fchown etc would flush the access cache, but I am getting a number
of messages and errors that indicate things aren't happy.  Attaching error
logs.  Some of the errors were caused by me running multiple mail clients
including mutt, Thunderbird, Outlook Express, other users may be using one
or more copies of thunderbird, or possibly other clients.  Most commonly
thunderbird.  Any help or advice would be appreciated.  My goal is to have
shared indexes between servers since I will eventually have 4.  I'd prefer
to avoid maintaining some kind of user->server preference mapping in a proxy
(haven't looked into it yet).  Thanks.
# 1.1.beta6: /usr/local/etc/dovecot.conf
ssl_cert_file: /usr/local/etc/apache2/ssl/mail.pem
ssl_key_file: /usr/local/etc/apache2/ssl/mail.pem
login_dir: /var/run/dovecot/login
login_executable: /usr/local/libexec/dovecot/imap-login
verbose_proctitle: yes
first_valid_uid: 1000
first_valid_gid: 1000
mail_extra_groups: postlocal
mail_location:
maildir:%h/Maildir:CONTROL=%h/Maildir/dovecot/private/control:INDEX=%h/Maildir/dovecot/private/indexes
mmap_disable: yes
mail_nfs_storage: yes
mail_nfs_index: yes
mail_plugins: acl
mail_log_max_lines_per_sec: 0
imap_client_workarounds: delay-newmail netscape-eoh tb-extra-mailbox-sep
namespace:
type: private
separator: /
inbox: yes
list: yes
subscriptions: yes
namespace:
type: private
separator: /
prefix: mail/
hidden: yes
subscriptions: yes
namespace:
type: private
separator: /
prefix: Mail/
hidden: yes
subscriptions: yes
namespace:
type: public
separator: /
prefix: #shared/decs/
location:
maildir:/egr/mail/shared/decs:CONTROL=%h/Maildir/dovecot/public/control/decs:INDEX=%h/Maildir/dovecot/public/indexes/decs
list: yes
subscriptions: yes
auth default:
passdb:
driver: pam
userdb:
driver: passwd
args: system_user=
socket:
type: listen
client:
path: /var/spool/postfix/private/auth
mode: 384
user: postfix
group: postfix
plugin:
acl: vfile:/usr/local/etc/dovecot-acls:cache_secs=10
List of errors:
"Trying to close mailbox with open transactions"
"Corrupted transaction log file Unexpected garbage at EOF"
"fscking index file"
"Transaction log got desynced for index"
"start_offset (3872) > current sync_offset"
"Fixed index file"
"log_file_head_offset 3872 -> 3680"
"Corrupted transaction log file record size too small"
"Transaction log file marked corrupted"
"file mail-index-sync-update.c: line 599: unreached"
"Duplicate file entry:"
"Corrupted transaction log file header update extends beyond record size"
Nov  4 22:17:03 boomhauer dovecot: Dovecot v1.1.beta6 starting up
Nov  4 23:32:23 boomhauer dovecot: IMAP(mcdouga9): Trying to close mailbox support.2005.01-Jan with open transactions
Nov  4 23:32:23 boomhauer dovecot: child 46161 (imap) killed with signal 6
Nov  5 01:11:43 boomhauer dovecot: IMAP(mcdouga9): Corrupted transaction log file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log: Unexpected garbage at EOF
Nov  5 01:13:59 boomhauer dovecot: IMAP(mcdouga9): Corrupted transaction log file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log: Unexpected garbage at EOF
Nov  5 01:13:59 boomhauer dovecot: IMAP(mcdouga9): Disconnected: Internal error occurred. Refer to server log for more information. [2007-11-05 01:13:59] bytes=4127/4532482
Nov  5 01:15:43 boomhauer dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 01:16:43 boomhauer dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 01:17:43 boomhauer dovecot: IMAP(mcdouga9): Transaction log got desynced for index /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 01:17:43 boomhauer dovecot: IMAP(mcdouga9): Disconnected: Mailbox is in inconsistent state, please relogin. bytes=4299/5007523
Nov  5 02:06:38 boomhauer dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index.log: start_offset (3872) > current sync_offset (3680)
Nov  5 02:06:38 boomhauer dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index
Nov  5 02:06:38 boomhauer dovecot: IMAP(mcdouga9): Fixed index file /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index: log_file_head_offset 3872 -> 3680
Nov  5 02:06:38 boomhauer dovecot: IMAP(mcdouga9): Fixed index file /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index: log_file_tail_offset 3872 -> 3680
Nov  5 02:06:38 boomhauer dovecot: IMAP(mcdouga9): Disconnected: Logged out bytes=1133/5754
Nov  5 10:06:50 boomhauer dovecot: IMAP(mcdouga9): Corrupted transaction log file /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index.log: record size too small (type=0x0, offset=3928, size=0)
Nov  5 10:07:46 boomhauer dovecot: IMAP(mcdouga9): Transaction log file /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index.log: marked corrupted
Nov  5 13:43:30 boomhauer dovecot: IMAP(nguye140): /home/nguye140/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (5572) > current sync_offset (5284)
Nov  5 13:43:30 boomhauer dovecot: IMAP(nguye140): fscking index file /home/nguye140/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  5 13:43:30 boomhauer dovecot: IMAP(nguye140): Fixed index file /home/nguye140/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 5572 -> 5284
Nov  5 13:43:30 boomhauer dovecot: IMAP(nguye140): Fixed index file /home/nguye140/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 5572 -> 5284
Nov  5 15:03:00 boomhauer dovecot: IMAP(mcdouga9): file mail-index-sync-update.c: line 599: unreached
Nov  5 15:03:00 boomhauer dovecot: child 78214 (imap) killed with signal 6
Nov  5 16:03:56 boomhauer dovecot: IMAP(mcdouga9): Transaction log file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log: marked corrupted
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1189447198.M910150P10430.hill:2,RS
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1193427305.M277014P88682.boomhauer:2,S
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1194025661.M154932P28762.boomhauer:2,S
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1194025665.M107072P28771.boomhauer:2,S
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1194027883.M070903P52370.hill:2,S
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1194267366.M742511P64048.boomhauer:2,S
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1194278384.M003974P96264.hill:2,S
Nov  6 09:12:26 boomhauer dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/control/decs/.support/dovecot-uidlist: Duplicate file entry: 1194279851.M701280P97579.hill:2,S
(a number of them, about 50?  seems like the same 50 messages complained about like this, at 9:12:26, 9:14:04, 09:14:46, 09:18:51, 14:42:49.
Nov  6 14:43:25 boomhauer dovecot: IMAP(jelneckt): Corrupted transaction log file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: record size too small (type=0x0, offset=26984, size=0)
Nov  6 14:47:26 boomhauer dovecot: IMAP(jelneckt): Transaction log file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: marked corrupted
Nov  6 15:16:35 boomhauer dovecot: IMAP(jelneckt): Disconnected for inactivity bytes=825/850

Nov  5 01:16:53 hill dovecot: IMAP(mcdouga9): Transaction log file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log: marked corrupted
Nov  5 01:21:51 hill dovecot: IMAP(mcdouga9): Trying to close mailbox freebsd-cvs with open transactions
Nov  5 01:21:51 hill dovecot: child 75087 (imap) killed with signal 6
Nov  5 02:06:49 hill dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/control/decs/.network/dovecot-uidlist: Duplicate file entry: 1194235915.M316064P47248.boomhauer:2,ST
Nov  5 02:06:49 hill dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/control/decs/.network/dovecot-uidlist: Duplicate file entry: 1194240041.M550300P72969.hill:2,ST
Nov  5 02:06:49 hill dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/control/decs/.network/dovecot-uidlist: Duplicate file entry: 1194240355.M754858P73301.hill:2,ST
Nov  5 02:06:49 hill dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/control/decs/.network/dovecot-uidlist: Duplicate file entry: 1194243924.M066185P51525.boomhauer:2,ST
Nov  5 02:06:49 hill dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/control/decs/.network/dovecot-uidlist: Duplicate file entry: 1194244965.M990468P52239.boomhauer:2,ST
Nov  5 02:06:49 hill dovecot: IMAP(mcdouga9): /home/mcdouga9/Maildir/dovecot/public/control/decs/.network/dovecot-uidlist: Duplicate file entry: 1194246389.M336415P76883.hill:2,
Nov  5 10:08:38 hill dovecot: IMAP(mcdouga9): Transaction log got desynced for index /home/mcdouga9/Maildir/dovecot/public/indexes/decs/.network/dovecot.index
Nov  5 10:08:38 hill dovecot: IMAP(mcdouga9): Disconnected: Mailbox is in inconsistent state, please relogin. bytes=19157/57504
Nov  5 14:50:57 hill dovecot: IMAP(mcdouga9): Corrupted transaction log file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log: header update extends beyond record size
Nov  5 14:50:57 hill dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 15:05:57 hill dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 15:20:57 hill dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 15:26:53 hill dovecot: IMAP(mcdouga9): file mail-index-sync-update.c: line 599: unreached
Nov  5 15:26:53 hill dovecot: child 72615 (imap) killed with signal 6
Nov  5 15:35:57 hill dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 15:50:57 hill dovecot: IMAP(mcdouga9): fscking index file /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 16:03:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:03:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:03:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:05:57 hill dovecot: IMAP(mcdouga9): Transaction log got desynced for index /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index
Nov  5 16:05:57 hill dovecot: IMAP(mcdouga9): Disconnected: Mailbox is in inconsistent state, please relogin. bytes=23965/37200957
Nov  5 16:05:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:05:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:05:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:07:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:07:59 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
Nov  5 16:08:00 hill dovecot: IMAP(mcdouga9): Invalid transaction log size (28600 vs 27840): /home/mcdouga9/Maildir/dovecot/private/indexes/.INBOX/dovecot.index.log
(many of these repeating (28600 vs 27840), pattern seemed to be 3 at once, every 2 minutes, continuing up to the present time Nov 6 14:49)
Nov  6 09:12:11 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (13044) > current sync_offset (12384)
Nov  6 09:12:11 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:12:11 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 13044 -> 12384
Nov  6 09:12:11 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 13044 -> 12384
Nov  6 09:13:12 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (15552) > current sync_offset (13456)
Nov  6 09:13:12 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:13:12 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 15552 -> 13456
Nov  6 09:13:12 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 15552 -> 13456
Nov  6 09:14:43 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (16648) > current sync_offset (14424)
Nov  6 09:14:43 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:14:43 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 16648 -> 14424
Nov  6 09:14:43 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 16648 -> 14424
Nov  6 09:16:44 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (17700) > current sync_offset (15328)
Nov  6 09:16:44 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:16:44 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 17700 -> 15328
Nov  6 09:16:44 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 17700 -> 15328
Nov  6 09:19:12 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (19048) > current sync_offset (16216)
Nov  6 09:19:12 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:19:12 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 19048 -> 16216
Nov  6 09:19:12 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 19048 -> 16216
Nov  6 09:22:13 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (20092) > current sync_offset (16532)
Nov  6 09:22:13 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:22:13 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 20092 -> 16532
Nov  6 09:22:13 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 20092 -> 16532
Nov  6 09:46:47 hill dovecot: IMAP(walbyjon): /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (21400) > current sync_offset (17768)
Nov  6 09:46:47 hill dovecot: IMAP(walbyjon): fscking index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 09:46:47 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 21400 -> 17768
Nov  6 09:46:47 hill dovecot: IMAP(walbyjon): Fixed index file /home/walbyjon/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 21400 -> 17768
Nov  6 14:42:43 hill dovecot: IMAP(jelneckt): /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (27068) > current sync_offset (26160)
Nov  6 14:42:43 hill dovecot: IMAP(jelneckt): fscking index file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 14:42:43 hill dovecot: IMAP(jelneckt): Fixed index file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 27068 -> 26160
Nov  6 14:42:43 hill dovecot: IMAP(jelneckt): Fixed index file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 27068 -> 26160
Nov  6 14:44:13 hill dovecot: IMAP(jelneckt): /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index.log: start_offset (28472) > current sync_offset (26984)
Nov  6 14:44:13 hill dovecot: IMAP(jelneckt): fscking index file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 14:44:13 hill dovecot: IMAP(jelneckt): Fixed index file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_head_offset 28472 -> 26984
Nov  6 14:44:13 hill dovecot: IMAP(jelneckt): Fixed index file /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index: log_file_tail_offset 28472 -> 26984
Nov  6 14:48:14 hill dovecot: IMAP(jelneckt): Transaction log got desynced for index /home/jelneckt/Maildir/dovecot/public/indexes/decs/.support/dovecot.index
Nov  6 14:48:14 hill dovecot: IMAP(jelneckt): Disconnected: Mailbox is in inconsistent state, please relogin. bytes=16540/100499