Authentication unsuccessful relaying from Postfix to Microsoft ESMTP MAIL Service
Hi,
I'm trying in vain to relay external mail from postfix on a Debian
lenny machine to a Microsoft SMTP server on the Internet. I've been
reading and searching for days. I've tried numerous combinations of
settings although I'm note certain what they all do and am
experiencing information overload.
I am trying to migrate from one MS server to another.
OLDSERVER runs on port 25.
NEWSERVER runs on port 587. Supposedly it requires TLS but I'm not
certain of that (more later).
My existing, working, setup has postfix set up for "Internet with smarthost"
and the login credentials for OLDSERVER are in /etc/postfix/sasl_passwd.
I send mail from mutt to "/usr/sbin/sendmail -oem -oi" and it is duly
relayed by postfix.
When I change relayhost to NEWSERVER:587, the mail gets stuck in postfix.
In /var/log/mail.log I see "Authentication unsuccessful".
On the same machine I set up an account in IceDove to use NEWSERVER:587
for SMTP and it just works.
What's more, it works when "Secure Connection" is set to any of
"None", "TLS", "Use TLS if available". (That's why I cast doubt on the
TLS requirement above).
So my questions are:
* How can I fix this in Postfix?
* Can Postfix do this? Or do I need to change to something else e.g. Exim?
* What does IceDove do that Postfix doesn't?
The rest of this mail contains more detail.
I've tried with:
* smtp_sasl_security_options set to noanonymous and empty
* smtp_tls_security_level set to "may", "none", "encrypt" and not set.
* relayhost set to NEWSERVER:587 and [NEWSERVER]:587 in main.cf and
sasl_passwd (kept them in step and updated sasl_passwd.db each time)
(Sanitised) server information using ehlo command in telnet:
$ telnet NEWSERVER 587
Trying NEWSERVER-IPADDR...
Connected to NEWSERVER.
Escape character is '^]'.
220 NEWSERVER-OTHERNAME Microsoft ESMTP MAIL Service ready at Fri, 7 May 2010 14:43:28 +0100
ehlo
250-NEWSERVER-OTHERNAME Hello [MY-IPADDR]
250-SIZE 15360000
250-PIPELINING
250-DSN
250-ENHANCEDSTATUSCODES
250-STARTTLS
250-AUTH GSSAPI NTLM
250-8BITMIME
250-BINARYMIME
250 CHUNKING
$ telnet OLDSERVER 25
Trying OLDSERVER-IPADDR...
Connected to OLDSERVER.
Escape character is '^]'.
220 OLDSERVER-OTHERNAME Microsoft ESMTP MAIL Service, Version: 6.0.3790.3959 ready at Fri, 7 May 2010 15:44:25 +0200
ehlo
250-OLDSERVER-OTHERNAME Hello [MY-IPADDR]
250-TURN
250-SIZE
250-ETRN
250-PIPELINING
250-DSN
250-ENHANCEDSTATUSCODES
250-8bitmime
250-BINARYMIME
250-CHUNKING
250-VRFY
250-X-EXPS GSSAPI NTLM LOGIN
250-X-EXPS=LOGIN
250-AUTH GSSAPI NTLM LOGIN
250-AUTH=LOGIN
250-X-LINK2STATE
250-XEXCH50
250 OK
Here are some sanitised logs from when the problem occurs. These were
collected with the following settings:
relayhost = NEWSERVER:587
smtp_sasl_security_options = noanonymous
smtp_tls_security_level = may
(although it's the same for all the settings I tried, except there were
no SSL/TLS logs when smtp_tls_security_level = none).
/var/log/auth.log:
May 9 16:30:01 rimmer postfix/smtp[10643]: NTLM client step 1
May 9 16:30:01 rimmer postfix/smtp[10643]: NTLM client step 2
May 9 16:30:01 rimmer postfix/smtp[10643]: server flags: ff810205
May 9 16:30:01 rimmer postfix/smtp[10643]: server domain: NEWSERVER-NTDOMAIN
May 9 16:30:01 rimmer postfix/smtp[10643]: calculating NT response
/var/log/mail.log:
May 9 16:30:01 rimmer postfix/pickup[10629]: 57BC739B7: uid=1000 from=<MY-EMAIL-ADDRESS>
May 9 16:30:01 rimmer postfix/cleanup[10641]: 57BC739B7: resent-message-id=<20100509153001.GF3672@MY-MAILNAME>
May 9 16:30:01 rimmer postfix/cleanup[10641]: 57BC739B7: message-id=<20100509141642.GB3672@MY-MAILNAME>
May 9 16:30:01 rimmer postfix/qmgr[10630]: 57BC739B7: from=<MY-EMAIL-ADDRESS>, size=863, nrcpt=1 (queue active)
May 9 16:30:01 rimmer postfix/smtp[10643]: initializing the client-side TLS engine
May 9 16:30:01 rimmer postfix/tlsmgr[10644]: open smtp TLS cache btree:/var/lib/postfix/smtp_scache
May 9 16:30:01 rimmer postfix/tlsmgr[10644]: tlsmgr_cache_run_event: start TLS smtp session cache cleanup
May 9 16:30:01 rimmer postfix/smtp[10643]: setting up TLS connection to NEWSERVER[NEWSERVER-IPADDR]:587
May 9 16:30:01 rimmer postfix/smtp[10643]: NEWSERVER[NEWSERVER-IPADDR]:587: TLS cipher list "ALL:+RC4:@STRENGTH"
May 9 16:30:01 rimmer postfix/smtp[10643]: looking for session smtp:NEWSERVER-IPADDR:587:NEWSERVER-OTHERNAME&p=0&c=ALL:+RC4:@STRENGTH in smtp cache
May 9 16:30:01 rimmer postfix/tlsmgr[10644]: lookup smtp session id=smtp:NEWSERVER-IPADDR:587:NEWSERVER-OTHERNAME&p=0&c=ALL:+RC4:@STRENGTH
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:before/connect initialization
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv2/v3 write client hello A
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 read server hello A
May 9 16:30:01 rimmer postfix/smtp[10643]: NEWSERVER[NEWSERVER-IPADDR]:587: certificate verification depth=2 verify=0 subject=/C=US/O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authority
May 9 16:30:01 rimmer postfix/smtp[10643]: certificate verification failed for NEWSERVER[NEWSERVER-IPADDR]:587: untrusted issuer /L=ValiCert Validation Network/O=ValiCert, Inc./OU=ValiCert Class 2 Policy Validation Authority/CN=http://www.valicert.com//emailAddress=info@valicert.com
May 9 16:30:01 rimmer postfix/smtp[10643]: NEWSERVER[NEWSERVER-IPADDR]:587: certificate verification depth=2 verify=0 subject=/C=US/O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authority
May 9 16:30:01 rimmer postfix/smtp[10643]: NEWSERVER[NEWSERVER-IPADDR]:587: certificate verification depth=1 verify=1 subject=/C=US/ST=Arizona/L=Scottsdale/O=GoDaddy.com, Inc./OU=http://certificates.godaddy.com/repository/CN=Go Daddy Secure Certification Authority/serialNumber=07969287
May 9 16:30:01 rimmer postfix/smtp[10643]: NEWSERVER[NEWSERVER-IPADDR]:587: certificate verification depth=0 verify=1 subject=/O=*.NEWSERVER-DOMAIN/OU=Domain Control Validated/CN=*.NEWSERVER-DOMAIN
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 read server certificate A
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 read server done A
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 write client key exchange A
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 write change cipher spec A
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 write finished A
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 flush data
May 9 16:30:01 rimmer postfix/smtp[10643]: SSL_connect:SSLv3 read finished A
May 9 16:30:01 rimmer postfix/smtp[10643]: save session smtp:NEWSERVER-IPADDR:587:NEWSERVER-OTHERNAME&p=0&c=ALL:+RC4:@STRENGTH to smtp cache
May 9 16:30:01 rimmer postfix/tlsmgr[10644]: put smtp session id=smtp:NEWSERVER-IPADDR:587:NEWSERVER-OTHERNAME&p=0&c=ALL:+RC4:@STRENGTH [data 1383 bytes]
May 9 16:30:01 rimmer postfix/tlsmgr[10644]: write smtp TLS cache entry smtp:NEWSERVER-IPADDR:587:NEWSERVER-OTHERNAME&p=0&c=ALL:+RC4:@STRENGTH: time=1273419001 [data 1383 bytes]
May 9 16:30:01 rimmer postfix/smtp[10643]: Untrusted TLS connection established to NEWSERVER[NEWSERVER-IPADDR]:587: TLSv1 with cipher RC4-MD5 (128/128 bits)
May 9 16:30:06 rimmer postfix/smtp[10643]: 57BC739B7: to=<MY-EMAIL-ADDRESS>, relay=NEWSERVER[NEWSERVER-IPADDR]:587, delay=5.5, delays=0.03/0.03/5.4/0, dsn=4.7.3, status=deferred (SASL authentication failed; server NEWSERVER[NEWSERVER-IPADDR] said: 535 5.7.3 Authentication unsuccessful)
Reply to: