Sam Michaels schrieb:
> Looks like a socket problem. Did you check the permissions like I
> mentioned? Mine always has the wrong permissions upon reboot when the
> socket is recreated. Socket is defined in the Local/Makefile on
> compile.
You mean permissions of /var/run/saslauthd/mux? Those are fine (777).
> To see more indepth what's going on, run strace on it and it will show
> you what access is denied.
[...]
write(2, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
80saslauthd[56740] :ipc_init : listening on socket:
/var/run/saslauthd/mux
) = 80
gettimeofday({0, 0}, NULL) = 0
getpid() = 56740 (ppid 56739)
sendto(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
99, 0, NULL, 0) = 99
getpid() = 56740 (ppid 56739)
write(2, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
56saslauthd[56740] :main : using process model
) = 56
gettimeofday({0, 0}, NULL) = 0
getpid() = 56740 (ppid 56739)
sendto(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
75, 0, NULL, 0) = 75
fork(saslauthd[56741] :get_accept_lock : acquired accept lock
) = 56741
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] write(2,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
56saslauthd[56740] :have_baby : forked child: 56741
) = 56
[pid 56740] gettimeofday({0, 0}, NULL) = 0
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] sendto(3,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 75, 0,
NULL, 0) = 75
[pid 56740] fork() = 56744
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] write(2,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
56saslauthd[56740] :have_baby : forked child: 56744
) = 56
[pid 56740] gettimeofday({0, 0}, NULL) = 0
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] sendto(3,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 75, 0,
NULL, 0) = 75
[pid 56740] fork() = 56746
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] write(2,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
56saslauthd[56740] :have_baby : forked child: 56746
) = 56
[pid 56740] gettimeofday({0, 0}, NULL) = 0
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] sendto(3,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 75, 0,
NULL, 0) = 75
[pid 56740] fork() = 56748
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] write(2,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
56saslauthd[56740] :have_baby : forked child: 56748
) = 56
[pid 56740] gettimeofday({0, 0}, NULL) = 0
[pid 56740] getpid() = 56740 (ppid 56739)
[pid 56740] sendto(3,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 75, 0,
NULL, 0) = 75
[pid 56740] fcntl(7, F_SETLKW, {type=0 /* F_??? */, whence=SEEK_SET,
start=0, len=0} <unfinished ...>
[pid 56741] fcntl(7, F_SETLKW, {...}) = 0
[pid 56741] getpid( <unfinished ...>
[pid 56744] getpid( <unfinished ...>
[pid 56741] <... getpid resumed> ) = 56741 (ppid 56740)
[pid 56744] <... getpid resumed> ) = 56744 (ppid 56740)
[pid 56741] write(2, 0xbfbfe1d0, 57saslauthd[56741] :rel_accept_lock :
released accept lock
<unfinished ...>
[pid 56744] write(2, 0xbfbfe1d0, 57saslauthd[56744] :get_accept_lock :
acquired accept lock
<unfinished ...>
[pid 56741] <... write resumed> ) = 57
[pid 56744] <... write resumed> ) = 57
[pid 56741] gettimeofday( <unfinished ...>
[pid 56744] gettimeofday( <unfinished ...>
[pid 56741] <... gettimeofday resumed> {...}, NULL) = 0
[pid 56744] <... gettimeofday resumed> {...}, NULL) = 0
[pid 56741] getpid( <unfinished ...>
[pid 56744] getpid( <unfinished ...>
[pid 56741] <... getpid resumed> ) = 56741 (ppid 56740)
[pid 56744] <... getpid resumed> ) = 56744 (ppid 56740)
[pid 56741] sendto(3, 0xbfbfdfa0, 76, 0, NULL, 0 <unfinished ...>
[pid 56744] sendto(3, 0xbfbfdfa0, 76, 0, NULL, 0 <unfinished ...>
[pid 56741] <... sendto resumed> ) = 76
[pid 56744] <... sendto resumed> ) = 76
[pid 56741] read(9, <unfinished ...>
[pid 56744] accept(8, <unfinished ...>
[pid 56741] <... read resumed> 0xbfbfe7ae, 2) = 2
[pid 56741] read(9, 0xbfbfeae0, 6) = 6
[pid 56741] read(9, 0xbfbfe7ae, 2) = 2
[pid 56741] read(9, 0xbfbfe9d0, 6) = 6
[pid 56741] read(9, 0xbfbfe7ae, 2) = 2
[pid 56741] read(9, 0xbfbfe7ae, 2) = 2
[pid 56741] open("/etc/pam.d/", O_RDONLY) = 10
[pid 56741] fstat(10, {st_mode=0, st_size=0, ...}) = 0
[pid 56741] break(0x805a000) = 0
[pid 56741] read(10,
"\363FH\0\f\0\4\1.\0\0\0\365KD\0\f\0\4\2..\0\0RGH\0\20\0"..., 4096) = 512
[pid 56741] break(0x805b000) = 0
[pid 56741] break(0x805c000) = 0
[pid 56741] read(10, "", 4096) = 0
[pid 56741] gettimeofday({4736755, 17039372}, NULL) = 0
[pid 56741] getpid() = 56741 (ppid 56740)
[pid 56741] sendto(3,
".\0\0\0\365KD\0\f\0\4\2..\0\0RGH\0\20\0\10\6README\0\325"..., 111, 0,
NULL, 0) = 111
[pid 56741] close(10) = 0
[pid 56741] gettimeofday({4736818, 50855948}, NULL) = 0
[pid 56741] getpid() = 56741 (ppid 56740)
[pid 56741] sendto(3,
"ftp\0002GH\0\20\0\10\4ftpd\0\333&\325YGH\0\20\0\10\4im"..., 85, 0,
NULL, 0) = 85
[pid 56741] getpid() = 56741 (ppid 56740)
[pid 56741] write(2,
"\0\332&\325WGH\0\f\0\10\3gdm\0\261HH\0\20\0\10\5login\0"...,
120saslauthd[56741] :do_auth : auth failure: [user=USER]
[service=] [realm=] [mech=pam] [reason=PAM start error]
) = 120
[pid 56741] gettimeofday({4737158, 50855948}, NULL) = 0
[pid 56741] getpid() = 56741 (ppid 56740)
[pid 56741] sendto(3,
"kde\0\16VH\0\24\0\10\3xdm\0tmp\0tmp\0hIH\0\20\0\10\5"..., 139, 0, NULL,
0) = 139
[pid 56741] write(9, "ot", 2) = 2
[pid 56741] write(9, "NO PAM start error", 18) = 18
[pid 56741] close(9) = 0
[pid 56741] fcntl(7, F_SETLKW, {type=0x805 /* F_??? */,
whence=0xffff8000 /* SEEK_??? */, start=65280, len=0} <unfinished ...>
[pid 56744] <... accept resumed> {sa_family=AF_UNIX, path=@}, [16]) = 9
[pid 56744] fcntl(7, F_SETLKW, {type=0x12e /* F_??? */, whence=SEEK_SET,
start=577956500568625280, len=577923119948234752}) = 0
[pid 56744] getpid( <unfinished ...>
[pid 56746] getpid( <unfinished ...>
[pid 56744] <... getpid resumed> ) = 56744 (ppid 56740)
[pid 56746] <... getpid resumed> ) = 56746 (ppid 56740)
[pid 56744] write(2, "
\336\4\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0"...,
57saslauthd[56744] :rel_accept_lock : released accept lock
<unfinished ...>
[pid 56746] write(2, 0xbfbfe1d0, 57saslauthd[56746] :get_accept_lock :
acquired accept lock
<unfinished ...>
[pid 56744] <... write resumed> ) = 57
[pid 56746] <... write resumed> ) = 57
[pid 56744] gettimeofday( <unfinished ...>
[pid 56746] gettimeofday( <unfinished ...>
[pid 56744] <... gettimeofday resumed> {0, 0}, NULL) = 0
[pid 56746] <... gettimeofday resumed> {...}, NULL) = 0
[pid 56744] getpid( <unfinished ...>
[pid 56746] getpid( <unfinished ...>
[pid 56744] <... getpid resumed> ) = 56744 (ppid 56740)
[pid 56746] <... getpid resumed> ) = 56746 (ppid 56740)
[pid 56744] sendto(3,
"\0\0\0\0\0\0\0\0p\336\4\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 76, 0,
NULL, 0 <unfinished ...>
[pid 56746] sendto(3, 0xbfbfdfa0, 76, 0, NULL, 0 <unfinished ...>
[pid 56744] <... sendto resumed> ) = 76
[pid 56746] <... sendto resumed> ) = 76
[pid 56744] read(9, <unfinished ...>
[pid 56746] accept(8, <unfinished ...>
[pid 56744] <... read resumed> "\1\0", 2) = 2
[pid 56744] read(9, "\0\0\0\0\0\0", 6) = 6
[pid 56744] read(9, "\0\0", 2) = 2
[pid 56744] read(9, "\0\0\0\0\0\0", 6) = 6
[pid 56744] read(9, "\0\0", 2) = 2
[pid 56744] read(9, "\0\0", 2) = 2
[pid 56744] open("/etc/pam.d/", O_RDONLY) = 10
[pid 56744] fstat(10, {st_mode=0, st_size=0, ...}) = 0
[pid 56744] break(0x805a000) = 0
[pid 56744] read(10,
"\363FH\0\f\0\4\1.\0\0\0\365KD\0\f\0\4\2..\0\0RGH\0\20\0"..., 4096) = 512
[pid 56744] break(0x805b000) = 0
[pid 56744] break(0x805c000) = 0
[pid 56744] read(10, "", 4096) = 0
[pid 56744] gettimeofday({4736755, 17039372}, NULL) = 0
[pid 56744] getpid() = 56744 (ppid 56740)
[pid 56744] sendto(3,
".\0\0\0\365KD\0\f\0\4\2..\0\0RGH\0\20\0\10\6README\0\325"..., 111, 0,
NULL, 0) = 111
[pid 56744] close(10) = 0
[pid 56744] gettimeofday({4736818, 50855948}, NULL) = 0
[pid 56744] getpid() = 56744 (ppid 56740)
[pid 56744] sendto(3,
"ftp\0002GH\0\20\0\10\4ftpd\0\333&\325YGH\0\20\0\10\4im"..., 85, 0,
NULL, 0) = 85
[pid 56744] getpid() = 56744 (ppid 56740)
[pid 56744] write(2,
"\0\332&\325WGH\0\f\0\10\3gdm\0\261HH\0\20\0\10\5login\0"...,
120saslauthd[56744] :do_auth : auth failure: [user=USER]
[service=] [realm=] [mech=pam] [reason=PAM start error]
) = 120
[pid 56744] gettimeofday({4737158, 50855948}, NULL) = 0
[pid 56744] getpid() = 56744 (ppid 56740)
[pid 56744] sendto(3,
"kde\0\16VH\0\24\0\10\3xdm\0tmp\0tmp\0hIH\0\20\0\10\5"..., 139, 0, NULL,
0) = 139
[pid 56744] write(9, "ot", 2) = 2
[pid 56744] write(9, "NO PAM start error", 18) = 18
[pid 56744] close(9) = 0
[pid 56744] fcntl(7, F_SETLKW, {type=0x805 /* F_??? */,
whence=0xffff8000 /* SEEK_??? */, start=65280, len=0}
[...]
Er, looks like it parses the wrong files under pam.d. ftpd, kde(?), gdm...
Jochen
