dovecot - Jul 2008 - Dovecot 1.1.1 killed with SIGABRT

Hi folks,

with Dovecot 1.1.1, I've had two "crashes" (SIGABRT) recently.
Dovecot 1.1.1 has been compiled from source and is running
on Fedora 8 Linux 32 Bit (all patches) with custom OpenSSL 0.9.8h.

[ output of "dovecot -n" ]
# 1.1.1: /usr/local/dovecot/etc/dovecot.conf
ssl_cert_file: /usr/local/dovecot/etc/dovecot.crt
ssl_key_file: /usr/local/dovecot/etc/dovecot.key
login_dir: /usr/local/dovecot/var/run/dovecot/login
login_executable: /usr/local/dovecot/libexec/dovecot/imap-login
mail_location: mbox:~/Mail:INBOX=/var/spool/mail/%u
auth default:
  mechanisms: plain login digest-md5 cram-md5
  passdb:
    driver: passwd-file
    args: /usr/local/dovecot/etc/dovecot.passwd
  userdb:
    driver: passwd-file
    args: /usr/local/dovecot/etc/dovecot.passwd

First, the "small" problem with Pine 4.64:

Jul 20 03:17:04 linux dovecot: imap-login: Login: user=<user1>,
method=CRAM-MD5, rip=138.201.2.8, lip=138.201.2.2, TLS
Jul 20 03:17:53 linux dovecot: IMAP(user1): UIDVALIDITY changed (1215137127
-> 1216072777) in mbox file /home/user1/Mail/Trash
Jul 20 03:17:53 linux dovecot: Panic: IMAP(user1): file
mail-index-transaction.c: line 548 (mail_index_transaction_get_next_uid):
assertion failed: (recs[count-1].uid >= next_uid)
Jul 20 03:17:53 linux dovecot: IMAP(user1): Raw backtrace: imap [0x80cf2f0]
-> imap [0x80cf34a] -> imap [0x80cec5c] -> imap [0x80ad621] -> imap
[0x80ae56b] -> imap(mail_cache_get_first_new_seq+0x12) [0x80a1d82] ->
imap(mail_cache_field_want_add+0x8d) [0x80a555d] ->
imap(index_mail_parse_header_init+0x1cc) [0x80964ac] ->
imap(index_mail_cache_parse_init+0x4e) [0x809696e] ->
imap(mbox_save_init+0x457) [0x807d4a7] -> imap(mailbox_save_init+0x51)
[0x809fd71] -> imap(mail_storage_copy+0xc1) [0x809df31] ->
imap(cmd_copy+0x1d2) [0x805b1f2] -> imap(cmd_uid+0x59) [0x805f489] -> imap
[0x805fe2c] -> imap [0x805fed5] -> imap [0x8060695] ->
imap(client_input+0x5e) [0x80608ae] -> imap(io_loop_handler_run+0x100)
[0x80d6c30] -> imap(io_loop_run+0x28) [0x80d5dc8] -> imap(main+0x4a1)
[0x80683d1] -> /lib/libc.so.6(__libc_start_main+0xe0) [0x149390] -> imap
[0x805a211]
Jul 20 03:17:53 linux dovecot: child 19853 (imap) killed with signal 6

The user didn't configure his Pine properly. He used IMAP to access
his INBOX, but he forgot to configure this for all other folders as
well. Now, Pine modified /home/user1/Mail/Trash directly, and when
Dovecot stumbled upon this file it killed itself with signal 6.

The problem is not reproducible. After this single failure,
Dovecot doesn't seem to have any problems with the folder.

However, instead of this panic operation, Dovecot maybe could issue a
warning or error response to the client so that the user (hopefully)
gets a clue about what's going wrong.

Second, the "big" problem with Thunderbird 2.0.0.14:

Jul 12 01:04:06 linux dovecot: imap-login: Login: user=<user2>,
method=CRAM-MD5, rip=138.201.2.4, lip=138.201.2.2, TLS
Jul 12 01:04:45 linux dovecot: Panic: IMAP(user2): file index-sync.c: line 39
(index_mailbox_set_recent_uid): assertion failed:
(seq_range_exists(&ibox->recent_flags, uid))
Jul 12 01:04:45 linux dovecot: IMAP(user2): Raw backtrace: imap [0x80cf2f0]
-> imap [0x80cf34a] -> imap [0x80cec5c] -> imap [0x809ccba] -> imap
[0x8080d10] -> imap(mbox_sync+0x522) [0x80817d2] -> imap [0x807a334] ->
imap(index_transaction_commit+0x4e) [0x809d99e] -> imap(cmd_copy+0x35f)
[0x805b37f] -> imap(cmd_uid+0x59) [0x805f489] -> imap [0x805fe2c] ->
imap [0x805fed5] -> imap [0x8060695] -> imap(client_input+0x5e)
[0x80608ae] -> imap(io_loop_handler_run+0x100) [0x80d6c30] ->
imap(io_loop_run+0x28) [0x80d5dc8] -> imap(main+0x4a1) [0x80683d1] ->
/lib/libc.so.6(__libc_start_main+0xe0) [0x149390] -> imap [0x805a211]
Jul 12 01:04:45 linux dovecot: child 25672 (imap) killed with signal 6
[happens over and over in an endless loop until Thunderbird is killed]

This has been a nasty one. Different user, different mail client.

INBOX with 350 messages in total, 3 of them new. Started Thunderbird,
index page is displayed fine, then clicked on one of the 3 new messages
to read it. For no apparent reason, Dovecot dies with signal 6.
Thunderbird reconnected automatically, and then Dovecot dies again.
Nice endless loop ...

Stopping and restarting the complete Dovecot subsystem with the help
of the init.d script didn't help. Finally the crashes stopped after
removing the cache files in /home/fubar/Mail/.imap/INBOX.

It's obvious that the cache files got corrupted somehow. There was
plenty of disk space free. And the cache files have been freshly
created from scratch with Dovecot 1.1.0. Other folders were not
affected. Except Dovecot, nobody ever touches these cache files.

Well, the good news is, it stopped crashing after removing the cache
files. The bad news is, without the cache files (which I removed)
the problem cannot be reproduced.

So, there's nothing more to offer than these two backtraces. Both
crashes are not related to each other and happened to different users
with different clients.

Maybe the backtraces and my descriptions help to find what's
going wrong or how to make Dovecot behave more robustly. If there's
any additional information needed, please let me know. Sorry that I
didn't save the corrupted cache files.

	Greetings, Andreas

On Mon, 2008-07-21 at 01:24 +0200, Andreas M. Kirchwitz
wrote:
> First, the "small" problem with Pine 4.64:
> 
> Jul 20 03:17:04 linux dovecot: imap-login: Login: user=<user1>,
method=CRAM-MD5, rip=138.201.2.8, lip=138.201.2.2, TLS
> Jul 20 03:17:53 linux dovecot: IMAP(user1): UIDVALIDITY changed (1215137127
-> 1216072777) in mbox file /home/user1/Mail/Trash
> Jul 20 03:17:53 linux dovecot: Panic: IMAP(user1): file
mail-index-transaction.c: line 548 (mail_index_transaction_get_next_uid):
assertion failed: (recs[count-1].uid >= next_uid)
Fixed: http://hg.dovecot.org/dovecot-1.1/rev/ea00b1553ef1
> However, instead of this panic operation, Dovecot maybe could issue a
> warning or error response to the client so that the user (hopefully)
> gets a clue about what's going wrong.
This should be transparent to the client. After the above fix it still
logs the warning and also a couple of more errors that I should probably
look into why they're happening.
> Jul 12 01:04:45 linux dovecot: Panic: IMAP(user2): file index-sync.c: line
39 (index_mailbox_set_recent_uid): assertion failed:
(seq_range_exists(&ibox->recent_flags, uid))
This seems to be happening with some mbox users. I guess I should try to
look at it again, but I haven't been able to reproduce it myself so far.
If you've any idea how to somewhat easily reproduce it, I'd like to
know.

If it still happens randomly, you could just comment out that line.
That'll cause recent flags to be somewhat wrong sometimes, but
Thunderbird doesn't care about them.
> INBOX with 350 messages in total, 3 of them new. Started Thunderbird,
> index page is displayed fine, then clicked on one of the 3 new messages
> to read it. For no apparent reason, Dovecot dies with signal 6.
> Thunderbird reconnected automatically, and then Dovecot dies again.
> Nice endless loop ...
If this still happens, I'd really like to have:

1. Output of "find ~/Maildir" (i.e. a list of all files in maildir)
2. dovecot-uidlist
3. dovecot.index and dovecot.index.log

None of those should contain anything sensitive about the mailbox
contents.
> Stopping and restarting the complete Dovecot subsystem with the help
> of the init.d script didn't help. Finally the crashes stopped after
> removing the cache files in /home/fubar/Mail/.imap/INBOX.
> 
> It's obvious that the cache files got corrupted somehow. There was
> plenty of disk space free. And the cache files have been freshly
> created from scratch with Dovecot 1.1.0. Other folders were not
> affected. Except Dovecot, nobody ever touches these cache files.
By "cache files" do you mean dovecot.index*? The dovecot.index.cache
file should have nothing to do with this problem.
> Well, the good news is, it stopped crashing after removing the cache
> files. The bad news is, without the cache files (which I removed)
> the problem cannot be reproduced.
Yes, it would have been nice to have them.. :)

Was this a completely new Dovecot installation, so Dovecot v1.0 was
never run?
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20080721/b004597a/attachment-0002.bin>

Timo Sirainen wrote:

 > Fixed: http://hg.dovecot.org/dovecot-1.1/rev/ea00b1553ef1
 
Great, thanks!

 >> Jul 12 01:04:45 linux dovecot: Panic: IMAP(user2): file index-sync.c:
line 39 (index_mailbox_set_recent_uid): assertion failed:
(seq_range_exists(&ibox->recent_flags, uid))
 > 
 >> Stopping and restarting the complete Dovecot subsystem with the help
 >> of the init.d script didn't help. Finally the crashes stopped
after
 >> removing the cache files in /home/user2/Mail/.imap/INBOX.
 >
 > By "cache files" do you mean dovecot.index*? The
dovecot.index.cache
 > file should have nothing to do with this problem.
 
Hmm, yes, I think so. But now that you ask, hmm, there might be a
slight chance that I also stripped the IMAP-related header keywords
(X-IMAP*, X-UID*) from /var/spool/mail/user2. But before you asked
I was pretty sure I just removed the directory ~user2/Mail/.imap/INBOX
(containing dovecot.index, dovecot.index.cache and dovecot.index.log).

The reason I'm not 100% sure is that, after things were working again,
I stopped Dovecot, removed all caches (Dovecot + Thunderbird) and
*then* stripped the IMAP-related header keywords; just to make sure
that all applications don't use any "bad data" that were left over
by the crash. Well, it happened a week ago... I'm really unsure now,
sorry.

Would that make more sense if I had not just removed the cache
files but also stripped the IMAP-related header keywords from
the INBOX file?

 > Was this a completely new Dovecot installation, so Dovecot v1.0 was
 > never run?

When I replaced Dovecot 1.0 with the new Dovecot 1.1, I removed
the cache files (rm -rf /home/*/Mail/.imap) and also stripped the
IMAP-related header keywords from all mbox files (X-IMAP*, X-UID*).
Don't worry, I don't do this for every update, but I did a lot of
things with my old Dovecot 1.0 installation, and I had this feeling
that now it's a good time for some clean-up. ;-)

Btw, I've had this problem only once. Never before, never after that.
So whatever it is, it happens very rarely. If it happens again,
I promise, I'll better keep track of my actions and all files.

	Greetings ... Andreas