Assertion failure with IMAP NOTIFY

[Florian Pritz]

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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL: <https://dovecot.org/pipermail/dovecot/attachments/20180805/0a6ac139/attachment.sig>