A new employee started today, when logging into his new mailbox this
morning during a walk-through I got a nasty server error response in
Thunderbird - something I never see, DC runs smooth as butter for us.
Checking the server log I see this:
== snip =dovecot: Jul 09 09:38:54 Error: IMAP(xxxxxxx): Maildir
/home/x/xxxxxxx/Maildir sync: UIDVALIDITY changed (1183406107 -> 1183999134)
dovecot: Jul 09 09:39:06 Error: IMAP(xxxxxxx): Corrupted transaction log
file /var/spool/dovecot/indexes/x/xxxxxxx/.INBOX/dovecot.index.log.2:
invalid indexid (1183406107 != 1183999146)
dovecot: Jul 09 09:39:06 Error: IMAP(xxxxxxx): Corrupted index cache
file /var/spool/dovecot/indexes/x/xxxxxxx/.INBOX/dovecot.index.cache:
indexid changed
== snip =
Some facts that make this a strange occurrence:
1) new IMAP mailbox, only one email was in it that I had sent last week
(boilerplate Welcome email)
2) was working perfectly fine on Friday when I set things up
(Thunderbird and SquirrelMail) and tested with the same client laptop
and same Thunderbird
3) nothing bad happened with the servers over the weekend, all is
tip-top - no restarts, reboots, nothing.
4) DC does use NFS mounted maildirs, but there is only one DC accessing
any maildir - no other servers touch ~/Maildir/. mmap is disabled.
What could be a reason for this index to have gotten corrupted? This is
the first time I've had an index go corrupt out of all the users, so I'd
like to try and track down the cause of this...
thx,
-te
== dovecot -n =# 1.0.1: /etc/dovecot.conf
log_path: /var/log/dovecot.log
protocols: imap imaps
listen: *
ssl_cert_file: /opt/SSL/server.pem
ssl_key_file: /opt/SSL/server.pem
login_dir: /var/run/dovecot/login
login_executable: /usr/libexec/dovecot/imap-login
login_process_per_connection: no
mail_location: maildir:~/Maildir:INDEX=/var/spool/dovecot/indexes/%1u/%u
mmap_disable: yes
namespace:
type: private
separator: .
prefix: INBOX.
inbox: yes
auth default:
cache_size: 4096
cache_ttl: 7200
passdb:
driver: pam
args: cache_key=%u dovecot
userdb:
driver: passwd
args: blocking=yes
== end =
--
Troy Engel | Systems Engineer
Fluid, Inc | http://www.fluid.com
Timo Sirainen
2007-Jul-10 04:24 UTC
[Dovecot] 1.0.1: corrupt index on fresh mailbox, ideas?
On Mon, 2007-07-09 at 11:45 -0700, Troy Engel wrote:> A new employee started today, when logging into his new mailbox this > morning during a walk-through I got a nasty server error response in > Thunderbird - something I never see, DC runs smooth as butter for us. > Checking the server log I see this: > > == snip => dovecot: Jul 09 09:38:54 Error: IMAP(xxxxxxx): Maildir > /home/x/xxxxxxx/Maildir sync: UIDVALIDITY changed (1183406107 -> 1183999134)dovecot-uidlist file had UIDVALIDITY 1183406107 (Mon Jul 2 19:55:07 UTC 2007) and index file had UIDVALIDITY 1183999134 (Mon Jul 9 16:38:54 UTC 2007). This also explains the rest of the errors, Dovecot v1.0 doesn't handle very nicely these UIDVALIDITY changes (v1.1 does better). For this to happen: 1. The index files have to be created. 2. dovecot-uidlist file has to be recreated without seeing the existing index. 3. Accessing mailbox again with the new dovecot-uidlist and old indexes causes this error. So the real reasons for these could include temporarily using different index file paths, restoring indexes/uidlists from backups, temporarily using index files for accessing other mailbox. -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 189 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070710/6cf7e250/attachment-0002.bin>
On 7/10/07, Timo Sirainen <tss at iki.fi> wrote:> dovecot-uidlist file had UIDVALIDITY 1183406107 (Mon Jul 2 19:55:07 UTC > 2007) and index file had UIDVALIDITY 1183999134 (Mon Jul 9 16:38:54 UTC > 2007). This also explains the rest of the errors, Dovecot v1.0 doesn't > handle very nicely these UIDVALIDITY changes (v1.1 does better). >This is probably the same problem as I described in my email from Jul 9, 2007 8:30 AM. Are there any plans to fix these error messages? I get warning emails from my log watchdog several times a day. Users are not complaining, so I think that they aren't loosing any emails. Timo, thank you for your great work! Chris
Timo Sirainen wrote:> > So the real reasons for these could include temporarily using different > index file paths, restoring indexes/uidlists from backups, temporarily > using index files for accessing other mailbox.OK I understand your 3 points about how it actually could happen, and the ideas above as to possible causes; unfortunately we are in none of those situations. :( It was a mailbox simply created, accessed via Thunderbird and Squirrelmail all of... maybe 3 times. Nothing at all changed between the time it was working and the time it wasn't (no other mailboxes were affected). I'll keep an eye out - I created another new mailbox yesterday which will get the exact same treatment for an employee starting next Monday. If it doesn't happen again I'll just resign to calling it a random happenstance. -te -- Troy Engel | Systems Engineer Fluid, Inc | http://www.fluid.com
Timo Sirainen
2007-Jul-10 17:21 UTC
[Dovecot] 1.0.1: corrupt index on fresh mailbox, ideas?
On Mon, 2007-07-09 at 11:45 -0700, Troy Engel wrote:> dovecot: Jul 09 09:38:54 Error: IMAP(xxxxxxx): Maildir > /home/x/xxxxxxx/Maildir sync: UIDVALIDITY changed (1183406107 -> 1183999134)Fixed: http://hg.dovecot.org/dovecot-1.0/rev/90ea01bfaf82 -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 189 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070710/43f157e1/attachment-0002.bin>
Stewart Dean
2007-Jul-10 17:28 UTC
[Dovecot] 1.0.1: corrupt index on fresh mailbox, ideas?
when will there be a respin for a V1.0.2? Timo Sirainen wrote:> On Mon, 2007-07-09 at 11:45 -0700, Troy Engel wrote: > >> dovecot: Jul 09 09:38:54 Error: IMAP(xxxxxxx): Maildir >> /home/x/xxxxxxx/Maildir sync: UIDVALIDITY changed (1183406107 -> 1183999134) >> > > Fixed: http://hg.dovecot.org/dovecot-1.0/rev/90ea01bfaf82 > >-- ===Stewart Dean, Unix System Admin, Henderson Computer Resources Center of Bard College, Annandale-on-Hudson, New York 12504 sdean at bard.edu voice: 845-758-7475, fax: 845-758-7035
On 7/10/07, Timo Sirainen <tss at iki.fi> wrote:> On Mon, 2007-07-09 at 11:45 -0700, Troy Engel wrote: > > dovecot: Jul 09 09:38:54 Error: IMAP(xxxxxxx): Maildir > > /home/x/xxxxxxx/Maildir sync: UIDVALIDITY changed (1183406107 -> 1183999134) > > Fixed: http://hg.dovecot.org/dovecot-1.0/rev/90ea01bfaf82 >Thanks. I applied this patch to 1.0.1 and after some hours I got: Error: IMAP(box1909): file maildir-uidlist.c: line 979 (maildir_uidlist_sync_deinit): assertion failed: (ctx->uidlist->uid_validity != 0) Error: IMAP(box1909): Raw backtrace: imap [0x809c6bb] -> imap [0x809c0b9] -> imap [0x8069a71] -> imap(maildir_transaction_save_commit_post+0x17) [0x806d8c7] -> imap(maildir_transaction_commit+0x6b) [0x8067f2b] -> imap(mailbox_transaction_commit+0x20) [0x808e7d0] -> imap [0x805590f] -> imap [0x8055a88] -> imap [0x80552d5] -> imap(io_loop_handler_run+0x128) [0x80a2a18] -> imap(io_loop_run+0x28) [0x80a1e88] -> imap(main+0x69) [0x8062de9] -> /lib/libc.so.6(__libc_start_main+0xc6) [0x40035e36] -> imap [0x80551f1] Error: child 1755 (imap) killed with signal 6 Error: IMAP(box1378): file maildir-uidlist.c: line 979 (maildir_uidlist_sync_deinit): assertion failed: (ctx->uidlist->uid_validity != 0) Error: IMAP(box1378): Raw backtrace: imap [0x809c6bb] -> imap [0x809c0b9] -> imap [0x8069a71] -> imap(maildir_transaction_save_commit_post+0x17) [0x806d8c7] -> imap(maildir_transaction_commit+0x6b) [0x8067f2b] -> imap(mailbox_transaction_commit+0x20) [0x808e7d0] -> imap(cmd_copy+0x135) [0x8056325] -> imap [0x805a685] -> imap [0x805a5fb] -> imap(_client_input+0x6d) [0x805a76d] -> imap(io_loop_handler_run+0x128) [0x80a2a18] -> imap(io_loop_run+0x28) [0x80a1e88] -> imap(main+0x69) [0x8062de9] -> /lib/libc.so.6(__libc_start_main+0xc6) [0x40035e36] -> imap [0x80551f1] Error: child 4013 (imap) killed with signal 6 Error: IMAP(box1378): file maildir-uidlist.c: line 979 (maildir_uidlist_sync_deinit): assertion failed: (ctx->uidlist->uid_validity != 0) Error: IMAP(box1378): Raw backtrace: imap [0x809c6bb] -> imap [0x809c0b9] -> imap [0x8069a71] -> imap(maildir_transaction_save_commit_post+0x17) [0x806d8c7] -> imap(maildir_transaction_commit+0x6b) [0x8067f2b] -> imap(mailbox_transaction_commit+0x20) [0x808e7d0] -> imap(cmd_copy+0x135) [0x8056325] -> imap [0x805a685] -> imap [0x805a5fb] -> imap(_client_input+0x6d) [0x805a76d] -> imap(io_loop_handler_run+0x128) [0x80a2a18] -> imap(io_loop_run+0x28) [0x80a1e88] -> imap(main+0x69) [0x8062de9] -> /lib/libc.so.6(__libc_start_main+0xc6) [0x40035e36] -> imap [0x80551f1] Error: child 4353 (imap) killed with signal 6 Chris