[Dovecot] imap signal 6 crash with backtrace (1.2rc5)
GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu"... Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libdl-2.9.so...done. done. Loaded symbols for /lib/i686/cmov/libdl.so.2 Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from /usr/lib/debug/lib/i686/cmov/libc-2.9.so...done. done. Loaded symbols for /lib/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.9.so...done. done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/local/lib/dovecot/imap/lib10_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib10_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_trash_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_trash_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_autocreate_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_autocreate_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_fts_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_fts_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_zlib_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_zlib_plugin.so Reading symbols from /usr/lib/libz.so.1...done. Loaded symbols for /usr/lib/libz.so.1 Reading symbols from /lib/libbz2.so.1.0...done. Loaded symbols for /lib/libbz2.so.1.0 Reading symbols from /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so Reading symbols from /lib/libgcc_s.so.1...done. Loaded symbols for /lib/libgcc_s.so.1 Core was generated by `imap [virus-al 127.0.0.1]'. Program terminated with signal 6, Aborted. [New process 2286] #0 0xb8027424 in __kernel_vsyscall () #0 0xb8027424 in __kernel_vsyscall () No symbol table info available. #1 0xb7ee2680 in *__GI_raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64 resultvar = <value optimized out> pid = -1207881740 selftid = 2286 #2 0xb7ee5d68 in *__GI_abort () at abort.c:88 act = {__sigaction_handler = {sa_handler = 0x9407170, sa_sigaction = 0x9407170}, sa_mask = {__val = {3219650520, 135193418, 3087083232, 0, 3219650640, 3219650628, 512, 0, 0, 3219650704, 3087292016, 134566083, 639, 0, 0, 0, 1, 135264238, 512, 1, 3219650628, 155218256, 69, 3219650756, 3219650600, 135195014, 155218927, 3219650628, 3219650632, 640, 155218288, 3086525667}}, sa_flags = 640, sa_restorer = 0x8105449 <write_full+57>} sigs = {__val = {32, 0 <repeats 31 times>}} #3 0x080f04a5 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:160 backtrace = 0x9406d40 "imap [0x80f0491] -> imap [0x80f0512] -> imap [0x80efe99] -> imap [0x80ac7e1] -> imap(index_mailbox_set_recent_seq+0x40) [0x80ac830] -> imap(maildir_sync_index+0xaa0) [0x807b330] -> imap [0x8079a49] ->"... #4 0x080f0512 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x8107fcc "file %s: line %d (%s): assertion failed: (%s)", args=0xbfe7f924 "�X\021\b\031") at failures.c:440 No locals. #5 0x080efe99 in i_panic ( format=0x8107fcc "file %s: line %d (%s): assertion failed: (%s)") at failures.c:207 No locals. #6 0x080ac7e1 in index_mailbox_set_recent_uid (ibox=0x9437ae8, uid=1) at index-sync.c:25 __PRETTY_FUNCTION__ = "index_mailbox_set_recent_uid" #7 0x080ac830 in index_mailbox_set_recent_seq (ibox=0x9437ae8, view=0x941d490, seq1=2, seq2=3) at index-sync.c:42 uid = 1 #8 0x0807b330 in maildir_sync_index (ctx=0x9439ab0, partial=true) at maildir-sync-index.c:554 mbox = (struct maildir_mailbox *) 0x9437ae8 view = (struct mail_index_view *) 0x941db30 view2 = (struct mail_index_view *) 0x941d490 iter = (struct maildir_uidlist_iter_ctx *) 0x0 trans = (struct mail_index_transaction *) 0x941cbb0 hdr = (const struct mail_index_header *) 0x941e5d0 empty_hdr = {major_version = 1 '\001', minor_version = 0 '\0', base_header_size = 0, header_size = 7687, record_size = 100, compat_flags = 0 '\0', unused = "\000\000", indexid = 0, flags = 0, uid_validity = 145, next_uid = 0, messages_count = 4096, unused_old_recent_messages_count = 8, seen_messages_count = 0, deleted_messages_count = 1245502813, first_recent_uid = 0, first_unseen_uid_lowwater = 1245502813, first_deleted_uid_lowwater = 0, log_file_seq = 1245502813, log_file_tail_offset = 0, log_file_head_offset = 12386328, sync_size = 13828297038023884800, sync_stamp = 155303216, day_stamp = 3219651144, day_first_uid = {135197247, 155303216, 155306120, 3219651320, 134735536, 3219651300, 0, 0}} rec = <value optimized out> seq = 1 seq2 = 3 uid = 70 prev_uid = 70 uflags = MAILDIR_UIDLIST_REC_FLAG_RECENT filename = 0x943a7f8 "1245502772.M197059P20490.postamt.charite.de,S=3934,W=4010" uid_validity = 1245502772 next_uid = <value optimized out> hdr_next_uid = 71 first_recent_uid = 1 first_uid = 1 changes = 0 ret = 0 time_before_sync = 1245502813 st = {st_dev = 120259084608, __pad1 = 1, __st_ino = 125064, st_mode = 135423232, st_nlink = 155425752, st_uid = 155214344, st_gid = 3219651224, st_rdev = 581638352693814272, __pad2 = 65024, st_size = 0, st_blksize = 6334504, st_blocks = 8589951424, st_atim = { tv_sec = 7687, tv_nsec = 100}, st_mtim = {tv_sec = 0, tv_nsec = 0}, st_ctim = {tv_sec = 0, tv_nsec = 274432}, st_ino = 17592186044416} expunged = 9 full_rescan = false __PRETTY_FUNCTION__ = "maildir_sync_index" #9 0x08079a49 in maildir_sync_context (ctx=0x9406208, forced=false, find_uid=0x0, lost_files_r=0xbfe7fb7b) at maildir-sync.c:847 sync_flags = 155423616 flags = 135313235 new_changed = true cur_changed = false lock_failure = false fname = 0x9437c80 "/home/v/i/virus-al/Maildir" ret = <value optimized out> __PRETTY_FUNCTION__ = "maildir_sync_context" #10 0x08079e15 in maildir_storage_sync_init (box=0x9437ae8, flags=0) at maildir-sync.c:916 _data_stack_cur_id = 3 ctx = (struct maildir_sync_context *) 0x9406208 lost_files = <value optimized out> ret = 0 __PRETTY_FUNCTION__ = "maildir_storage_sync_init" #11 0x0806fe04 in imap_sync_init (client=0x9413360, box=0x9437ae8, imap_flags=IMAP_SYNC_FLAG_SAFE, flags=0) at imap-sync.c:146 ctx = (struct imap_sync_context *) 0x9439520 __PRETTY_FUNCTION__ = "imap_sync_init" #12 0x08070103 in cmd_sync_delayed (client=0x9413360) at imap-sync.c:591 cmd = <value optimized out> first_expunge = <value optimized out> first_nonexpunge = <value optimized out> __PRETTY_FUNCTION__ = "cmd_sync_delayed" #13 0x0806772c in client_handle_input (client=0x9413360) at client.c:728 ret = false remove_io = false handled_commands = true __PRETTY_FUNCTION__ = "client_handle_input" #14 0x08067eff in client_input (client=0x9413360) at client.c:752 cmd = <value optimized out> output = (struct ostream *) 0x9413514 bytes = <value optimized out> __PRETTY_FUNCTION__ = "client_input" #15 0x080f90c0 in io_loop_handler_run (ioloop=0x940fd88) at ioloop-epoll.c:208 ctx = (struct ioloop_handler_context *) 0x940ea80 event = (const struct epoll_event *) 0x940eac0 list = (struct io_list *) 0x9413598 io = (struct io_file *) 0x9413570 tv = {tv_sec = 1799, tv_usec = 999799} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #16 0x080f8530 in io_loop_run (ioloop=0x940fd88) at ioloop.c:338 No locals. #17 0x08070985 in main (argc=) at main.c:323 No locals. $1 = {prev = 0x0, next = 0x0, client = 0x9413360, pool = 0x94135d8, tag = 0x9413668 "a0195", name = 0x9413670 "NOOP", args = 0x0, cmd_flags = COMMAND_FLAG_BREAKS_SEQS, func = 0, context = 0x0, module_contexts = {arr = {buffer = 0x9413630, element_size = 4}, v = 0x9413630, v_modifiable = 0x9413630}, parser = 0x94185e0, state = CLIENT_COMMAND_STATE_WAIT_SYNC, sync = 0x9413678, uid = 0, cancel = 0, param_error = 0, search_save_result = 0, temp_executed = 0} (gdb) quit
from my log:
Jun 20 15:00:13 postamt dovecot: IMAP(virus-al): /home/v/i/virus-al/Maildir/dovecot-uidlist: next_uid was lowered (70 -> 2)
Jun 20 15:00:13 postamt dovecot: IMAP(virus-al): Panic: file index-sync.c: line 25 (index_mailbox_set_recent_uid): assertion failed: (seq_range_exists(&ibox->recent_flags, uid))
Jun 20 15:00:13 postamt dovecot: IMAP(virus-al): Raw backtrace: imap [0x80f0491] -> imap [0x80f0512] -> imap [0x80efe99] -> imap [0x80ac7e1] -> imap(index_mailbox_set_recent_seq+0x40) [0x80ac830] -> imap(maildir_sync_index+0xaa0) [0x807b330] -> imap [0x8079a49] -> imap(maildir_storage_sync_init+0x125) [0x8079e15] -> imap(imap_sync_init+0x54) [0x806fe04] -> imap(cmd_sync_delayed+0x223) [0x8070103] -> imap(client_handle_input+0x1bc) [0x806772c] -> imap(client_input+0x5f) [0x8067eff] -> imap(io_loop_handler_run+0xe0) [0x80f90c0] -> imap(io_loop_run+0x20) [0x80f8530] -> imap(main+0x5f5) [0x8070985] -> /lib/i686/cmov/libc.so.6(__libc_start_main+0xe5) [0xb7ecd775] -> imap [0x805fce1]
Jun 20 15:00:13 postamt dovecot: dovecot: child 2286 (imap) killed with signal 6 (core dumped)
-- Ralf Hildebrandt Postfix - Einrichtung, Betrieb und Wartung Tel. +49 (0)30-450 570-155 http://www.computerbeschimpfung.de Sollen sich auch alle schämen, die gedankenlos sich der Wunder der Wissenschaft und Technik bedienen und nicht mehr davon geistig erfaßt haben, als die Kuh von der Botanik der Pflanzen, die sie mit Wohlbehagen frißt. -- A. Einstein
On Jun 20, 2009, at 9:27 AM, Ralf Hildebrandt wrote:
Jun 20 15:00:13 postamt dovecot: IMAP(virus-al): /home/v/i/virus-al/Maildir/dovecot-uidlist: next_uid was lowered (70
-> 2)
Any idea why this happened? next_uid really shouldn't get lowered. Did
something e.g. restore an older dovecot-uidlist to the Maildir?
- Timo Sirainen <tss@iki.fi>:
On Jun 20, 2009, at 9:27 AM, Ralf Hildebrandt wrote:
Jun 20 15:00:13 postamt dovecot: IMAP(virus-al): /home/v/i/virus-al/Maildir/dovecot-uidlist: next_uid was lowered (70 -> 2)
Any idea why this happened? next_uid really shouldn't get lowered. Did
something e.g. restore an older dovecot-uidlist to the Maildir?
virus-al is a mailbox that holds quarantined spam. I'm the only person accessing it AND when this happened, I was (as usual) the only person looking at the mailbox. I logged in using mutt from localhost via IMAP.
I checked: there are no scripts that (for example) delete files from the maildir
-- Ralf Hildebrandt Postfix - Einrichtung, Betrieb und Wartung Tel. +49 (0)30-450 570-155 http://www.computerbeschimpfung.de "Whom computers would destroy, they must first drive mad." -- Anon.
On Sat, 2009-06-20 at 22:02 +0200, Ralf Hildebrandt wrote:
- Timo Sirainen <tss@iki.fi>:
On Jun 20, 2009, at 9:27 AM, Ralf Hildebrandt wrote:
Jun 20 15:00:13 postamt dovecot: IMAP(virus-al): /home/v/i/virus-al/Maildir/dovecot-uidlist: next_uid was lowered (70 -> 2)
Any idea why this happened? next_uid really shouldn't get lowered. Did
something e.g. restore an older dovecot-uidlist to the Maildir?virus-al is a mailbox that holds quarantined spam. I'm the only person accessing it AND when this happened, I was (as usual) the only person looking at the mailbox. I logged in using mutt from localhost via IMAP.
I checked: there are no scripts that (for example) delete files from the maildir
Is it possible that the entire virus-al mailbox gets deleted and recreated (while the mailbox is open)? Do you have any "UIDVALIDITY changed" lines in logs? Wonder if these would do something:
http://hg.dovecot.org/dovecot-1.2/rev/51aee73e49a5 http://hg.dovecot.org/dovecot-1.2/rev/5a4875e92829
- Timo Sirainen <tss@iki.fi>:
Is it possible that the entire virus-al mailbox gets deleted and recreated (while the mailbox is open)?
No. There may be processes that delete files/mails from the Maildir, though.
Do you have any "UIDVALIDITY changed" lines in logs?
# zfgrep -h virus-al /var/log/OLD/2009-07-*/pop3d-imapd.log |grep UIDVALIDITY Jul 2 02:27:19 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/virus-al/Maildir: UIDVALIDITY changed (1246493487 -> 1246494049) Jul 2 22:25:34 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/virus-al/Maildir: UIDVALIDITY changed (1246564263 -> 1246566306) Jul 18 21:30:00 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/virus-al/Maildir: UIDVALIDITY changed (1247941041 -> 1247944777) That's all for last month
Wonder if these would do something:
http://hg.dovecot.org/dovecot-1.2/rev/51aee73e49a5 http://hg.dovecot.org/dovecot-1.2/rev/5a4875e92829
-- Ralf Hildebrandt Geschäftsbereich IT | Abteilung Netzwerk Charité - Universitätsmedizin Berlin Campus Benjamin Franklin Hindenburgdamm 30 | D-12203 Berlin Tel. +49 30 450 570 155 | Fax: +49 30 450 570 962 ralf.hildebrandt@charite.de | http://www.charite.de
On Jul 27, 2009, at 3:11 AM, Ralf Hildebrandt wrote:
- Timo Sirainen <tss@iki.fi>:
Is it possible that the entire virus-al mailbox gets deleted and recreated (while the mailbox is open)?
No. There may be processes that delete files/mails from the Maildir,
though.Do you have any "UIDVALIDITY changed" lines in logs?
# zfgrep -h virus-al /var/log/OLD/2009-07-*/pop3d-imapd.log |grep
UIDVALIDITY Jul 2 02:27:19 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/ virus-al/Maildir: UIDVALIDITY changed (1246493487 -> 1246494049) Jul 2 22:25:34 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/ virus-al/Maildir: UIDVALIDITY changed (1246564263 -> 1246566306) Jul 18 21:30:00 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/ virus-al/Maildir: UIDVALIDITY changed (1247941041 -> 1247944777) That's all for last month
OK, that definitely means something's either deleting dovecot-uidlist
files or changing that mailbox's index files in some way, which then
causes the UIDVALIDITY changed errors and/or next_uid changed errors.
Neither should really be happening.. I can always try to get those
crashes fixed, but I think the underlying problem is some external
script or something.
- Timo Sirainen <tss@iki.fi>:
# zfgrep -h virus-al /var/log/OLD/2009-07-*/pop3d-imapd.log |grep UIDVALIDITY Jul 2 02:27:19 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/ virus-al/Maildir: UIDVALIDITY changed (1246493487 -> 1246494049) Jul 2 22:25:34 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/ virus-al/Maildir: UIDVALIDITY changed (1246564263 -> 1246566306) Jul 18 21:30:00 postamt dovecot: IMAP(virus-al): Maildir /home/v/i/ virus-al/Maildir: UIDVALIDITY changed (1247941041 -> 1247944777) That's all for last month
OK, that definitely means something's either deleting dovecot-uidlist files or changing that mailbox's index files in some way, which then causes the UIDVALIDITY changed errors and/or next_uid changed errors. Neither should really be happening.. I can always try to get those crashes fixed, but I think the underlying problem is some external script or something.
Could be, but as you can see the crash happens WAY WAY later.
-- Ralf Hildebrandt Geschäftsbereich IT | Abteilung Netzwerk Charité - Universitätsmedizin Berlin Campus Benjamin Franklin Hindenburgdamm 30 | D-12203 Berlin Tel. +49 30 450 570 155 | Fax: +49 30 450 570 962 ralf.hildebrandt@charite.de | http://www.charite.de
On Jul 27, 2009, at 3:29 AM, Ralf Hildebrandt wrote:
OK, that definitely means something's either deleting dovecot-uidlist files or changing that mailbox's index files in some way, which then causes the UIDVALIDITY changed errors and/or next_uid changed errors. Neither should really be happening.. I can always try to get those crashes fixed, but I think the underlying problem is some external script or something.
Could be, but as you can see the crash happens WAY WAY later.
Yes, but the root cause could be the same thing. Sometimes it would
complain about UIDVALIDITY changing, sometimes about next_uid with a
crash.
participants (2)
-
Ralf Hildebrandt
-
Timo Sirainen