Folks:
I've been running Dovecot 2.0.7 on a Qmail / Vpopmail installation built
on Debian Squeeze, with no problems for about a year. Dovecot is used
for IMAP/S auth only.
Dovecot is built from source. I just upgraded to 2.0.15 but it
segfaults whenever an IMAP auth is attempted, regardless of the user who
tries to login, whether by webmail (Roundmail) Android phone (K-9 Mail)
or iPad (Roundmail)
I downgraded to 2.0.13 but the segfault persisted. Re-installed 2.0.7
and that cleared it right up.
Here's the pertinent details from 2.0.15.
Anything else I can provide?
root at XXX:/# uname -a
Linux XXX 2.6.32-5-686 #1 SMP Wed Jan 12 04:01:41 UTC 2011 i686 GNU/Linux
root at XXX:/# dovecot -n
# 2.0.15: /usr/local/etc/dovecot/dovecot.conf
# OS: Linux 2.6.32-5-686 i686 Debian 6.0.3
auth_debug = yes
auth_debug_passwords = yes
auth_verbose = yes
auth_verbose_passwords = plain
disable_plaintext_auth = no
first_valid_uid = XXXX
last_valid_uid = XXXX
log_path = /var/log/dovecot.log
mail_debug = yes
passdb {
driver = vpopmail
}
protocols = imap
service imap-login {
inet_listener imap {
address = *
port = 143
}
inet_listener imaps {
address = *
port = 993
}
process_limit = 128
vsz_limit = 64 M
}
ssl_cert = </etc/ssl/certs/dovecot.pem
ssl_key = </etc/ssl/private/dovecot.pem
userdb {
driver = vpopmail
}
verbose_ssl = yes
Here's a failed login transaction from /var/log/dovecot
[snip -- 10 lines or so. The SSL handshake completes OK]
Nov 15 14:08:43 auth: Debug: client in: AUTH 1 PLAIN
service=imap secured lip=192.xxx.xxx.xxx
rip=174.79.xxx.xxxlport=143 rport=55437
resp=XYXYXYXYXYXXYXYXYXYXYXYXYXYX=Nov 15 14:08:43 auth-worker: Debug: Loading
modules from directory:
/usr/local/lib/dovecot/auth
Nov 15 14:08:43 auth-worker: Debug:
vpopmail(user at mydomain.net,174.79.xxx.xxx): lookup user=user
domain=domain.net
Nov 15 14:08:43 auth: Debug: client out: OK 1 user=user at mydomain.net
Nov 15 14:08:43 auth: Debug: master in: REQUEST 2710831105 686
1 XYXYXYXYXYXXYYXYXYX
Nov 15 14:08:43 auth-worker: Debug:
vpopmail(user at domain.net,174.79.xxx.xxx): lookup user=user domain=domain.net
Nov 15 14:08:43 auth: Error: auth worker: Aborted request: Worker
process died unexpectedly
Nov 15 14:08:43 master: Error: service(auth-worker): child 690 killed
with signal 11 (core dumped)
Nov 15 14:08:43 auth: Debug: master out: FAIL 2710831105
Nov 15 14:08:43 imap: Error: Internal auth failure (client-pid=686
client-id=1)
Nov 15 14:08:43 imap-login: Info: Internal login failure (pid=686 id=1)
(auth failed, 1 attempts): user=<user at domain.net>, method=PLAIN,
rip=174.79.xxx.xxx, lip=192.xxx.xxx.xxx, mpid=691, TLS
Nov 15 14:08:43 imap-login: Warning: SSL alert: where=0x4008, ret=256:
warning close notify [174.79.xxx.xxx]
Nov 15 14:08:43 auth-worker: Debug: Loading modules from directory:
/usr/local/lib/dovecot/auth
I ought to mention that /usr/local/lib/dovecot/auth is empty.
Here's the backtrace:
root at XXX:/# gdb /usr/local/libexec/dovecot/auth
/usr/local/var/run/dovecot/core
GNU gdb (GDB) 7.0.1-debian
[snip]
Reading symbols from /usr/local/libexec/dovecot/auth...done.
warning: Can't read pathname for load map: Input/output error.
Reading symbols from /usr/local/lib/dovecot/libdovecot.so.0...done.
Loaded symbols for /usr/local/lib/dovecot/libdovecot.so.0
Reading symbols from /lib/i686/cmov/libcrypt.so.1...Reading symbols from
/usr/lib/debug/lib/i686/cmov/libcrypt-2.11.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/libcrypt.so.1
Reading symbols from /home/vpopmail/lib/libvpopmail.so...(no debugging
symbols found)...done.
Loaded symbols for /home/vpopmail/lib/libvpopmail.so
Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from
/usr/lib/debug/lib/i686/cmov/libdl-2.11.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/libdl.so.2
Reading symbols from /lib/i686/cmov/librt.so.1...Reading symbols from
/usr/lib/debug/lib/i686/cmov/librt-2.11.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/librt.so.1
Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from
/usr/lib/debug/lib/i686/cmov/libc-2.11.2.so...done.
(no debugging symbols found)...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.11.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/i686/cmov/libpthread.so.0...Reading symbols
from /usr/lib/debug/lib/i686/cmov/libpthread-2.11.2.so...done.
(no debugging symbols found)...done.
Loaded symbols for /lib/i686/cmov/libpthread.so.0
Reading symbols from /home/vpopmail/etc/vpopmail.authmodule...(no
debugging symbols found)...done.
Loaded symbols for /home/vpopmail/etc/vpopmail.authmodule
Core was generated by `dovecot/auth -w'.
Program terminated with signal 11, Segmentation fault.
#0 0x00000000 in ?? ()
(gdb) bt full
#0 0x00000000 in ?? ()
No symbol table info available.
#1 0x08059890 in auth_worker_handle_user (client=0x82b34d0) at
auth-worker-client.c:405
auth_request = 0x82b56e8
userdb_id = 1
#2 auth_worker_handle_line (client=0x82b34d0) at auth-worker-client.c:534
id = 2
#3 auth_worker_input (client=0x82b34d0) at auth-worker-client.c:614
_data_stack_cur_id = 3
line = <value optimized out>
ret = 232
#4 0xb785f021 in io_loop_call_io (io=0x82b3688) at ioloop.c:384
ioloop = 0x82a6398
t_id = 2
#5 0xb78600d3 in io_loop_handler_run (ioloop=0x82a6398) at
ioloop-epoll.c:213
ctx = 0x82b1f38
event = 0x82b1f78
list = 0x82b36b0
io = 0x829e2b0
tv = {tv_sec = 2147483, tv_usec = 0}
msecs = 1
ret = 1
i = 0
j = 0
call = 192
#6 0xb785efa0 in io_loop_run (ioloop=0x82a6398) at ioloop.c:405
No locals.
#7 0xb784abaa in master_service_run (service=0x82a62e8,
callback=0x805c470 <worker_connected>) at master-service.c:481
No locals.
#8 0x0805c828 in main (argc=2, argv=0x82a61c0) at main.c:298
c = <value optimized out>
(gdb)
--mhg
On Tue, 2011-11-15 at 14:31 -0500, Mark Goldey wrote: Could you do a bit more with gdb and this core:> #1 0x08059890 in auth_worker_handle_user (client=0x82b34d0) at > auth-worker-client.c:405 > auth_request = 0x82b56e8 > userdb_id = 1fr 1 p *auth_request->userdb->userdb p *auth_request->userdb->userdb->iface
Your message was discarded by mailman, probably because it was html-only. Anyway: On Wed, 2011-11-16 at 13:15 -0500, Mark Goldey wrote:> (gdb) p *auth_request->userdb->userdb->iface > $2 = {name = 0x807023e "vpopmail", preinit = 0x8065d60 > <vpopmail_preinit>, init = 0, deinit = 0, > lookup = 0x8066010 <vpopmail_lookup>, iterate_init = 0, iterate_next > = 0, iterate_deinit = 0}OK, so "auth_request->userdb->userdb->iface->lookup" should call vpopmail_lookup(), it's not NULL as this says:> > (gdb) bt full > > #0 0x00000000 in ?? ()So something's going strangely wrong. Maybe gcc optimizations cause this and the real problem happens later. Try compiling auth process with optimizations: - Remove -O2 from src/auth/Makefile - cd src/auth ; make clean ; make ; make install Is the backtrace different?
Sorry about the HTML.
I removed the string "-O2" from the /auth Makefile and, for good
measure, did make clean, make and make install for all of Dovecot.
Still, it crashed when trying to log in via IMAP (webmail). Core
dumped, here's the backtrace.
[snip]
Core was generated by `dovecot/auth -w'.
Program terminated with signal 11, Segmentation fault.
#0 0x00000000 in ?? ()
(gdb) bt full
#0 0x00000000 in ?? ()
No symbol table info available.
#1 0x0805b0c7 in auth_worker_handle_user (client=0x82754d0, id=2,
args=0x82601c8) at auth-worker-client.c:405
auth_request = 0x82776e8
userdb_id = 1
#2 0x0805b630 in auth_worker_handle_line (client=0x82754d0,
line=0x82757da
"2\tUSER\t1\tuser=mgoldXX at
goldey.net\tservice=imap\toriginal_username=mgoldXX at
goldey.net\trequested_login_user\tlip=127.0.0.1\trip=127.0.0.1\tlport=143\trport=47574\tsecured=1\tsuccessful=1\tmech=PLAIN")
at auth-worker-client.c:534
args = 0x82601c0
id = 2
ret = false
#3 0x0805b890 in auth_worker_input (client=0x82754d0) at
auth-worker-client.c:614
_data_stack_cur_id = 3
line = 0x82757da
"2\tUSER\t1\tuser=mgoldXX at
goldey.net\tservice=imap\toriginal_username=mgoldXX at
goldey.net\trequested_login_user\tlip=127.0.0.1\trip=127.0.0.1\tlport=143\trport=47574\tsecured=1\tsuccessful=1\tmech=PLAIN"
ret = 183
#4 0xb7726021 in io_loop_call_io (io=0x8275688) at ioloop.c:384
ioloop = 0x8268398
t_id = 2
#5 0xb77270d3 in io_loop_handler_run (ioloop=0x8268398) at
ioloop-epoll.c:213
ctx = 0x8273f38
event = 0x8273f78
list = 0x82756b0
io = 0xbf80049f
tv = {tv_sec = 2147483, tv_usec = 0}
msecs = 1
ret = 1
i = 0
j = 0
call = 192
#6 0xb7725fa0 in io_loop_run (ioloop=0x8268398) at ioloop.c:405
No locals.
#7 0xb7711baa in master_service_run (service=0x82682e8,
callback=0x805e466 <worker_connected>) at master-service.c:481
No locals.
#8 0x0805e7aa in main (argc=2, argv=0x82681c0) at main.c:298
c = -1
And, for good measure:
(gdb) fr 1
#1 0x0805b0c7 in auth_worker_handle_user (client=0x82754d0, id=2,
args=0x82601c8) at auth-worker-client.c:405
405 auth_request->userdb->userdb->iface->
(gdb) p *auth_request->userdb->userdb
$1 = {args = 0x8268d10 "", cache_key = 0x0, blocking = true, id = 1,
init_refcount = 1, iface = 0x807b320}
(gdb) p *auth_request->userdb->userdb->iface
$2 = {name = 0x8074f3d "vpopmail", preinit = 0x8069a27
<vpopmail_preinit>, init = 0, deinit = 0,
lookup = 0x806975f <vpopmail_lookup>, iterate_init = 0, iterate_next 0,
iterate_deinit = 0}
This is all Greek to me, but I'm happy to do more troubleshooting.
--mhg