[Dovecot] 1.0.1: corrupt index on fresh mailbox, ideas?
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:
new IMAP mailbox, only one email was in it that I had sent last week (boilerplate Welcome email)
was working perfectly fine on Friday when I set things up (Thunderbird and SquirrelMail) and tested with the same client laptop and same Thunderbird
nothing bad happened with the servers over the weekend, all is tip-top - no restarts, reboots, nothing.
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
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:
The index files have to be created.
dovecot-uidlist file has to be recreated without seeing the existing index.
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.
On 7/10/07, Timo Sirainen tss@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
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)
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)
--
Stewart Dean, Unix System Admin, Henderson Computer Resources
Center of Bard College, Annandale-on-Hudson, New York 12504
sdean@bard.edu voice: 845-758-7475, fax: 845-758-7035
Timo Sirainen wrote:
On Tue, 2007-07-10 at 13:28 -0400, Stewart Dean wrote:
when will there be a respin for a V1.0.2?
This week.
Thank you! I'm not sure how I would test this for you, prior to 1.0.2 - do you need it tested somehow?
regards, -te
-- Troy Engel | Systems Engineer Fluid, Inc | http://www.fluid.com
On Tuesday 10 July 2007 17:32:57 Troy Engel wrote:
Timo Sirainen wrote:
On Tue, 2007-07-10 at 13:28 -0400, Stewart Dean wrote:
when will there be a respin for a V1.0.2?
This week.
Thank you! I'm not sure how I would test this for you, prior to 1.0.2 - do you need it tested somehow?
I can patch (probably will) and test my rig but I don't know how to reproduce the problem. As I pointed out in a different thread about UIDVALIDITY error/warnings, we initially saw the UIDVALIDITY error/warning immediately upon upgrade to 1.0.1. I have not seen them since. I haven't seen the utime error/warning since I used that patch but I could never reproduce that problem either.
On 11.7.2007, at 3.02, Jim Horner wrote:
On Tuesday 10 July 2007 17:32:57 Troy Engel wrote:
Timo Sirainen wrote:
On Tue, 2007-07-10 at 13:28 -0400, Stewart Dean wrote:
when will there be a respin for a V1.0.2?
This week.
Thank you! I'm not sure how I would test this for you, prior to
1.0.2 - do you need it tested somehow?I can patch (probably will) and test my rig but I don't know how to
reproduce the problem.
The way I reproduced it was:
Create a new mailbox
Open the empty mailbox
Logout.
Create a new message to the maildir (not with Dovecot's deliver)
Open the mailbox again.
On 7/10/07, Timo Sirainen tss@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)
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
On Wed, 2007-07-11 at 15:18 +0200, Chris Laif wrote:
On 7/10/07, Timo Sirainen tss@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)
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)
How about this then: http://hg.dovecot.org/dovecot-1.0/rev/b6753fd66298
On 7/12/07, Timo Sirainen tss@iki.fi wrote:
On Wed, 2007-07-11 at 15:18 +0200, Chris Laif wrote:
On 7/10/07, Timo Sirainen tss@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)
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)
How about this then: http://hg.dovecot.org/dovecot-1.0/rev/b6753fd66298
Ok, thank you for your quick response. Patch applied. Let's wait and see :)
Chris
participants (5)
-
Chris Laif
-
Jim Horner
-
Stewart Dean
-
Timo Sirainen
-
Troy Engel