[Dovecot] dies on start-up: Auth process
I was digging through some of the archives and ran into someone who was having the same problem, but for completely different reasons....i think.
dovecot: Nov 02 07:58:51 Info: Dovecot starting up dovecot: Nov 02 07:58:52 Error: Auth process died too early - shutting down dovecot: Nov 02 07:58:52 Error: child 27673 (login) killed with signal 11 dovecot: Nov 02 07:58:52 Error: child 27672 (login) killed with signal 11 dovecot: Nov 02 07:58:52 Error: child 27671 (login) killed with signal 11 dovecot: Nov 02 07:58:52 Error: child 27670 (auth) killed with signal 11
So I took the advice posted and ran 'strace dovecot' and this is what I got. Unfortunately I'm not exactly good enough with this to even know what I'm looking at.
But I suspect the notation about "/dev/null" might have something to do with it. my user, dovecot as a shell of /bin/bash and a $HOME of /usr/local/lib/dovecot By all rights, he's almost a regular user, except that his UID is <100 (I built user:dovecot as a system uid under SuSE 8.2)
open("/var/run/dovecot/", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0 close(3) = 0 lstat64("/var/run/dovecot/", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0 open(".", O_RDONLY|O_LARGEFILE) = 3 open("/var/run/dovecot//login", O_RDONLY|O_LARGEFILE|O_NOFOLLOW) = 4 fchdir(4) = 0 open("/dev/null", O_RDONLY|O_NONBLOCK|O_DIRECTORY) = -1 ENOTDIR (Not a directory) open(".", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 6 fstat64(6, {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 fcntl64(6, F_SETFD, FD_CLOEXEC) = 0 brk(0) = 0x8061000 brk(0x8062000) = 0x8062000 getdents64(6, /* 2 entries */, 4096) = 48 getdents64(6, /* 0 entries */, 4096) = 0 close(4) = 0 close(6) = 0 fchdir(3) = 0 close(3) = 0 geteuid32() = 0 lstat64("/var/run/dovecot//login", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 open("/var/run/dovecot//login", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 close(3) = 0 lstat64("/var/run/dovecot//login", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0 access("/usr/local/libexec/dovecot/dovecot-auth", X_OK) = 0 open("/dev/null", O_RDONLY|O_LARGEFILE) = 3 fcntl64(3, F_GETFD) = 0 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0 dup(3) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 6 setsockopt(6, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0 setsockopt(6, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 bind(6, {sa_family=AF_INET, sin_port=htons(143), sin_addr=inet_addr("0.0.0.0")}, 16) = 0 getsockname(6, {sa_family=AF_INET, sin_port=htons(143), sin_addr=inet_addr("0.0.0.0")}, [16]) = 0 listen(6, 8) = 0 fcntl64(6, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 fcntl64(6, F_GETFD) = 0 fcntl64(6, F_SETFD, FD_CLOEXEC) = 0 dup(4) = 7 fcntl64(7, F_GETFD) = 0 fcntl64(7, F_SETFD, FD_CLOEXEC) = 0 dup(4) = 8 fcntl64(8, F_GETFD) = 0 fcntl64(8, F_SETFD, FD_CLOEXEC) = 0 dup(4) = 9 fcntl64(9, F_GETFD) = 0 fcntl64(9, F_SETFD, FD_CLOEXEC) = 0 dup2(4, 0) = 0 dup2(4, 1) = 1 dup2(4, 2) = 2 fork() = 27706 exit_group(0) = ?
Am Sun, 02 Nov 2003 08:07:25 -0500 hat Tom Allison <tallison@tacocat.net> geschrieben:
So I took the advice posted and ran 'strace dovecot' and this is what I got. Unfortunately I'm not exactly good enough with this to even know what I'm looking at.
Can you run "strace -fF dovecot -F", so it traces the children that die prematurely?
Your trace doesn't show processes that terminate by receiving a certain signal, unfortunately.
-- Matthias Andree
Matthias Andree wrote:
Am Sun, 02 Nov 2003 08:07:25 -0500 hat Tom Allison <tallison@tacocat.net> geschrieben:
So I took the advice posted and ran 'strace dovecot' and this is what I got. Unfortunately I'm not exactly good enough with this to even know what I'm looking at.
Can you run "strace -fF dovecot -F", so it traces the children that die prematurely?
Your trace doesn't show processes that terminate by receiving a certain signal, unfortunately.
I did that, but it's too large to post and I can't send it to you directly. I'm getting my mail rejected as part of a DUL group.
Any suggestions?
On Mon, Nov 03, 2003 at 06:56:53AM -0500, Tom Allison wrote:
Can you run "strace -fF dovecot -F", so it traces the children that die prematurely?
Your trace doesn't show processes that terminate by receiving a certain signal, unfortunately.
I did that, but it's too large to post and I can't send it to you directly. I'm getting my mail rejected as part of a DUL group.
Any suggestions?
[pid 26281] stat64("/usr/local/lib/dovecot/auth/pam.so", 0xbffffcd0) = -1 ENOENT (No such file or directory)
This seems to indicate that you have set auth_passdb = pam, but without PAM support compiled in so it tries to look it up as module and still doesn't find it.
[pid 26281] send(4, "<18>Nov 3 06:36:26 dovecot-auth"..., 59, 0) = 59
And I think this means it should have written "Unknown passdb type 'PAM'" error message to log file. It didn't get there?
On Mon, Nov 03, 2003 at 06:56:53AM -0500, Tom Allison wrote:
Can you run "strace -fF dovecot -F", so it traces the children that die prematurely?
Your trace doesn't show processes that terminate by receiving a certain signal, unfortunately.
I did that, but it's too large to post and I can't send it to you directly. I'm getting my mail rejected as part of a DUL group.
Any suggestions?
[pid 26281] stat64("/usr/local/lib/dovecot/auth/pam.so", 0xbffffcd0) = -1 ENOENT (No such file or directory)
This seems to indicate that you have set auth_passdb = pam, but without PAM support compiled in so it tries to look it up as module and still doesn't find it.
[pid 26281] send(4, "<18>Nov 3 06:36:26 dovecot-auth"..., 59, 0) = 59
And I think this means it should have written "Unknown passdb type 'PAM'" error message to log file. It didn't get there?
IIRC, configure --help showed pam as a default authentication. Do you need to recompile this '--with-pam' as one of the options? I have been compiling this as: ./configure --enable-debug or ./configure --enable-debug --enable-cyrus-sasl2
On Mon, Nov 03, 2003 at 03:45:53PM -0500, tallison@tacocat.net wrote:
IIRC, configure --help showed pam as a default authentication. Do you need to recompile this '--with-pam' as one of the options?
It tries to detect PAM automatically. Running configure should list it in passdb list. If it doesn't, you could check from config.log if there's some errors about PAM.
I have been compiling this as: ./configure --enable-debug or ./configure --enable-debug --enable-cyrus-sasl2
Well, cyrus-sasl2 doesn't actually work at all and you shouldn't really use the debugging, that's mostly meant for my own use :) --enable-debug adds a lot of unnecessary things just so that I can quickly notice if I break some things.
Timo Sirainen wrote:
On Mon, Nov 03, 2003 at 03:45:53PM -0500, tallison@tacocat.net wrote:
IIRC, configure --help showed pam as a default authentication. Do you need to recompile this '--with-pam' as one of the options?
It tries to detect PAM automatically. Running configure should list it in passdb list. If it doesn't, you could check from config.log if there's some errors about PAM.
I have been compiling this as: ./configure --enable-debug or ./configure --enable-debug --enable-cyrus-sasl2
Well, cyrus-sasl2 doesn't actually work at all and you shouldn't really use the debugging, that's mostly meant for my own use :) --enable-debug adds a lot of unnecessary things just so that I can quickly notice if I break some things.
./configure --with-pam | grep pam
returns: configure: line 8578: pkg-config: command not found checking for pam_start in -lpam... no
On Sun, Nov 02, 2003 at 08:07:25AM -0500, Tom Allison wrote:
I was digging through some of the archives and ran into someone who was having the same problem, but for completely different reasons....i think.
dovecot: Nov 02 07:58:51 Info: Dovecot starting up dovecot: Nov 02 07:58:52 Error: Auth process died too early - shutting down dovecot: Nov 02 07:58:52 Error: child 27673 (login) killed with signal 11
See what ldd /usr/local/libexec/dovecot/dovecot-auth says? Are there any unresolved libraries? I don't remember seeing other reasons yet why auth process dies immediately.
Timo Sirainen wrote:
On Sun, Nov 02, 2003 at 08:07:25AM -0500, Tom Allison wrote:
I was digging through some of the archives and ran into someone who was having the same problem, but for completely different reasons....i think.
dovecot: Nov 02 07:58:51 Info: Dovecot starting up dovecot: Nov 02 07:58:52 Error: Auth process died too early - shutting down dovecot: Nov 02 07:58:52 Error: child 27673 (login) killed with signal 11
See what ldd /usr/local/libexec/dovecot/dovecot-auth says? Are there any unresolved libraries? I don't remember seeing other reasons yet why auth process dies immediately.
fluffy:/home/tallison # ldd /usr/local/libexec/dovecot/dovecot-auth libcrypt.so.1 => /lib/libcrypt.so.1 (0x40019000) libdl.so.2 => /lib/libdl.so.2 (0x4004a000) libc.so.6 => /lib/libc.so.6 (0x4004e000) /lib/ld-linux.so.2 => /lib/ld-linux.so.2 (0x40000000) fluffy:/home/tallison #
Tom Allison wrote:
Timo Sirainen wrote:
On Sun, Nov 02, 2003 at 08:07:25AM -0500, Tom Allison wrote:
I was digging through some of the archives and ran into someone who was having the same problem, but for completely different reasons....i think.
dovecot: Nov 02 07:58:51 Info: Dovecot starting up dovecot: Nov 02 07:58:52 Error: Auth process died too early - shutting down dovecot: Nov 02 07:58:52 Error: child 27673 (login) killed with signal 11
I'm making some slow progress. It seemd to be better after I've added a configuration option for cyrus-sasl2 support and set the auth_userdb = passwd.
It loads.
but logging in is another matter entirely.
I can't seem to authenticate.
Tom Allison wrote:
Tom Allison wrote:
Timo Sirainen wrote:
On Sun, Nov 02, 2003 at 08:07:25AM -0500, Tom Allison wrote:
I was digging through some of the archives and ran into someone who was having the same problem, but for completely different reasons....i think.
dovecot: Nov 02 07:58:51 Info: Dovecot starting up dovecot: Nov 02 07:58:52 Error: Auth process died too early - shutting down dovecot: Nov 02 07:58:52 Error: child 27673 (login) killed with signal 11
I'm making some slow progress. It seemd to be better after I've added a configuration option for cyrus-sasl2 support and set the auth_userdb = passwd.
It loads.
but logging in is another matter entirely.
I can't seem to authenticate.
Found the strace segment that has the response 'NO Authentication failed'
srw-rw-rw- /var/run/.nscd_socket drwxr-xr-x /home/tallison/Maildir
My log shows: imap-login: .. Warning Killed with signal 2
And I can use the user/passwd listed to login at the terminal and via SSH. Don't worry, this is behind a firewall right now and this specific account will be converted to a spam-trap once I launch so I really don't care about having a password exposed right now.
I'm getting closer.....
[pid 32035] <... poll resumed> [{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=0, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNV AL}, {fd=8, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=9, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=10, events=POLLIN| POLLPRI|POLLERR|POLLHUP|POLLNVAL, revents=POLLIN}, {fd=11, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 6, 4367) = 1 [pid 32038] write(8, "\0tallison\0Appl3", 15 <unfinished ...> [pid 32035] gettimeofday( <unfinished ...> [pid 32038] <... write resumed> ) = 15 [pid 32035] <... gettimeofday resumed> {1067865382, 123624}, {300, 0}) = 0 [pid 32038] gettimeofday( <unfinished ...> [pid 32035] read(10, <unfinished ...> [pid 32038] <... gettimeofday resumed> {1067865382, 123963}, NULL) = 0 [pid 32035] <... read resumed> "\2\0\0\0\1\0\0\0\17\0\0\0\0tallison\0Appl3", 4076) = 27 [pid 32038] poll( <unfinished ...> [pid 32035] socket(PF_UNIX, SOCK_STREAM, 0) = 12 [pid 32035] connect(12, {sa_family=AF_UNIX, path="/var/run/.nscd_socket"}, 110) = 0 [pid 32035] writev(12, [{"\2\0\0\0\0\0\0\0\t\0\0\0", 12}, {"tallison\0", 9}], 2) = 21 [pid 32035] read(12, "L\'\33@\1\0\0\0\t\0\0\0\2\0\0\0\364\1\0\0d\0\0\0\f\0\0"..., 36) = 36 [pid 32035] read(12, "tallison\0x\0Tom Allison\0/home/tal"..., 48) = 48 [pid 32035] close(12) = 0 [pid 32035] write(10, "\1\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 20 <unfinished ...> [pid 32038] <... poll resumed> [{fd=8, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL, revents=POLLIN}, {fd=3, events=POLLIN|POLLPRI|POLLER R|POLLHUP|POLLNVAL}, {fd=7, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 3, 328) = 1 [pid 32035] <... write resumed> ) = 20 [pid 32038] gettimeofday({1067865382, 131212}, {300, 0}) = 0 [pid 32038] read(8, "\1\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4068) = 20 [pid 32038] write(7, "1 NO Authentication failed.", 27) = 27 [pid 32038] write(7, "\r\n", 2) = 2 [pid 32038] gettimeofday({1067865382, 132062}, NULL) = 0 [pid 32038] poll( <unfinished ...> [pid 32035] gettimeofday({1067865382, 132352}, NULL) = 0 [pid 32035] poll( <unfinished ...>
participants (4)
-
Matthias Andree
-
tallison＠tacocat.net
-
Timo Sirainen
-
Tom Allison