[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:327
I'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 connected
How 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@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/userdb
Best Wishes, Chris
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@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
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 *map
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). :)
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 *map
OK:
(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@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
On Wed, 2009-09-30 at 14:54 +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)
This was actually a pretty rare problem that happened when two processes tried to create a previously non-existing Dovecot index at the exact same time, but they had a different value in "current time" variable (by one second). This'll fix it: http://hg.dovecot.org/dovecot-1.2/rev/1fb19e1c84f5
So next problem: the login process crashing..
Timo Sirainen wrote:
On Wed, 2009-09-30 at 14:54 +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)
This was actually a pretty rare problem that happened when two processes tried to create a previously non-existing Dovecot index at the exact same time, but they had a different value in "current time" variable (by one second). This'll fix it: http://hg.dovecot.org/dovecot-1.2/rev/1fb19e1c84f5
So next problem: the login process crashing..
I've put in the patched imap-login and turned on per-process setid core dumps with "coreadm -e proc-setid" (I don't think we need the global setid ones). We had a few more imap-login crashes a few minutes before I made the changes :|
Anyway, I've seen lots of
imap-login: Error: proxy: Unexpected input, ignoring: C OK CAPABILITY completed.:
since the update. Looks pretty harmless to me though?
Best Wishes, Chris
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@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
On Wed, 2009-09-30 at 17:21 +0100, Chris Wakelin wrote:
I've put in the patched imap-login and turned on per-process setid core dumps with "coreadm -e proc-setid" (I don't think we need the global setid ones). We had a few more imap-login crashes a few minutes before I made the changes :|
Did you also add -D parameter to imap-login? I don't think it otherwise can write core files (but who knows, maybe it can). You could also test it yourself by just kill -SEGV <imap-login pid>
imap-login: Error: proxy: Unexpected input, ignoring: C OK CAPABILITY completed.:
since the update. Looks pretty harmless to me though?
Harmless yes, but a bug anyway. This should fix it: http://hg.dovecot.org/dovecot-1.2/rev/5053bfd20001
Timo Sirainen wrote:
On Wed, 2009-09-30 at 17:21 +0100, Chris Wakelin wrote:
I've put in the patched imap-login and turned on per-process setid core dumps with "coreadm -e proc-setid" (I don't think we need the global setid ones). We had a few more imap-login crashes a few minutes before I made the changes :|
Did you also add -D parameter to imap-login? I don't think it otherwise can write core files (but who knows, maybe it can). You could also test it yourself by just kill -SEGV <imap-login pid>
No, according to the coreadm man page the core file gets written as root (and kill -SEGV worked on the test box).
I've only just spotted that we got one a few hours ago:
Sep 30 17:36:53 dovecot: Error: child 24413 (login) killed with signal 11 (core dumped) (latest ip=82.33.xx.xx)
(so not the Prayer server this time; someone via an ISP, for which we only allow IMAPS in the firewall). Here's the backtrace:
#0 client_get_extra_disconnect_reason (client=0x635b8) at client-common.c:206 206 if (ssl_require_client_cert) (gdb) bt #0 client_get_extra_disconnect_reason (client=0x635b8) at client-common.c:206 #1 0x299b4 in io_loop_run (ioloop=0x635b8) at ioloop.c:330 #2 0x1d314 in main (argc=0, argv=0xffbefb24, envp=0xffbefb2c) at main.c:487
so it looks like this one could be an SSL issue, but Prayer isn't using SSL; perhaps it just happens to appear as the "latest ip" as it's the most common one, and the crashes were caused by different connections altogether (we have login_process_per_connection = no)?
imap-login: Error: proxy: Unexpected input, ignoring: C OK CAPABILITY completed.: since the update. Looks pretty harmless to me though?
Harmless yes, but a bug anyway. This should fix it: http://hg.dovecot.org/dovecot-1.2/rev/5053bfd20001
Yep, that fixes it. I've seen one other though, occurring twice in fairly quick succession, but for different users (both staff on Exchange but still using Prayer Webmail instead of Outlook Web Access):
Sep 30 21:56:04 auth(default): Info: passwd-file(xxxxxxx,134.225.1.46): No password Sep 30 21:56:04 imap-login: Error: proxy: Unexpected input: + Ready for additional command text.: user=<xxxxxxx>, method=PLAIN, rip=134.225.1.46, lip=134.225.16.6
Sep 30 21:58:07 auth(default): Info: passwd-file(yyyyyyyy,134.225.1.46): No password Sep 30 21:58:07 imap-login: Error: proxy: Unexpected input: + Ready for additional command text.: user=<yyyyyyyy>, method=PLAIN, rip=134.225.1.46, lip=134.225.16.6
BTW the proxy.imap files read as passdbs look like:
<username>:::::::proxy=y nopassword=y host=134.225.1.104
Best Wishes, Chris
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@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
On Sep 30, 2009, at 6:10 PM, Chris Wakelin wrote:
#0 client_get_extra_disconnect_reason (client=0x635b8) at client- common.c:206 206 if (ssl_require_client_cert) (gdb) bt #0 client_get_extra_disconnect_reason (client=0x635b8) at client- common.c:206 #1 0x299b4 in io_loop_run (ioloop=0x635b8) at ioloop.c:330 #2 0x1d314 in main (argc=0, argv=0xffbefb24, envp=0xffbefb2c) at
main.c:487
This looks broken. There's no way it can crash in there. Also it can't
go there directly from io_loop_run(). You sure this core was from imap-
login and not something else?
Sep 30 21:56:04 auth(default): Info: passwd-file(xxxxxxx, 134.225.1.46): No password Sep 30 21:56:04 imap-login: Error: proxy: Unexpected input: + Ready
for additional command text.: user=<xxxxxxx>, method=PLAIN,
rip=134.225.1.46, lip=134.225.16.6
This is it! This is what was causing the crashes I knew about. And now
I also understand it, it's because username or password contained some
characters that caused Dovecot to send LOGIN command using literals
instead of quoted strings, which in turn sends that "+" line which
Dovecot assumed was a reply to AUTHENTICATE command. This fixes it: http://hg.dovecot.org/dovecot-1.2/rev/8e8a706d6905
Now, if you still get crashes, there's something else broken too.
Timo Sirainen wrote:
On Sep 30, 2009, at 6:10 PM, Chris Wakelin wrote:
#0 client_get_extra_disconnect_reason (client=0x635b8) at client-common.c:206 206 if (ssl_require_client_cert) (gdb) bt #0 client_get_extra_disconnect_reason (client=0x635b8) at client-common.c:206 #1 0x299b4 in io_loop_run (ioloop=0x635b8) at ioloop.c:330 #2 0x1d314 in main (argc=0, argv=0xffbefb24, envp=0xffbefb2c) at main.c:487
This looks broken. There's no way it can crash in there. Also it can't go there directly from io_loop_run(). You sure this core was from imap-login and not something else?
It turns out to be just before I replaced the first patched imap-login (with the extra logging patches) with another (with the "C CAPABILITY" fix in as well). How about (from the older binary):
#0 0x1b5d4 in client_get_extra_disconnect_reason (client=0x635b8) at client-common.c:209 209 return t_strdup_printf("(auth failed, %u attempts)", (gdb) bt #0 0x1b5d4 in client_get_extra_disconnect_reason (client=0x635b8) at client-common.c:209 #1 0x299b4 in io_loop_run (ioloop=0x635b8) at ioloop.c:335 #2 0x1d314 in main (argc=0, argv=0xffbefb24, envp=0xffbefb2c) at main.c:491
(gdb still suggests it's not sure it's the right binary, though).
Sep 30 21:56:04 auth(default): Info: passwd-file(xxxxxxx,134.225.1.46): No password Sep 30 21:56:04 imap-login: Error: proxy: Unexpected input: + Ready for additional command text.: user=<xxxxxxx>, method=PLAIN, rip=134.225.1.46, lip=134.225.16.6
This is it! This is what was causing the crashes I knew about. And now I also understand it, it's because username or password contained some characters that caused Dovecot to send LOGIN command using literals instead of quoted strings, which in turn sends that "+" line which Dovecot assumed was a reply to AUTHENTICATE command. This fixes it: http://hg.dovecot.org/dovecot-1.2/rev/8e8a706d6905
the usernames had nothing unusual, just [a-z0-9]*, but of course the passwords could have been anything!
They didn't seem to cause a crash though (I've now renamed the core in case Solaris won't overwrite it with another one).
Now, if you still get crashes, there's something else broken too.
I've patched it again. Let's see what happens!
Best Wishes, Chris
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@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
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.%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
participants (2)
-
Chris Wakelin
-
Timo Sirainen