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>