Hi,
For a few weeks I've been running a custom notification script[1] that uses IMAP NOTIFY. The script uses a single connection, sets up a NOTIFY watch on a couple of mailboxes + automatic FETCH for the selected mailbox. If a status update arrives for a different mailbox, it selects that box and fetches the mail.
Today I got the following error in the log:
Aug 5 14:56:12 karif dovecot[1881]: imap(xxxx)<22699><TBjUXqtyZI5R2c0k>: Panic: file mail.c: line 242 (mail_get_header_stream): assertion failed: (headers->box == mail->box) Aug 5 14:56:12 karif dovecot[1881]: imap(xxxx)<22699><TBjUXqtyZI5R2c0k>: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xcfbff) [0x7fda11806bff] -> /usr/lib/dovecot/libdovecot.so.0(+0xcfcba) [0x7fda11806cba] -> /usr/lib/dovecot/libdovecot.so.0(+0x414bb) [0x7fda117784bb] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x3566e) [0x7fda11aec66e] -> /usr/lib/dovecot/libdovecot-storage.so.0(imap_msgpart_open+0x43b) [0x7fda11bb3a1b] -> dovecot/imap(+0x211ed) [0x55e00d2a21ed] -> dovecot/imap(+0x1f69c) [0x55e00d2a069c] -> dovecot/imap(imap_fetch_more_no_lock_update+0xf) [0x55e00d2a17ff] -> dovecot/imap(+0x23891) [0x55e00d2a4891] -> dovecot/imap(imap_client_notify_newmails+0xfa) [0x55e00d2a4a6a] -> dovecot/imap(imap_sync_more+0x755) [0x55e00d2a9f75] -> dovecot/imap(+0x29006) [0x55e00d2aa006] -> dovecot/imap(cmd_sync_delayed+0x27b) [0x55e00d2aa50b] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0x10d) [0x7fda1181c82d] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd2) [0x7fda1181df52] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x4d) [0x7fda1181caad] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x41) [0x7fda1181cc11] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x14) [0x7fda117a0074] -> dovecot/imap(main+0x342) [0x55e00d28fb82] -> /usr/lib/libc.so.6(__libc_start_main+0xeb) [0x7fda1139e06b] -> dovecot/imap(_start+0x2a) [0x55e00d28fd1a] Aug 5 14:56:12 karif dovecot[1881]: imap(xxxx)<22699><TBjUXqtyZI5R2c0k>: Fatal: master: service(imap): child 22699 killed with signal 6 (core not dumped - https://dovecot.org/bugreport.html#coredumps - set /proc/sys/fs/suid_dumpable to 2)
I'm not sure what happened exactly, but I can tell you that a new mail, that went to the selected mailbox (INBOX), was arriving at the time of the crash.
The script logs the IMAP traffic (sadly without timestamps so far). Here's a slightly censored (3 dots in a few places) and stripped log in the hope that it helps. Lines prefixed with >> are sent to the server, those with << are received from the server.
[login stuff] server-speed >> CMD-2 notify set (selected (MessageExpunge MessageNew (uid body.peek[header.fields (from to subject)]))) (mailboxes (INBOX INBOX.Postmaster ... ... ... ...) (MessageNew MessageExpunge MailboxName)) server-speed << CMD-2 OK NOTIFY completed (0.002 + 0.000 + 0.001 secs). [various untagged fetches/selects + fetch/noops] [script was in a different mailbox, status update for INBOX arrives thus script select INBOX] server-speed >> CMD-51 select INBOX server-speed << * OK [CLOSED] Previous mailbox closed. server-speed << * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk redirected $label2 $label4 $label5 NonJunk $Forwarded $label3 $label1 done Old) server-speed << * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent Junk redirected $label2 $label4 $label5 NonJunk $Forwarded $label3 $label1 done Old \*)] Flags permitted. server-speed << * 20 EXISTS server-speed << * 1 RECENT server-speed << * OK [UNSEEN 14] First unseen. server-speed << * OK [UIDVALIDITY 1336752926] UIDs valid server-speed << * OK [UIDNEXT 41885] Predicted next UID server-speed << * OK [HIGHESTMODSEQ 138681] Highest server-speed << CMD-51 OK [READ-WRITE] Select completed (0.001 + 0.000 secs). server-speed >> CMD-52 uid fetch 41884 (body.peek[header.fields (from to subject)]) server-speed << * 20 FETCH (UID 41884 BODY[HEADER.FIELDS (FROM TO SUBJECT)] {164} server-speed << From: ... server-speed << To: ... server-speed << Subject: ... server-speed << server-speed << ) server-speed << CMD-52 OK Fetch completed (0.001 + 0.000 secs). Got data for notification: [...] Sending notification with data: {...} [the next few lines happen over a span of roughly 9 minutes] server-speed << * 20 EXPUNGE server-speed << * 0 RECENT server-speed << * 8 EXPUNGE server-speed << * 11 EXPUNGE server-speed << * 18 EXISTS server-speed << * 1 RECENT server-speed << * 18 FETCH (UID 41885 [this is apparnently when the server crashed]
I'm afraid I can't reproduce the issue and I don't have the time to try right now, so I can't provide much more information than what is in here. Still, if you have questions, feel free to ask me. Just know that I won't be getting you a better backtrace/coredump any time soon.
[1] https://git.server-speed.net/users/flo/App-ImapNotify/tree/
Florian