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

Adam McDougall mcdouga9 at egr.msu.edu
Tue Nov 6 22:57:24 EET 2007 

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

-------------- next part --------------
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

More information about the dovecot mailing list