Random error with sasl+pam+mysql

Thu Oct 11 07:17:18 EDT 2012

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 at mail:~# testsaslauthd -u user at example.com -p XXX -f 
/var/spool/postfix/var/run/saslauthd/mux
0: NO "authentication failed"
root at mail:~# testsaslauthd -u user at example.com -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