I've followed tutorial on http://flurdy.com/docs/postfix/ to set up an email server, and most of it works (after switching from Courier to Dovecot). Just not sending email through SMTP. Sending with sendmail works.
This is what I see in /var/log/auth.log when I try to send an email with Thunderbird:
May 22 18:45:59 myserver postfix/submission/smtpd[16560]: sql auxprop plugin using mysql
May 22 18:45:59 myserver saslauthd[16141]: pam_unix(smtp:auth): check pass; user unknown
May 22 18:45:59 myserver saslauthd[16141]: pam_unix(smtp:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=
May 22 18:46:01 myserver saslauthd[16141]: DEBUG: auth_pam: pam_authenticate failed: Authentication failure
May 22 18:46:01 myserver saslauthd[16141]: : auth failure: [user=user1] [service=smtp] [realm=myserver.nl] [mech=pam] [reason=PAM auth error]
May 22 18:46:01 myserver saslauthd[16142]: pam_unix(smtp:auth): check pass; user unknown
May 22 18:46:01 myserver saslauthd[16142]: pam_unix(smtp:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=
May 22 18:46:04 myserver saslauthd[16142]: DEBUG: auth_pam: pam_authenticate failed: Authentication failure
May 22 18:46:04 myserver saslauthd[16142]: : auth failure: [user=user1] [service=smtp] [realm=myserver.nl] [mech=pam] [reason=PAM auth error]
(I'm logged in as [email protected], and IMAP works.)
And I can see something query mysql for user [email protected], but there are some many processes and daemons and configs working together, I have no idea which part fails.
A summary:
- postfix is set up to use sasl (in
/etc/postfix/main.cfand/etc/postfix/sasl/smtpd.conf) - saslauthd is set up to use pam (in
/etc/default/saslauthd) - pam smtp is set up to use mysql for its user db (but it never seems to?) (in
/etc/pam.d/smtp)
The sql_select from /etc/postfix/sasl/smtpd.conf is used to query for user1. I can see changes there in the mysql log.
The configured table and columns in /etc/pam.d/smtp are never used. Changes there don't do anything.
testsaslauthd only 'works' for me if I add -f /var/spool/postfix/var/run/saslauthd/mux, but it ALWAYS returns a NO "authentication failed" and NEVER queries mysql, so I've no idea how that could ever work. But the auth.log output is very similar to the output from Thunderbird's real request (that does trigger a mysql query/lookup):
May 22 18:59:56 myserver saslauthd[16756]: pam_unix(imap:auth): check pass; user unknown
May 22 18:59:56 myserver saslauthd[16756]: pam_unix(imap:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost=
May 22 18:59:58 myserver saslauthd[16756]: DEBUG: auth_pam: pam_authenticate failed: Authentication failure
May 22 18:59:58 myserver saslauthd[16756]: : auth failure: [[email protected]] [service=imap] [realm=] [mech=pam] [reason=PAM auth error]
And then there's the password hash. I've set up Dovecot to only accept SSL and use the plaintext password (users.clear). I don't know if the hashed password (users.crypt) is correct, or if it's even used by Postfix. I've tried all combinations in all config files. The auth.log output is always the same. No details.
Thunderbird tells me it can't send the message, and then shows a kind of error message: ... "unexpected error 80004005" ... "could not be sent for an unknown reason". That doesn't seem like a wrong password error, but an internal server error somewhere. But no horrible error messages in the logs...
After adding some debug level somewhere (sorry I can't remember, so many config files!!) the syslog contains more on the smtp connection:
May 22 19:10:45 myserver postfix/submission/smtpd[16779]: SSL_accept:SSLv3/TLS read finished
...
May 22 19:10:45 myserver postfix/submission/smtpd[16779]: Anonymous TLS connection established from ip-1.2.3.4.ip.myisp.net[4.3.2.1]: TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits)
...
May 22 19:10:45 myserver postfix/submission/smtpd[16779]: Read 22 chars: EHLO [192.168.0.101]??
...
May 22 19:10:45 myserver postfix/submission/smtpd[16779]: Read 49 chars: AUTH PLAIN AHVzZXIxQG15c2VydmVyLm5sAHBp
May 22 19:10:48 myserver postfix/submission/smtpd[16779]: warning: SASL authentication failure: Password verification failed
May 22 19:10:48 myserver postfix/submission/smtpd[16779]: warning: ip-1.2.3.4.ip.myisp.net[4.3.2.1]: SASL PLAIN authentication failed: authentication failure
May 22 19:10:48 myserver postfix/submission/smtpd[16779]: Write 64 chars: 535 5.7.8 Error: authentication failed:
...
May 22 19:10:48 myserver postfix/submission/smtpd[16779]: Read 12 chars: AUTH LOGIN??
May 22 19:10:48 myserver postfix/submission/smtpd[16779]: Write 18 chars: 334 VXNlcm5hbWU6??
...
May 22 19:10:50 myserver postfix/submission/smtpd[16779]: warning: ip-1.2.3.4.ip.myisp.net[4.3.2.1]: SASL LOGIN authentication failed: authentication failure
May 22 19:10:50 myserver postfix/submission/smtpd[16779]: Write 64 chars: 535 5.7.8 Error: authentication failed:
...
May 22 19:10:52 myserver postfix/submission/smtpd[16779]: disconnect from ip-1.2.3.4.ip.myisp.net[4.3.2.1] ehlo=2 starttls=1 auth=0/2 quit=1 commands=4/6
The EHLO + AUTH PLAIN ... are interesting... The EHLO isn't myserver? The logged base64 is cut off? And then "Password verification failed", but no details on which part failed.
I can't find any more debugging than this. syslog, mail log, auth log, mysql log. All the config files are huge, so I didn't add most. I followed http://flurdy.com/docs/postfix/ pretty exactly, and verified every step several times, so that's what I got. EXCEPT clear vs crypt, I've changed that around a few times.
Any brilliant ideas?
