dovecot - Feb 2005 - corruption and errors in dovecot-stable

Hi,

We switched from dovecot 0.99.something to 1.0-stable (on FreeBSD 4.10) 
a few days ago and have been seeing many errors and one corrupted 
mailbox so far.  Almost everyone uses mbox format, and most users 
primarily use SquirrelMail; I use Apple Mail and Thunderbird, as well 
as accessing the mailboxes locally with Mutt, and have not noted any 
visible problems.

There have been several of these messages:

dovecot: Feb 21 11:40:06 Error: IMAP(njr): mbox sync: UID inserted in 
the middle of mailbox /usr/home/njriley/mail/lists/trac (5308 > 1151)
dovecot: Feb 21 22:57:13 Error: IMAP(njr): mbox sync: UID inserted in 
the middle of mailbox /usr/home/njriley/mail/lists/trac (6458 > 1151)
dovecot: Feb 22 08:37:03 Error: IMAP(njr): mbox sync: UID inserted in 
the middle of mailbox /usr/home/njriley/mail/lists/reportlab-users 
(5162 > 3812)

Others:

dovecot: Feb 22 11:44:17 Error: IMAP(njr): file mbox-sync-parse.c: line 
221 (parse_x_uid): assertion failed: (!ctx->sync_ctx->sync_restart)
dovecot: Feb 22 11:44:17 Error: child 19931 (imap) killed with signal 6

dovecot: Feb 25 06:26:09 Error: IMAP(kbode): file istream-raw-mbox.c: 
line 383 (istream_raw_mbox_get_body_size): assertion failed: 
(rstream->body_offset != (uoff_t)-1)
dovecot: Feb 25 06:26:09 Error: child 83423 (imap) killed with signal 6

(I think this refers to the mailbox that was corrupted)

dovecot: Feb 25 12:30:40 Error: IMAP(sachs): Transaction log file 
/home/sachs/Mail/.imap/INBOX/dovecot.index.log: invalid indexid 
(1109356120 != 1108933119)
dovecot: Feb 25 12:30:40 Error: IMAP(sachs): Corrupted transaction log 
file /home/sachs/Mail/.imap/INBOX/dovecot.index.log: Extension record 
update update without intro prefix
dovecot: Feb 25 12:30:41 Error: IMAP(sachs): Transaction log file 
/home/sachs/Mail/.imap/INBOX/dovecot.index.log: marked corrupted
dovecot: Feb 25 12:39:34 Error: IMAP(sachs): Transaction log file 
/home/sachs/Mail/.imap/INBOX/dovecot.index.log: invalid indexid 
(1109356120 != 1108933119)
dovecot: Feb 25 12:39:34 Error: IMAP(sachs): Lost transaction log file 
/home/sachs/Mail/.imap/INBOX/dovecot.index.log seq 2
dovecot: Feb 25 12:39:41 Error: IMAP(sachs): Transaction log file 
/home/sachs/Mail/.imap/INBOX/dovecot.index.log: invalid indexid 
(1108933119 != 1109356120)

I am currently reinstalling 0.99.14, but it would be nice to be able to 
switch to a 1.0-derived version again - we have to run two copies of 
0.99.x to get what we want.  If there is any additional testing I can 
do to help fix these problems, please let me know.

Thanks,

-- 
Nicholas Riley <njriley at uiuc.edu>     | 4111 Siebel Center
Department of Computer Science        | 201 N. Goodwin Ave.
and Medical Scholars Program          | Urbana, IL 61801-2302
Univ. of Illinois at Urbana-Champaign | +1 217 244 2274

Le 02/25/2005 08:48 PM, Nicholas Riley a ?crit :
> dovecot: Feb 22 11:44:17 Error: IMAP(njr): file mbox-sync-parse.c: line 
> 221 (parse_x_uid): assertion failed: (!ctx->sync_ctx->sync_restart)
> dovecot: Feb 22 11:44:17 Error: child 19931 (imap) killed with signal 6
I do see the same errors.

-- 
Nico
La logique est 'la science de la preuve'.
	-+- John Mill -+-

Timo,

What about these errors in Dovecot-stable ? Are they bad or can we just
ignore them ?
I haven't seen any related fixes in the changelogs so I don't know if
these are fixed or not.. Please tell us :)

Thanx !

-- 
Nico
Penser c'est dire non.
	-+- ?mile Chartier, dit Alain (1868-1951), Propos sur la religion -+-

On Fri, 2005-02-25 at 13:48 -0600, Nicholas Riley wrote:
> dovecot: Feb 21 11:40:06 Error: IMAP(njr): mbox sync: UID inserted in 
> the middle of mailbox /usr/home/njriley/mail/lists/trac (5308 > 1151)
dovecot-stable may handle mboxes a differently than 0.99.x, so I guess
these could happen (although they shouldn't.. I'd like to know if this
can be reproduced somehow?). In any case Dovecot should fix these and
you shouldn't see these more than once per each mailbox. If they appear
constantly for same mailboxes, there is a problem..
> dovecot: Feb 22 11:44:17 Error: IMAP(njr): file mbox-sync-parse.c: line 
> 221 (parse_x_uid): assertion failed: (!ctx->sync_ctx->sync_restart)
Probably somehow related to above error, but shouldn't happen.
> dovecot: Feb 25 06:26:09 Error: IMAP(kbode): file istream-raw-mbox.c: 
> line 383 (istream_raw_mbox_get_body_size): assertion failed: 
> (rstream->body_offset != (uoff_t)-1)
Same here. Have to look at these.
> dovecot: Feb 25 12:30:40 Error: IMAP(sachs): Transaction log file 
> /home/sachs/Mail/.imap/INBOX/dovecot.index.log: invalid indexid 
> (1109356120 != 1108933119)
Means the log file was recreated.
> dovecot: Feb 25 12:30:40 Error: IMAP(sachs): Corrupted transaction log 
> file /home/sachs/Mail/.imap/INBOX/dovecot.index.log: Extension record 
> update update without intro prefix
Strange. Is dovecot running over NFS or something?

Can you reproduce any of these problems easily or do they occur only
randomly?

-------------- 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/20050312/62eef3f3/attachment-0001.bin>

On Mar 12, 2005, at 2:53 PM, Timo Sirainen wrote:
> On Fri, 2005-02-25 at 13:48 -0600, Nicholas Riley wrote:
>> dovecot: Feb 21 11:40:06 Error: IMAP(njr): mbox sync: UID inserted in
>> the middle of mailbox /usr/home/njriley/mail/lists/trac (5308 >
1151)
>
> dovecot-stable may handle mboxes a differently than 0.99.x, so I guess
> these could happen (although they shouldn't.. I'd like to know if
this
> can be reproduced somehow?). In any case Dovecot should fix these and
> you shouldn't see these more than once per each mailbox. If they appear
> constantly for same mailboxes, there is a problem..
Since I wrote this, I have upgraded to 1.0-test63; see my other mail 
for why I can't compile -test65 :-).  I am only running this for my own 
mailbox, not for the other users on the system, who are back on 
0.99.13.

dovecot: Mar 15 22:00:12 Error: IMAP(njr): mbox sync: UID inserted in 
the middle of mailbox /usr/home/njriley/mail/lists/trac (14238 > 1151)
[...]
dovecot: Mar 16 13:02:45 Error: IMAP(njr): mbox sync: UID inserted in 
the middle
  of mailbox /usr/home/njriley/mail/lists/trac (15539 > 1151)
[...]
dovecot: Mar 16 15:47:37 Error: IMAP(njr): mbox sync: UID inserted in 
the middle of mailbox /usr/home/njriley/mail/lists/trac (16855 > 1151)

so it looks like for at least one mailbox, it does recur.

The only other message I've been getting with 1.0-test63 has been:

dovecot: Mar 15 22:00:18 Error: IMAP(njr): Fixed index file 
/usr/home/njriley/mail/.imap/Deleted Messages/dovecot.index: 
recent_messages_count 1 -> 0
[...]
dovecot: Mar 16 17:19:18 Error: IMAP(njr): Fixed index file 
/usr/home/njriley/mail/.imap/Deleted Messages/dovecot.index: 
recent_messages_count 2 -> 0
>> dovecot: Feb 25 12:30:40 Error: IMAP(sachs): Corrupted transaction log
>> file /home/sachs/Mail/.imap/INBOX/dovecot.index.log: Extension record
>> update update without intro prefix
>
> Strange. Is dovecot running over NFS or something?
No, mailboxes are on a local disk (FreeBSD 4.10 UFS).
> Can you reproduce any of these problems easily or do they occur only
> randomly?
I am loath to expose the users to these failures, but I will try again 
to test for a short period with 1.0-test65 or later once I get it to 
compile.

-- 
Nicholas Riley <njriley at uiuc.edu>     | 4111 Siebel Center
Department of Computer Science        | 201 N. Goodwin Ave.
and Medical Scholars Program          | Urbana, IL 61801-2302
Univ. of Illinois at Urbana-Champaign | +1 217 244 2274