Unable to confirm Postfix is using SASL_OAUTH2

[VictorHumansa]

Good day, could use a hand with the postfix setup.

Following the guideline setting up sasl and postfix to relay email to office365, I managed to get postfix up and completed the token generation, test of config and refresh also work properly.

However when I try to send email via postfix, I always get Recipient address rejected

Jul 12 18:47:22 nwdpc0s3rtp postfix/smtpd[481183]: connect from localhost[127.0.0.1] Jul 12 18:47:22 nwdpc0s3rtp postfix/smtpd[481183]: NOQUEUE: reject: RCPT from localhost[127.0.0.1]: 550 5.1.1 victortsang@humansa.com.hk: Recipient address rejected: [smtp.office365.com]:587; from=servicesalerts@humansahealth.com to=victortsang@humansa.com.hk proto=ESMTP helo= Jul 12 18:47:22 nwdpc0s3rtp postfix/smtpd[481183]: disconnect from localhost[127.0.0.1] ehlo=2 starttls=1 mail=1 rcpt=0/1 quit=1 commands=5/6

I can see no indication oauth2 is being triggered in the log, and the token file hasn't been updated. Is there any debug log I can check to verify postfix is indeed using OATH to connect to office 365?

here's my main.cf setup for SASL auth

smtp_sasl_auth_enable = yes smtp_sasl_password_maps = hash:/etc/postfix/sasl_passwd smtp_sasl_security_options = smtp_sasl_mechanism_filter = xoauth2

relayhost = [smtp.office365.com]:587 smtp_use_tls = yes smtp_always_send_ehlo = yes

[tarickb]

I suspect, but I'm not entirely sure, that it's Postfix that's rejecting your message, not Outlook. Can you supply the full contents of your main.cf file, with sensitive parts redacted?

[VictorHumansa]

Thank you Tarickb. below is my main.cf

smtpd_banner = $myhostname ESMTP $mail_name biff = no

append_dot_mydomain = no

readme_directory = no compatibility_level = 3.6

TLS parameters

smtpd_tls_cert_file=/etc/ssl/certs/ssl-cert-snakeoil.pem smtpd_tls_key_file=/etc/ssl/private/ssl-cert-snakeoil.key smtpd_tls_security_level=encrypt smtp_tls_CApath=/etc/ssl/certs

smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache

smtpd_relay_restrictions = permit_mynetworks reject_unauth_destination myhostname = nwdpc0s3rtp alias_maps = hash:/etc/aliases alias_database = hash:/etc/aliases myorigin = /etc/mailname mydestination = localhost.localdomain, localhost

enable SASL authentication

smtp_sasl_auth_enable = yes smtp_sasl_password_maps = hash:/etc/postfix/sasl_passwd smtp_sasl_security_options = smtp_sasl_mechanism_filter = xoauth2

relayhost = [smtp.office365.com]:587 smtp_use_tls = yes smtp_always_send_ehlo = no

mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128 mailbox_size_limit = 0 recipient_delimiter = + inet_interfaces = loopback-only default_transport = error relay_transport = error inet_protocols = all

[tarickb]

This looks a little suspect to me:

default_transport = error
relay_transport = error

But I'll admit I'm not a Postfix expert (not even close). Can you comment out those lines and try again?

[VictorHumansa]

Thank you Tarickb, the error has gone and now postfix report success. however the email I send doesn't seems to be getting delivered. I will continue tomorrow and share my finding.

[VictorHumansa]

As it turns out the email didn't really get send, checking into the log, it seems to be stuck on this error

relay=smtp.office365.com[40.100.29.242]:587, delay=522, delays=520/0.02/1.2/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtp.office365.com[40.100.29.242]: bad protocol / cancel)

and here's more detail on the log.

Jul 12 23:08:39 nwdpc0s3rtp smtp: input attribute name: (end) Jul 12 23:08:39 nwdpc0s3rtp smtp: vstream_buf_get_ready: fd 17 got 217 Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-SG2PR01CA0137.outlook.office365.com Hello [218.255.xxx.xxx] Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-SIZE 157286400 Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-PIPELINING Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-DSN Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-ENHANCEDSTATUSCODES Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-AUTH LOGIN XOAUTH2 Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-8BITMIME Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-BINARYMIME Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250-CHUNKING Jul 12 23:08:39 nwdpc0s3rtp smtp: < smtp.office365.com[52.98.84.82]:587: 250 SMTPUTF8 Jul 12 23:08:39 nwdpc0s3rtp smtp: match_string: smtp_sasl_mechanism_filter: login ~? xoauth2 Jul 12 23:08:39 nwdpc0s3rtp smtp: match_list_match: LOGIN: no match Jul 12 23:08:39 nwdpc0s3rtp smtp: sasl_mech_filter: drop SASL mechanism: 'LOGIN' Jul 12 23:08:39 nwdpc0s3rtp smtp: match_string: smtp_sasl_mechanism_filter: xoauth2 ~? xoauth2 Jul 12 23:08:39 nwdpc0s3rtp smtp: sasl_mech_filter: keep SASL mechanism: 'XOAUTH2' Jul 12 23:08:39 nwdpc0s3rtp smtp: server features: 0x20902f size 157286400 Jul 12 23:08:39 nwdpc0s3rtp smtp: Using ESMTP PIPELINING, TCP send buffer size is 87040, PIPELINING buffer size is 4096 Jul 12 23:08:39 nwdpc0s3rtp smtp: maps_find: smtp_sasl_password_maps: smtp.office365.com: not found Jul 12 23:08:39 nwdpc0s3rtp smtp: maps_find: smtp_sasl_password_maps: hash:/etc/postfix/sasl_passwd(0,lock|fold_fix|utf8_request): [smtp.office365.com]:587 = servicesalerts@humansahealth.com:/etc/token/serversalert Jul 12 23:08:39 nwdpc0s3rtp smtp: smtp_sasl_passwd_lookup: host smtp.office365.com' userservicesalerts@humansahealth.com' pass `/etc/token/serversalert' Jul 12 23:08:39 nwdpc0s3rtp smtp: starting new SASL client Jul 12 23:08:39 nwdpc0s3rtp smtp: smtp_sasl_authenticate: smtp.office365.com[52.98.84.82]:587: SASL mechanisms XOAUTH2 Jul 12 23:08:39 nwdpc0s3rtp smtp: xsasl_cyrus_client_get_user: servicesalerts@humansahealth.com Jul 12 23:08:39 nwdpc0s3rtp smtp: xsasl_cyrus_client_get_passwd: /etc/token/serversalert Jul 12 23:08:39 nwdpc0s3rtp smtp: vstream_buf_get_ready: fd 18 got 10 Jul 12 23:08:39 nwdpc0s3rtp smtp: private/defer socket: wanted attribute: status Jul 12 23:08:39 nwdpc0s3rtp smtp: input attribute name: status Jul 12 23:08:39 nwdpc0s3rtp smtp: input attribute value: 0 Jul 12 23:08:39 nwdpc0s3rtp smtp: private/defer socket: wanted attribute: (list terminator) Jul 12 23:08:39 nwdpc0s3rtp smtp: input attribute name: (end) Jul 12 23:08:39 nwdpc0s3rtp smtp: 2E616783314: to=victortsang@humansa.com.hk, relay=smtp.office365.com[40.100.29.242]:587, delay=522, delays=520/0.02/1.2/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtp.office365.com[40.100.29.242]: bad protocol / cancel)

[tarickb]

What sort of environment are you running in? Is this an Ubuntu installation? I don't know where that xsasl_cyrus_client_get_user log line is coming from. What are the contents of your /etc/sasl-xoauth2.conf file?

[VictorHumansa]

Thank you for the tips Tarickb. I have installed sasl2-bin while researching for work around. after a apt purge the offending issue is gone.

after fixing the ca-certificate.ctr getting removed on postfix restart following the thread below, the login is working now and mail and flowing through okey. https://github.com/tarickb/sasl-xoauth2/issues/13

Many thanks for your help

[tarickb]

Glad it worked!