Q:

SASL Authentication Failed on Postfix as relay server with office365

I'm setting a postfix server as relay to an account in office 365.
I configure the main file /etc/postfix/main.cf as follows:
relayhost = [smtp.office365.com]:587
smtp_sasl_auth_enable = yes
smtp_sasl_password_maps = hash:/etc/postfix/sasl_passwd
smtp_sasl_mechanism_filter = login
smtp_use_tls = yes
smtp_always_send_ehlo = yes
#smtp_tls_security_level = secure
smtp_tls_security_level = may
smtp_tls_mandatory_protocols = TLSv1
smtp_tls_mandatory_ciphers = high
smtp_tls_secure_cert_match = nexthop
#Check that this path exists -- these are the certificates used by TLS
smtp_tls_CAfile = /etc/pki/tls/certs/ca-bundle.crt
#Set the sasl options
smtp_sasl_security_options = noanonymous
sender_canonical_maps = regexp:/etc/postfix/sender_canonical

Also made a sasl_password file:
[smtp.office365.com]:587 username@domain.com:thepassword

And applied the postmap command:
postmap sasl_passwd

The messages are not delivered and log show the next message
Aug 29 11:22:04 relaysmtp postfix/error[13501]: 0CA2C82CD1: to=<username@domain.com>, relay=none, delay=6538, delays=6538/0/0/0.01, dsn=4.7.3, status=deferred (delivery temporarily suspended: SASL authentication failed; server smtp.office365.com[40.102.32.146] said: 535 5.7.3 Authentication unsuccessful [PT1sdsaoPP.akpr0.prod.outlook.com])

The postfix version is 3.2.3 in a CentOS 6.10
I configured the Postfix's log to more verbose output; then i tested with Telnet command from another host.
I'll paste the primitive and the output from postfix separate by signs:
telnet 192.168.0.10 25
Trying 192.168.0.10...
Connected to 192.168.0.10.
Escape character is '^]'.
220 **************************************

Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: < unknown[192.168.0.15]: quit
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 221 2.0.0 Bye
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 0.0.0.0/0
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: match_hostaddr: smtpd_client_event_limit_exceptions: 192.168.0.15 ~? 0.0.0.0/0
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: disconnect from unknown[192.168.0.15] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: master_notify: status 1
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: connection closed
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: proxymap stream disconnect
Sep  4 18:28:37 relaysmtp postfix/smtpd[9402]: rewrite stream disconnect
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: connection established
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: master_notify: status 0
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: name_mask: resource
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: name_mask: software
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: connect from unknown[192.168.0.15]
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: match_list_match: unknown: no match
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: match_list_match: 192.168.0.15: no match
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: match_list_match: unknown: no match
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: match_list_match: 192.168.0.15: no match
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: smtp_stream_setup: maxtime=300 enable_deadline=0
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 0.0.0.0/0
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: match_hostaddr: smtpd_client_event_limit_exceptions: 192.168.0.15 ~? 0.0.0.0/0
Sep  4 18:28:46 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 220 relay.domain.com ESMTP Postfix
---------------------------------------------------------------------------------------------------------------------------
ehlo localhost
250-relay.domain.com
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN

Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: < unknown[192.168.0.15]: ehlo localhost
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: match_list_match: unknown: no match
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: match_list_match: 192.168.0.15: no match
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-relay.domain.comhos
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-PIPELINING
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-SIZE 10240000
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-VRFY
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-ETRN
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-ENHANCEDSTATUSCODES
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250-8BITMIME
Sep  4 18:29:44 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250 DSN
-----------------------------------------------------------------------------------------------------------------------
mail from: <username@domain.com>
250 2.1.0 Ok

Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: < unknown[192.168.0.15]: mail from: <username@domain.com>
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: extract_addr: input: <username@domain.com>
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: smtpd_check_addr: addr=username@domain.com
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: ctable_locate: leave existing entry key ?username@domain.com
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: extract_addr: in: <username@domain.com>, result: username@domain.com
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: smtpd_check_rewrite: trying: permit_inet_interfaces
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: permit_inet_interfaces: unknown 192.168.0.15
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: fsspace: .: block size 4096, blocks free 2121461
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: smtpd_check_queue: blocks 4096 avail 2121461 min_free 0 msg_size_limit 10240000
Sep  4 18:33:21 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250 2.1.0 Ok

----------------------------------------------------------------------------------------------------------------------------
rcpt to: <otheruser@testmail.com>

Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: < unknown[192.168.0.15]: rcpt to: <otheruser@testmail.com>
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: extract_addr: input: <otheruser@testmail.com>
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: smtpd_check_addr: addr=otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: connect to subsystem private/rewrite
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr request = rewrite
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr rule = local
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr address = username@domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: 0
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: address
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: address
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: username@domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: (list terminator)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: (end)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: rewrite_clnt: local: username@domain.com -> username@domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr request = rewrite
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr rule = local
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr address = otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: 0
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: address
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: address
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: (list terminator)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: (end)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: rewrite_clnt: local: otheruser@testmail.com -> otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr request = resolve
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr sender = username@domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr address = otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: 0
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: transport
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: transport
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: smtp
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: nexthop
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: nexthop
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: [smtp.office365.com]:587
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: recipient
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: recipient
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: flags
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: 4096
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: private/rewrite socket: wanted attribute: (list terminator)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: (end)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: resolve_clnt: `username@domain.com' -> `otheruser@testmail.com' -> transp=`smtp' host=`[smtp.office365.com]:587' rcpt=`otheruser@testmail.com' flags= class=default
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: ctable_locate: install entry key username@domain.com?otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: extract_addr: in: <otheruser@testmail.com>, result: otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: >>> START Recipient address RESTRICTIONS <<<
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: generic_checks: name=permit_mynetworks
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: permit_mynetworks: unknown 192.168.0.15
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_hostname: mynetworks: unknown ~? 0.0.0.0/0
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_hostaddr: mynetworks: 192.168.0.15 ~? 0.0.0.0/0
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: smtpd_acl_permit: checking smtpd_log_access_permit_actions settings
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_list_match: permit_mynetworks: no match
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: smtpd_acl_permit: smtpd_log_access_permit_actions: no match
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: generic_checks: name=permit_mynetworks status=1
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: >>> END Recipient address RESTRICTIONS <<<
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: >>> CHECKING Recipient address VALIDATION MAPS <<<
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: ctable_locate: leave existing entry key username@domain.com?otheruser@testmail.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: maps_find: recipient_canonical_maps: otheruser@testmail.com: not found
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? relay.domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? localhost.domain.comf
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? localhost
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_list_match: testmail.com: no match
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: maps_find: recipient_canonical_maps: @testmail.com: not found
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: mail_addr_find: otheruser@testmail.com -> (not found)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: maps_find: canonical_maps: otheruser@testmail.com: not found
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? relay.domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? localhost.domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? localhost
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_list_match: testmail.com: no match
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: maps_find: canonical_maps: @testmail.com: not found
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: mail_addr_find: otheruser@testmail.com -> (not found)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: maps_find: virtual_alias_maps: otheruser@testmail.com: not found
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? relay.domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? localhost.domain.com
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_string: mydestination: testmail.com ~? localhost
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: match_list_match: testmail.com: no match
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: maps_find: virtual_alias_maps: @testmail.com: not found
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: mail_addr_find: otheruser@testmail.com -> (not found)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: after input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: name_mask: sendmail
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: name_mask: verify
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: connect to subsystem public/cleanup
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: public/cleanup socket: wanted attribute: queue_id
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: queue_id
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute value: 64FFA85196
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: public/cleanup socket: wanted attribute: (list terminator)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: input attribute name: (end)
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: send attr flags = 178
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: 64FFA85196: client=unknown[192.168.0.15]
Sep  4 18:34:16 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250 2.1.5 Ok
-----------------------------------------------------------------------------------------------------------------------------------
data
354 End data with <CR><LF>.<CR><LF>

Sep  4 18:35:40 relaysmtp postfix/smtpd[9402]: < unknown[192.168.0.15]: data
Sep  4 18:35:40 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 354 End data with <CR><LF>.<CR><LF>
--------------------------------------------------------------------------------------------------------------------------------------
subject: Test mail
Test message
.

Sep  4 18:36:43 relaysmtp postfix/cleanup[9488]: 64FFA85196: message-id=<>
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: public/cleanup socket: wanted attribute: status
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: input attribute name: status
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: input attribute value: 0
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: public/cleanup socket: wanted attribute: reason
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: input attribute name: reason
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: input attribute value: (end)
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: public/cleanup socket: wanted attribute: (list terminator)
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: input attribute name: (end)
Sep  4 18:36:43 relaysmtp postfix/smtpd[9402]: > unknown[192.168.0.15]: 250 2.0.0 Ok: queued as 64FFA85196
Sep  4 18:36:43 relaysmtp postfix/qmgr[9399]: 64FFA85196: from=<username@domain.com>, size=225, nrcpt=1 (queue active)
Sep  4 18:36:55 relaysmtp postfix/smtp[9520]: 64FFA85196: SASL authentication failed; server smtp.office365.com[191.232.101.210] said: 535 5.7.3 Authentication unsuccessful [FR1PR80CA0078.lamprd80.prod.outlook.com]
Sep  4 18:37:06 relaysmtp postfix/smtp[9520]: 64FFA85196: SASL authentication failed; server smtp.office365.com[191.232.104.2] said: 535 5.7.3 Authentication unsuccessful [RO1P152CA0065.LAMP152.PROD.OUTLOOK.COM]

It seems postfix isn't even using sasl_passwd.db file generated with postmap.
What am i missing?
Thanks for help

A:

I ask another account and the authentication works and the messages can be delivered.

