On 5/28/2022 2:21 PM, Viktor Dukhovni wrote:
[ Please respect the "Reply-To" header]
Oops, sorry, will do.
I'm making some progress. I turned on debug tracing in postfix and
saslauthd and made some interesting discoveries:
1) The command I got from an internet post to generate the base64
encoded user/password was incorrect, or intended for a different
version of the echo command. In
$ echo -ne '\000myu...@mydomain.com\000[password]' | base64
bash echo expects numeric escapes to be \0nnn. It correctly
parsed the first \000 but my password happens to start with
a digit, so it didn't generate the nul there. I needed \0000
instead.
THAT EXPLAINS THE PROTOCOL ERROR
2) After fixing that issue it still fails with a slightly
different error:
535 5.7.8 Error: authentication failed: authentication failure
The crucial bit of information is that, with saslauthd running
in the foreground, with debug enabled, NOTHING GETS LOGGED,
even though I see log entries when running testsaslauthd.
I conclude therefore that the Postfix-to-saslauthd communication
isn't working, which narrows down the problem.
For completeness here's everything I can think of that could be
related:
$ ls -ld /etc/sasl2
drwxr-xr-x 2 root root 4096 May 19 00:58 /etc/sasl2
$ ls -l /etc/sasl2/
-rw-r--r-- 1 root root 62 May 28 18:18 smtpd.conf
$ cat /etc/sasl2/smtpd.conf
pwcheck_method: saslauthd
log_level: 7
mech_list: PLAIN LOGIN
Extract from Postfix debug log (with correctly formatted base64 string)
: < localhost[127.0.0.1]: AUTH PLAIN [redacted]
: xsasl_cyrus_server_first: sasl_method PLAIN, init_response [redacted]
: xsasl_cyrus_server_first: decoded initial response
: warning: SASL authentication failure: Password verification failed
: warning: localhost[127.0.0.1]: SASL PLAIN authentication failed:
authentication failure
: > localhost[127.0.0.1]: 535 5.7.8 Error: authentication failed:
authentication failure
Foreground saslauthd command, including debug output from
successful testsaslauthd but no log entries corresponding to the
immediately above extract from the Postfix log:
$ sudo saslauthd -a pam -d -c -m /var/spool/postfix/var/run/saslauthd
saslauthd[27086] :num_procs : 5
saslauthd[27086] :mech_option: NULL
saslauthd[27086] :run_path : /var/spool/postfix/var/run/saslauthd
saslauthd[27086] :auth_mech : pam
saslauthd[27086] :mmaped shared memory segment on file:
/var/spool/postfix/var/run/saslauthd/cache.mmap
saslauthd[27086] :bucket size: 96 bytes
saslauthd[27086] :stats size : 36 bytes
saslauthd[27086] :timeout : 28800 seconds
saslauthd[27086] :cache table: 985828 total bytes
saslauthd[27086] :cache table: 1711 slots
saslauthd[27086] :cache table: 10266 buckets
saslauthd[27086] :flock file opened at
/var/spool/postfix/var/run/saslauthd/cache.flock
saslauthd[27086] :using accept lock file:
/var/spool/postfix/var/run/saslauthd/mux.accept
saslauthd[27086] :master pid is: 0
saslauthd[27086] :listening on socket:
/var/spool/postfix/var/run/saslauthd/mux
saslauthd[27086] :using process model
saslauthd[27086] :forked child: 27087
saslauthd[27086] :forked child: 27088
saslauthd[27086] :forked child: 27089
saslauthd[27086] :forked child: 27090
saslauthd[27086] :acquired accept lock
saslauthd[27086] :released accept lock
saslauthd[27089] :acquired accept lock
saslauthd[27089] :attempting a read lock on slot: 543
saslauthd[27089] :[login=jhg] [service=smtpd] [realm=]: not found,
update pending
saslauthd[27089] :attempting to release lock on slot: 543
saslauthd[27089] :attempting a write lock on slot: 543
saslauthd[27089] :lookup committed
saslauthd[27089] :attempting to release lock on slot: 543
saslauthd[27089] :auth success: [user=jhg] [service=smtpd] [realm=]
[mech=pam]
saslauthd[27089] :response: OK
$ sudo postconf |egrep 'smtpd_sasl|tls_auth'
smtpd_sasl_auth_enable = no
smtpd_sasl_authenticated_header = yes
smtpd_sasl_exceptions_networks =
smtpd_sasl_local_domain =
smtpd_sasl_path = smtpd
smtpd_sasl_response_limit = 12288
smtpd_sasl_security_options = noanonymous
smtpd_sasl_service = smtp
smtpd_sasl_tls_security_options = $smtpd_sasl_security_options
smtpd_sasl_type = cyrus
smtpd_tls_auth_only = yes
Directory permissions:
$ ls -ld /var/spool/postfix
drwxr-xr-x 21 root root 4096 May 27 21:42 /var/spool/postfix
$ ls -ld /var/spool/postfix/var
drwxr-xr-x 3 root root 4096 May 27 21:42 /var/spool/postfix/var
$ ls -ld /var/spool/postfix/var/run
drwxr-xr-x 3 root root 4096 May 27 21:42 /var/spool/postfix/var/run
$ ls -ld /var/spool/postfix/var/run/saslauthd/
drwxr-x--- 2 root sasl 4096 May 28 23:30
/var/spool/postfix/var/run/saslauthd/
$ sudo ls -l /var/spool/postfix/var/run/saslauthd/
total 964
-rw------- 1 root root 0 May 28 23:30 cache.flock
-rw------- 1 root root 986112 May 28 23:51 cache.mmap
srwxrwxrwx 1 root root 0 May 28 23:30 mux
-rw------- 1 root root 0 May 28 23:30 mux.accept
-rw------- 1 root root 0 May 28 23:30 saslauthd.pid.lock
$ grep postfix /etc/group
sasl:x:45:postfix
postfix:x:117:
Is there an option to increase the debug level in Postfix's
interaction with saslauthd?
--
Jim Garrison
j...@acm.org
