Chris Wakelin
2009-Sep-30 10:06 UTC
[Dovecot] Some issues in Dovecot 1.2.5 after upgrade from 1.0.15
We upgraded from Dovecot 1.0.15 to 1.2.5 last night, on Solaris 10 using mboxes, mostly without issues. However I had to trash the index/cache files (too many folders were showing corruption issues which is especially bad for Prayer Webmail ".prayer" folders that store preferences; Prayer sees a disconnection as the folder being missing!). I've had one imap process panic in mailbox sync (as I mentioned above, the index files have been newly created in 1.2.5):> Sep 30 09:57:10 imap-login: Info: Login: user=<xxxxxxxx>, method=PLAIN, rip=134.225.xx.xx, lip=134.225.16.6 > Sep 30 09:57:10 imap-login: Info: Login: user=<xxxxxxxx>, method=PLAIN, rip=134.225.xx.xx, lip=134.225.16.6 > Sep 30 09:57:11 IMAP 25384 xxxxxxxx 134.225.xx.xx : Panic: file mail-index-sync-update.c: line 933 (mail_index_sync_map): assertion failed: (map->hdr.indexid == index->indexid || map->hdr.indexid == 0) > Sep 30 09:57:11 dovecot: Error: child 25384 (imap) killed with signal 6 (core dumped)This looks like it was the user's first connection since the upgrade, as well. Here's the backtrace:> #0 0xff21fe78 in _libc_kill () from /usr/lib/libc.so.1 > (gdb) bt > #0 0xff21fe78 in _libc_kill () from /usr/lib/libc.so.1 > #1 0xff1b5a3c in abort () from /usr/lib/libc.so.1 > #2 0xbe258 in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at failures.c:160 > #3 0xbeb14 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x0, args=0xffbee758) at failures.c:440 > #4 0xbe414 in i_panic (format=0xec7f0 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:207 > #5 0x98a00 in mail_index_sync_map (_map=0x1263e4, type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802 > #6 0x8c618 in mail_index_map (index=0x1263a8, type=MAIL_INDEX_SYNC_HANDLER_HEAD) at mail-index-map.c:934 > #7 0x89e30 in mail_index_refresh (index=0x0) at mail-index.c:551 > #8 0x62bec in mbox_sync_header_refresh (mbox=0x1272d8) at mbox-sync.c:1586 > #9 0x62d28 in mbox_sync_has_changed_full (mbox=0x1272d8, leave_dirty=true, empty_r=0xffbeeab7) at mbox-sync.c:1644 > #10 0x62cb4 in mbox_sync_has_changed (mbox=0xffffffff, leave_dirty=true) at mbox-sync.c:1611 > #11 0x63428 in mbox_sync_int (mbox=0x1272d8, flags=0, lock_id=0xffbeee04) at mbox-sync.c:1701 > #12 0x634f4 in mbox_sync (mbox=0x1272d8, flags=0) at mbox-sync.c:1894 > #13 0x63674 in mbox_storage_sync_init (box=0x1272d8, flags=65) at mbox-sync.c:1936 > #14 0x7ebf4 in mailbox_sync_init (box=0x1272d8, flags=65) at mail-storage.c:562 > #15 0x7ecb8 in mailbox_sync (box=0x1272d8, flags=65, status_items=239, status_r=0xffbeefd0) at mail-storage.c:593 > #16 0x29fc0 in select_open (ctx=0x11ebf0, mailbox=0x1 <Address 0x1 out of bounds>, readonly=false) at cmd-select.c:273 > #17 0x2a294 in cmd_select_full (cmd=0x11eb60, readonly=false) at cmd-select.c:382 > #18 0x2a3d0 in cmd_select (cmd=0x11eb60) at cmd-select.c:389 > #19 0x2d064 in client_command_input (cmd=0x11eb60) at client.c:611 > #20 0x2cf08 in client_command_input (cmd=0x11eb60) at client.c:660 > #21 0x2d0ec in client_handle_next_command (client=0x11e8d8, remove_io_r=0xffbef2b7) at client.c:701 > #22 0x2d1e0 in client_handle_input (client=0x11e8d8) at client.c:713 > #23 0x2d318 in client_input (client=0x11e8d8) at client.c:752 > #24 0xc7ea4 in io_loop_handler_run (ioloop=0x11b370) at ioloop-poll.c:203 > #25 0xc7694 in io_loop_run (ioloop=0x11b370) at ioloop.c:335 > #26 0x36e34 in main (argc=1119232, argv=0xffbef4fc, envp=0xffbef50c) at main.c:327I'm also seeing some other errors, e.g. :> Sep 30 10:37:06 auth(default): Error: Master request 15820.607 not found > Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 10:51:38 dovecot: Error: child 11162 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 10:54:03 imap-login: Warning: Error sending handshake to auth server: Transport endpoint is not connectedHow do I get the login (presumably imap-login) processes to dump core (or do I need to insert gdbhelper)? Dovecot -n output (%J is a local hash function and we don't use the lda; my start-up script sets the fd limit to 4096 once Dovecot has started):> # 1.2.5: /opt/RDGdovect/etc/dovecot.conf > Warning: fd limit 2048 is lower than what Dovecot can use under full load (more than 4352). Either grow the limit or change login_max_processes_count and max_mail_processes settings > # OS: SunOS 5.8 sun4u ufs > base_dir: /opt/RDGdovect/var/run/ > log_path: /opt/RDGdovect/var/log/dovecot.log > info_log_path: /opt/RDGdovect/var/log/dovecot.log > protocols: imap imaps pop3 pop3s > listen(default): 134.225.16.6:143 > listen(imap): 134.225.16.6:143 > listen(pop3): 134.225.16.6:110 > ssl_listen(default): 134.225.16.6:993 > ssl_listen(imap): 134.225.16.6:993 > ssl_listen(pop3): 134.225.16.6:995 > ssl_cert_file(default): /opt/RDGdovect/ssl/imap.reading.ac.uk.crt.pem > ssl_cert_file(imap): /opt/RDGdovect/ssl/imap.reading.ac.uk.crt.pem > ssl_cert_file(pop3): /opt/RDGdovect/ssl/pop.reading.ac.uk.crt.pem > ssl_key_file(default): /opt/RDGdovect/ssl/imap.reading.ac.uk.key.pem > ssl_key_file(imap): /opt/RDGdovect/ssl/imap.reading.ac.uk.key.pem > ssl_key_file(pop3): /opt/RDGdovect/ssl/pop.reading.ac.uk.key.pem > disable_plaintext_auth: no > shutdown_clients: no > login_dir: /opt/RDGdovect/var/run/login > login_executable(default): /opt/RDGdovect/libexec/dovecot/imap-login > login_executable(imap): /opt/RDGdovect/libexec/dovecot/imap-login > login_executable(pop3): /opt/RDGdovect/libexec/dovecot/pop3-login > login_greeting(default): University of Reading IMAP ready. > login_greeting(imap): University of Reading IMAP ready. > login_greeting(pop3): University of Reading POP3 ready. > login_process_per_connection: no > max_mail_processes: 4096 > verbose_proctitle: yes > mail_location: mbox:/export/folders/%13.h/mail/:INBOX=/export/mail/%13.h/INBOX:INDEX=/export/indexes/%13.h > mail_nfs_storage: yes > mbox_very_dirty_syncs: yes > mail_drop_priv_before_exec: yes > mail_executable(default): /opt/RDGdovect/libexec/dovecot/imap > mail_executable(imap): /opt/RDGdovect/libexec/dovecot/imap > mail_executable(pop3): /opt/RDGdovect/libexec/dovecot/pop3 > mail_plugins(default): zlib mail_log > mail_plugins(imap): zlib mail_log > mail_plugins(pop3): > mail_plugin_dir(default): /opt/RDGdovect/libexec/plugins > mail_plugin_dir(imap): /opt/RDGdovect/libexec/plugins > mail_plugin_dir(pop3): /opt/RDGdovect/lib/dovecot/pop3 > mail_log_prefix: %Us %p %u %r : > imap_client_workarounds(default): delay-newmail > imap_client_workarounds(imap): delay-newmail > imap_client_workarounds(pop3): > pop3_reuse_xuidl(default): no > pop3_reuse_xuidl(imap): no > pop3_reuse_xuidl(pop3): yes > pop3_uidl_format(default): %08Xu%08Xv > pop3_uidl_format(imap): %08Xu%08Xv > pop3_uidl_format(pop3): %08Xv%08Xu > pop3_client_workarounds(default): > pop3_client_workarounds(imap): > pop3_client_workarounds(pop3): outlook-no-nuls > namespace: > type: private > separator: / > inbox: yes > list: yes > subscriptions: yes > namespace: > type: private > separator: / > prefix: mail/ > hidden: yes > list: no > subscriptions: yes > namespace: > type: private > separator: / > prefix: ~/mail/ > hidden: yes > list: no > subscriptions: yes > namespace: > type: private > separator: / > prefix: ~%u/mail/ > hidden: yes > list: no > subscriptions: yes > lda: > postmaster_address: postmaster at example.com > auth default: > mechanisms: plain login > username_format: %Lu > verbose: yes > passdb: > driver: passwd-file > args: /export/mailconfig/%Ju/%u/migrating > deny: yes > passdb: > driver: passwd-file > args: /export/mailconfig/%Ju/%u/proxy.%Ls > passdb: > driver: ldap > args: /opt/RDGdovect/etc/dovecot-ldap.conf > userdb: > driver: passwd-file > args: /opt/RDGdovect/etc/userdbBest Wishes, Chris -- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin at reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
Timo Sirainen
2009-Sep-30 13:21 UTC
[Dovecot] Some issues in Dovecot 1.2.5 after upgrade from 1.0.15
On Wed, 2009-09-30 at 11:06 +0100, Chris Wakelin wrote:> > Sep 30 09:57:11 IMAP 25384 xxxxxxxx 134.225.xx.xx : Panic: file mail-index-sync-update.c: line 933 (mail_index_sync_map): assertion failed: (map->hdr.indexid == index->indexid || map->hdr.indexid == 0)..> > #5 0x98a00 in mail_index_sync_map (_map=0x1263e4, type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802Could you also do: fr 5 p *index p *map> > Sep 30 10:37:06 auth(default): Error: Master request 15820.607 not foundEither timed out for some reason or some other strange bug..> > Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46)..> How do I get the login (presumably imap-login) processes to dump coreWith Linux this would be enough: login_executable = .../imap-login -D With Solaris you'll also have to somehow make setuid binaries dump core. http://publib.boulder.ibm.com/httpserv/ihsdiag/coredumps.html says you could do: coreadm -e global-setid -e proc-setid -e global Perhaps with those global core dumps it wouldn't even be necessary to add the -D parameter. Anyway the -D's point was to make the /var/run/dovecot/login/ directory writable to it, so it could write core dump there.> (or do I need to insert gdbhelper)?I'm not really sure anymore if that even works (anymore). :) -------------- 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/20090930/953f0147/attachment-0002.bin>
Timo Sirainen
2009-Sep-30 13:37 UTC
[Dovecot] Some issues in Dovecot 1.2.5 after upgrade from 1.0.15
On Wed, 2009-09-30 at 11:06 +0100, Chris Wakelin wrote:> > Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46)..> > passdb: > > driver: passwd-file > > args: /export/mailconfig/%Ju/%u/proxy.%LsYou're using proxying also? Apparently there's something wrong there, perhaps with master user logins or something.. I haven't yet found out what exactly it is, but these should fix the crashes and log more information: http://hg.dovecot.org/dovecot-1.2/rev/b1293abca645 http://hg.dovecot.org/dovecot-1.2/rev/c8e24c1b8468 -------------- 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/20090930/cfc6ff3a/attachment-0002.bin>
Chris Wakelin
2009-Sep-30 13:54 UTC
[Dovecot] Some issues in Dovecot 1.2.5 after upgrade from 1.0.15
Timo Sirainen wrote:> On Wed, 2009-09-30 at 11:06 +0100, Chris Wakelin wrote: >>> Sep 30 09:57:11 IMAP 25384 xxxxxxxx 134.225.xx.xx : Panic: file mail-index-sync-update.c: line 933 (mail_index_sync_map): assertion failed: (map->hdr.indexid == index->indexid || map->hdr.indexid == 0) > .. >>> #5 0x98a00 in mail_index_sync_map (_map=0x1263e4, type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802 > > Could you also do: > > fr 5 > p *index > p *mapOK:> (gdb) fr 5 > #5 0x98a00 in mail_index_sync_map (_map=0x1263e4, type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802 > 802 return 0; > (gdb) p *index > $1 = {dir = 0x1264f8 "/export/indexes/a/120/xxxxxxxx/.imap/INBOX", prefix = 0x11add0 "dovecot.index", cache = 0x127930, log = 0x1271f0, fsync_mask = 0, > mode = 384, gid = -1, gid_origin = 0x1278b8 "/export/mail/a/120/xxxxxxxx/INBOX", extension_pool = 0x126540, extensions = {arr = {buffer = 0x126558, > element_size = 36}, v = 0x126558, v_modifiable = 0x126558}, sync_lost_handlers = {arr = {buffer = 0x11b578, element_size = 4}, v = 0x11b578, > v_modifiable = 0x11b578}, filepath = 0x1278e8 "/export/indexes/a/120/xxxxxxxx/.imap/INBOX/dovecot.index", fd = -1, map = 0x127ac0, > indexid = 1254301030, inconsistency_id = 0, last_read_log_file_seq = 0, last_read_log_file_head_offset = 0, last_read_log_file_tail_offset = 0, > last_read_stat = {st_dev = 0, st_pad1 = {0, 0, 0}, st_ino = 0, st_mode = 0, st_nlink = 0, st_uid = 0, st_gid = 0, st_rdev = 0, st_pad2 = {0, 0}, > st_size = 0, st_atim = {tv_sec = 0, tv_nsec = 0}, st_mtim = {tv_sec = 0, tv_nsec = 0}, st_ctim = {tv_sec = 0, tv_nsec = 0}, st_blksize = 0, > st_blocks = 0, st_fstype = '\000' <repeats 15 times>, st_pad4 = {0, 0, 0, 0, 0, 0, 0, 0}}, fsck_log_head_file_seq = 0, fsck_log_head_file_offset = 0, > lock_type = 3, shared_lock_count = 0, excl_lock_count = 0, lock_id_counter = 2, lock_method = FILE_LOCK_METHOD_FCNTL, file_lock = 0x0, dotlock = 0x0, > keywords_pool = 0x126948, keywords = {arr = {buffer = 0x11b5c8, element_size = 4}, v = 0x11b5c8, v_modifiable = 0x11b5c8}, keywords_hash = 0x126b88, > keywords_ext_id = 0, modseq_ext_id = 1, module_contexts = {arr = {buffer = 0x11b5a0, element_size = 4}, v = 0x11b5a0, v_modifiable = 0x11b5a0}, > error = 0x0, nodiskspace = 0, index_lock_timeout = 0, opened = 1, log_locked = 0, mmap_disable = 0, fsync_disable = 0, use_excl_dotlocks = 1, > nfs_flush = 0, readonly = 0, mapping = 1, syncing = 0, need_recreate = 0, index_min_write = 1, modseqs_enabled = 0, initial_create = 0, > initial_mapped = 1} > (gdb) p *map > $2 = {index = 0x1263a8, refcount = 2, hdr = {major_version = 7 '\a', minor_version = 2 '\002', base_header_size = 120, header_size = 120, record_size = 8, > compat_flags = 0 '\000', unused = "\000\000", indexid = 1254301031, flags = 0, uid_validity = 0, next_uid = 1, messages_count = 0, > unused_old_recent_messages_count = 0, seen_messages_count = 0, deleted_messages_count = 0, first_recent_uid = 1, first_unseen_uid_lowwater = 0, > first_deleted_uid_lowwater = 0, log_file_seq = 2, log_file_tail_offset = 0, log_file_head_offset = 40, sync_size = 0, sync_stamp = 0, day_stamp = 0, > day_first_uid = {0, 0, 0, 0, 0, 0, 0, 0}}, hdr_base = 0x127fc0, hdr_copy_buf = 0x11b640, extension_pool = 0x0, extensions = {arr = {buffer = 0x0, > element_size = 0}, v = 0x0, v_modifiable = 0x0}, ext_id_map = {arr = {buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0}, > keyword_idx_map = {arr = {buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0}, rec_map = 0x127b78, write_base_header = 0, write_ext_header = 0, > write_atomic = 0}I was wrong about it being Solaris 10; the mail server is still on Solaris 8 (with the latest and last patch cluster installed) and Dovecot was compiled with gcc 3.3.2. I've got a backup of the user's INBOX available, but I haven't been able to reproduce the crash on my test box (either with it put through mboxcrypt.pl or without). I've seen no similar crashes (so far) either. Let me know if you'd like me to send the anonymised version (4MB expands to ~70MB).> >>> Sep 30 10:37:06 auth(default): Error: Master request 15820.607 not found > > Either timed out for some reason or some other strange bug.. > >>> Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > .. >> How do I get the login (presumably imap-login) processes to dump core > > With Linux this would be enough: > > login_executable = .../imap-login -D > > With Solaris you'll also have to somehow make setuid binaries dump core. > http://publib.boulder.ibm.com/httpserv/ihsdiag/coredumps.html says you > could do: > > coreadm -e global-setid -e proc-setid -e global > > Perhaps with those global core dumps it wouldn't even be necessary to > add the -D parameter. Anyway the -D's point was to make > the /var/run/dovecot/login/ directory writable to it, so it could write > core dump there. > >> (or do I need to insert gdbhelper)? > > I'm not really sure anymore if that even works (anymore). :)...>>>> Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) >> .. >>>> passdb: >>>> driver: passwd-file >>>> args: /export/mailconfig/%Ju/%u/proxy.%Ls >> >> You're using proxying also? Apparently there's something wrong there, >> perhaps with master user logins or something.. I haven't yet found out >> what exactly it is, but these should fix the crashes and log more >> information: >> >> http://hg.dovecot.org/dovecot-1.2/rev/b1293abca645 >> http://hg.dovecot.org/dovecot-1.2/rev/c8e24c1b8468 >>Yes we're proxying to Exchange 2003 for those users that have a proxy.imap or proxy.pop3 in their mailconfig directory (we migrated most of our staff from Unix mailstore to Exchange without them noticing; all the students, most functional accounts, and staff that have too much mail are still on Unix). I'll look at applying the patches this evening (there's probably no point doing it on the test server as I guess it's triggered by load or something odd in Exchange). Strangely, though we haven't had any crashes since this morning:> Sep 30 00:38:32 dovecot: Error: child 26387 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 00:55:02 dovecot: Error: child 9268 (login) killed with signal 11 (core not dumped) (ip=134.225.1.46) > Sep 30 09:43:07 dovecot: Error: child 13660 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 10:51:38 dovecot: Error: child 11162 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 11:18:05 dovecot: Error: child 23772 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46) > Sep 30 11:20:16 dovecot: Error: child 2120 (login) killed with signal 11 (core not dumped) (latest ip=134.225.1.46)and all of them had latest ip=134.225.1.46, which is our Prayer Webmail server and is used mostly by students (i.e. not people on Exchange). Best Wishes, Chris -- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin at reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094