Hello list,
my setup is Ubuntu 12.04, postfix, cyrus, cyrus-sasl and pam-mysql using
standard dist-packages. MySQL is on another server on the same machine
in a openvz container.
After around 3 days sasl starts with erratic behaviour. Sometimes
authentification works, sometimes not. All of a sudden. I tried
tessaslauthd from console with success, next time with an error.
root@mail:~# testsaslauthd -u user@xxxxxxxxxxx -p XXX -f
/var/spool/postfix/var/run/saslauthd/mux
0: NO "authentication failed"
root@mail:~# testsaslauthd -u user@xxxxxxxxxxx -p XXX -f
/var/spool/postfix/var/run/saslauthd/mux
0: OK "Success."
Restart of saslauthd daemon fixes everything until around 3 days when
the misbehaviour starts again.
I observed everything carefully with all relevant debugging options but
no real insights. Below you find some strace from the saslauthd. First
part is not working, second part works.
Does someone has an idea to solve or give me a hint what else i could do
to trace down the problem?
Thank you very much!
Tobias
Working:
[...]
26720 read(9, "#\n# /etc/pam.d/common-session - "..., 4096) = 1437
26720 open("/lib/x86_64-linux-gnu/security/pam_umask.so",
O_RDONLY|O_CLOEXEC) = 10
26720 read(10,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220\v\0\0\0\0\0\0"...,
832) = 832
26720 fstat(10, {st_mode=S_IFREG|0644, st_size=10304, ...}) = 0
26720 mmap(NULL, 2105560, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 10, 0) = 0x7f3438ea4000
26720 mprotect(0x7f3438ea6000, 2093056, PROT_NONE) = 0
26720 mmap(0x7f34390a5000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 10, 0x1000) = 0x7f34390a5000
26720 close(10) = 0
26720 mprotect(0x7f34390a5000, 4096, PROT_READ) = 0
26720 read(9, "", 4096) = 0
26720 close(9) = 0
26720 munmap(0x7f34404e2000, 4096) = 0
26720 read(8, "", 4096) = 0
26720 close(8) = 0
26720 munmap(0x7f34404e3000, 4096) = 0
26720 write(2, "Can't initialize threads: error "..., 35) = 35
26720 sendto(3, "<39>Oct 11 08:41:12 saslauthd[26"..., 97, MSG_NOSIGNAL,
NULL, 0) = 97
26720 munmap(0x7f343b56c000, 2140256) = 0
26720 munmap(0x7f343b027000, 5525168) = 0
26720 munmap(0x7f343ad2b000, 3125544) = 0
26720 munmap(0x7f343ab11000, 2200480) = 0
26720 munmap(0x7f343a8f7000, 2202328) = 0
26720 munmap(0x7f343a6d8000, 2221680) = 0
26720 munmap(0x7f343a4d6000, 2101280) = 0
26720 munmap(0x7f343a2d4000, 2101296) = 0
26720 munmap(0x7f3438ea4000, 2105560) = 0
26720 sendto(3, "<38>Oct 11 08:41:12 saslauthd[26"..., 157,
MSG_NOSIGNAL, NULL, 0) = 157
26720 write(6, "\0\21", 2) = 2
26720 write(6, "NO PAM auth error", 17) = 17
26720 close(6) = 0
[...]
Not working:
[...]
26722 open("/etc/pam.d/common-session", O_RDONLY) = 9
26722 fstat(9, {st_mode=S_IFREG|0644, st_size=1437, ...}) = 0
26722 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7f34404e2000
26722 read(9, "#\n# /etc/pam.d/common-session - "..., 4096) = 1437
26722 open("/lib/x86_64-linux-gnu/security/pam_umask.so",
O_RDONLY|O_CLOEXEC) = 10
26722 read(10,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220\v\0\0\0\0\0\0"...,
832) = 832
26722 fstat(10, {st_mode=S_IFREG|0644, st_size=10304, ...}) = 0
26722 mmap(NULL, 2105560, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 10, 0) = 0x7f3438ea4000
26722 mprotect(0x7f3438ea6000, 2093056, PROT_NONE) = 0
26722 mmap(0x7f34390a5000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 10, 0x1000) = 0x7f34390a5000
26722 close(10) = 0
26722 mprotect(0x7f34390a5000, 4096, PROT_READ) = 0
26722 read(9, "", 4096) = 0
26722 close(9) = 0
26722 munmap(0x7f34404e2000, 4096) = 0
26722 read(8, "", 4096) = 0
26722 close(8) = 0
26722 munmap(0x7f34404e3000, 4096) = 0
26722 clone(child_stack=0x7f343a0d1fb0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0x7f343a0d29d0, tls=0x7f343a0d2700,
child_tidptr=0x7f343a0d29d0) = 19629
26722 futex(0x7f343a0d29d0, FUTEX_WAIT, 19629, NULL) = 0
26722 open("/etc/services", O_RDONLY|O_CLOEXEC) = 8
26722 fstat(8, {st_mode=S_IFREG|0644, st_size=19366, ...}) = 0
26722 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7f34404e3000
26722 read(8, "# Network services, Internet sty"..., 4096) = 4096
26722 read(8, "ase\nz3950\t\t210/udp\t\twais\nipx\t\t21"..., 4096) = 4096
26722 read(8, "usnote\t1352/tcp\tlotusnotes\t# Lot"..., 4096) = 4096
26722 close(8) = 0
26722 munmap(0x7f34404e3000, 4096) = 0
26722 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART,
0x7f343ec8e4c0}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART,
0x7f343ec8e4c0}, 8) = 0
26722 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=101, ...}) = 0
26722 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 8
26722 fstat(8, {st_mode=S_IFREG|0644, st_size=277, ...}) = 0
26722 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7f34404e3000
26722 read(8, "fe00::0\t\tip6-localnet\nff00::0\t\ti"..., 4096) = 277
26722 read(8, "", 4096) = 0
26722 close(8) = 0
26722 munmap(0x7f34404e3000, 4096) = 0
26722 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=101, ...}) = 0
26722 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 8
26722 connect(8, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("213.133.100.100")}, 16) = 0
26722 poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}])
26722 sendto(8, "\"0\1\0\0\1\0\0\0\0\0\0\5mysql\fshifthamburg\3"..., 40,
MSG_NOSIGNAL, NULL, 0) = 40
26722 poll([{fd=8, events=POLLIN}], 1, 5000) = 1 ([{fd=8, revents=POLLIN}])
[...]
--
Tobias Kirchhofer
