Ask a Question

SMTP via office365 with authentication

0 votes
by (270 points)

we are using REBEX for SMTP mail sending since a couple of years and it worked fine with office365 also. But recently this changed by some of our customers and now we are getting errors on any way we try.

So following settings and results:
smtp.office365.com
port 465
SSL/TLS any

-> none of supported authentication methods is accepted by the server
but after the error we can send the mail without login

smtp.office365.com
port 587
START/TLS

-> none of supported authentication methods is accepted by the server
-> and on sending 'the server has closed the connection'

only on Port 25 without authentication sending is possible without error messages

So what can we do to get authenticated sending running without errors?

Ths,

Kirsten

Applies to: Rebex Secure Mail
by (148k points)
Please use Smtp object's LogWriter property to create a communication log (as described at https://www.rebex.net/kb/logging/) and either post it here or mail it to us for analysis. Based on the log, we should be able to tell what is going on. Thanks!
by (270 points)
edited by
Log for Port 587

2020-09-04 11:13:08.740 Opening log file.
2020-09-04 11:13:08.740 INFO FileLogWriter(2)[1] Info: Assembly: Rebex.Common 2020 R2 for .NET 4.6-4.8
2020-09-04 11:13:08.740 INFO FileLogWriter(2)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2020-09-04 11:13:08.740 DEBUG FileLogWriter(2)[1] Info: Culture: de; Windows-1252
2020-09-04 11:13:08.740 DEBUG Smtp(2)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2020-09-04 11:13:08.740 INFO Smtp(2)[1] Info: Connecting to smtp.office365.com:587 using Smtp.
2020-09-04 11:13:08.740 INFO Smtp(2)[1] Info: Assembly: Rebex.Smtp 2020 R2 for .NET 4.6-4.8
2020-09-04 11:13:08.740 INFO Smtp(2)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2020-09-04 11:13:08.744 DEBUG Smtp(2)[1] Info: Culture: de; Windows-1252
2020-09-04 11:13:08.744 DEBUG Smtp(2)[1] Proxy: Resolving 'smtp.office365.com'.
2020-09-04 11:13:08.750 DEBUG Smtp(2)[1] Proxy: Connecting to 52.97.163.2:587 (no proxy).
2020-09-04 11:13:08.752 DEBUG Smtp(2)[1] Proxy: Connection established.
2020-09-04 11:13:08.752 DEBUG Smtp(2)[1] Info: Connection succeeded.
2020-09-04 11:13:08.752 DEBUG Smtp(2)[1] Info: State changed from 'Connecting' to 'Reading'.
2020-09-04 11:13:08.757 INFO Smtp(2)[1] Response: 220 mail.software-concept.de ESMTP ready.
2020-09-04 11:13:08.757 DEBUG Smtp(2)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:13:08.757 DEBUG Smtp(2)[1] Info: State changed from 'Ready' to 'Sending'.
2020-09-04 11:13:08.757 INFO Smtp(2)[1] Command: EHLO nb-fardy****
2020-09-04 11:13:08.757 DEBUG Smtp(2)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Response: 250-mail.software-concept.de Hello nb-fardy**** [192.168.51.39]
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Response: 250-SIZE 52428800
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Response: 250-8BITMIME
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Response: 250-PIPELINING
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Response: 250-STARTTLS
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Response: 250 HELP
2020-09-04 11:13:08.782 DEBUG Smtp(2)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:13:08.782 DEBUG Smtp(2)[1] Info: State changed from 'Ready' to 'Sending'.
2020-09-04 11:13:08.782 INFO Smtp(2)[1] Command: STARTTLS
2020-09-04 11:13:08.782 DEBUG Smtp(2)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:13:08.788 INFO Smtp(2)[1] Response: 220 TLS go ahead
2020-09-04 11:13:08.788 DEBUG Smtp(2)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:13:08.788 DEBUG Smtp(2)[1] Info: Upgrading connection to TLS.
2020-09-04 11:13:08.788 DEBUG Smtp(2)[1] TLS: Using classic TLS core.
2020-09-04 11:13:08.788 DEBUG Smtp(2)[1] TLS: Enabled cipher suites: 0x0C1FFFFFFFF4F666.
2020-09-04 11:13:08.788 DEBUG Smtp(2)[1] TLS: Applicable cipher suites: 0x0C1FFFFFFFF4F666.
2020-09-04 11:13:08.788 DEBUG Smtp(2)[1] TLS: HandshakeMessage:ClientHello was sent.
2020-09-04 11:13:08.902 DEBUG Smtp(2)[1] TLS: HandshakeMessage:ServerHello was received.
2020-09-04 11:13:08.902 INFO Smtp(2)[1] TLS: Negotiating TLS 1.2, RSA with ephemeral Diffie-Hellman, AES with 256-bit key in GCM mode, AEAD.
2020-09-04 11:13:08.902 DEBUG Smtp(2)[1] TLS: The server supports secure renegotiation.
2020-09-04 11:13:08.902 DEBUG Smtp(2)[1] TLS: HandshakeMessage:Certificate was received.
2020-09-04 11:13:08.902 DEBUG Smtp(2)[1] TLS: HandshakeMessage:ServerKeyExchange was received.
2020-09-04 11:13:08.902 DEBUG Smtp(2)[1] TLS: HandshakeMessage:ServerHelloDone was received.
2020-09-04 11:13:08.902 DEBUG Smtp(2)[1] TLS: Verifying server certificate ('CN=*.software-concept.de').
2020-09-04 11:13:08.903 DEBUG Smtp(2)[1] TLS: Certificate verification result: Accept
2020-09-04 11:13:08.903 DEBUG Smtp(2)[1] TLS: Verifying server key exchange signature.
2020-09-04 11:13:08.904 DEBUG Smtp(2)[1] TLS: Received ephemeral Diffie-Hellman prime.
2020-09-04 11:13:08.919 DEBUG Smtp(2)[1] TLS: Ephemeral Diffie-Hellman prime size is 2048 bits (minimum allowed size is 1024 bits).
2020-09-04 11:13:08.981 DEBUG Smtp(2)[1] TLS: HandshakeMessage:ClientKeyExchange was sent.
2020-09-04 11:13:08.982 DEBUG Smtp(2)[1] TLS: CipherSpec:ChangeCipherSpec was sent.
2020-09-04 11:13:08.982 DEBUG Smtp(2)[1] TLS: HandshakeMessage:Finished was sent.
2020-09-04 11:13:09.069 DEBUG Smtp(2)[1] TLS: CipherSpec:ChangeCipherSpec was received.
2020-09-04 11:13:09.069 DEBUG Smtp(2)[1] TLS: HandshakeMessage:Finished was received.
2020-09-04 11:13:09.069 INFO Smtp(2)[1] TLS: Connection secured using cipher: TLS 1.2, RSA with ephemeral Diffie-Hellman, AES with 256-bit key in GCM mode, AEAD.
2020-09-04 11:13:09.069 DEBUG Smtp(2)[1] Info: Connection upgraded to TLS 1.2.
2020-09-04 11:13:09.069 DEBUG Smtp(2)[1] Info: State changed from 'Ready' to 'Sending'.
2020-09-04 11:13:09.069 INFO Smtp(2)[1] Command: EHLO nb-fardy****
2020-09-04 11:13:09.069 DEBUG Smtp(2)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:13:09.071 INFO Smtp(2)[1] Response: 250-mail.software-concept.de Hello nb-fardy**** [192.168.51.39]
2020-09-04 11:13:09.071 INFO Smtp(2)[1] Response: 250-SIZE 52428800
2020-09-04 11:13:09.071 INFO Smtp(2)[1] Response: 250-8BITMIME
2020-09-04 11:13:09.071 INFO Smtp(2)[1] Response: 250-PIPELINING
2020-09-04 11:13:09.071 INFO Smtp(2)[1] Response: 250 HELP
2020-09-04 11:13:09.071 DEBUG Smtp(2)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:13:09.093 ERROR Smtp(2)[1] Info: Rebex.Net.SmtpException: None of the supported authentication methods is accepted by the server.
   bei Rebex.Net.Smtp.kjyf(String fg, String fh, SmtpAuthentication fi)
2020-09-04 11:13:09.164 DEBUG Smtp(2)[1] Info: State changed from 'Ready' to 'Sending'.
2020-09-04 11:13:09.164 INFO Smtp(2)[1] Command: MAIL FROM:<**@conceptoffice.onmicrosoft.com> SIZE=401
2020-09-04 11:13:09.164 DEBUG Smtp(2)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:13:09.167 INFO Smtp(2)[1] Response: 250 OK
2020-09-04 11:13:09.167 DEBUG Smtp(2)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:13:09.167 DEBUG Smtp(2)[1] Info: State changed from 'Ready' to 'Pipelining'.
2020-09-04 11:13:09.167 INFO Smtp(2)[1] Command: RCPT TO:<e.fardy****@software-concept.de>
2020-09-04 11:13:09.172 INFO Smtp(2)[1] Response: 550 Authentication required for connections on TCP port 587
2020-09-04 11:13:09.172 DEBUG Smtp(2)[1] Info: State changed from 'Pipelining' to 'Sending'.
2020-09-04 11:13:09.173 INFO Smtp(2)[1] Command: RSET
2020-09-04 11:13:09.173 DEBUG Smtp(2)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:13:09.173 DEBUG Smtp(2)[1] TLS: TLS socket was closed, 0 bytes of data were received.
2020-09-04 11:13:09.173 DEBUG Smtp(2)[1] Info: Connection closed.
2020-09-04 11:13:09.195 DEBUG Smtp(2)[1] TLS: Closing TLS socket.
2020-09-04 11:13:09.195 DEBUG Smtp(2)[1] Info: State changed from 'Reading' to 'Disconnected'.
2020-09-04 11:13:09.214 ERROR Smtp(2)[1] Info: Rebex.Net.SmtpException: The server has closed the connection.
   bei kbqn.trhk()
   bei kbqn.trhm(String& ne)
   bei kbqn.trhn()
   bei Rebex.Net.Smtp.kjxa(Int32 cf, Boolean cg)
   bei Rebex.Net.Smtp.kjxb()
   bei Rebex.Net.Smtp.kjxg(Boolean ct, String[] cu, kbqp cv, String cw, Int64 cx)
   bei Rebex.Net.Smtp.kjxp(String dk, String[] dl, String dm, Stream dn, TransferEncoding dp)
   bei Rebex.Net.Smtp.kjxw(MimeMessage eg, Stream eh, MailAddress ei, MailAddressCollection ej)
   bei Rebex.Net.Smtp.kjxz(MailMessage er, MailAddress es, MailAddressCollection et)
by (270 points)
edited by
Log for 465

2020-09-04 11:19:44.961 Opening log file.
2020-09-04 11:19:44.961 INFO FileLogWriter(4)[1] Info: Assembly: Rebex.Common 2020 R2 for .NET 4.6-4.8
2020-09-04 11:19:44.961 INFO FileLogWriter(4)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2020-09-04 11:19:44.962 DEBUG FileLogWriter(4)[1] Info: Culture: de; Windows-1252
2020-09-04 11:19:44.962 DEBUG Smtp(4)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2020-09-04 11:19:44.962 INFO Smtp(4)[1] Info: Connecting to smtp.office365.com:465 using Smtp.
2020-09-04 11:19:44.962 INFO Smtp(4)[1] Info: Assembly: Rebex.Smtp 2020 R2 for .NET 4.6-4.8
2020-09-04 11:19:44.962 INFO Smtp(4)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2020-09-04 11:19:44.965 DEBUG Smtp(4)[1] Info: Culture: de; Windows-1252
2020-09-04 11:19:44.965 DEBUG Smtp(4)[1] Proxy: Resolving 'smtp.office365.com'.
2020-09-04 11:19:44.982 DEBUG Smtp(4)[1] Proxy: Connecting to 52.97.176.34:465 (no proxy).
2020-09-04 11:19:44.984 DEBUG Smtp(4)[1] Proxy: Connection established.
2020-09-04 11:19:44.984 DEBUG Smtp(4)[1] Info: Connection succeeded.
2020-09-04 11:19:44.984 DEBUG Smtp(4)[1] Info: Upgrading connection to TLS.
2020-09-04 11:19:44.984 DEBUG Smtp(4)[1] TLS: Using classic TLS core.
2020-09-04 11:19:44.984 DEBUG Smtp(4)[1] TLS: Enabled cipher suites: 0x0C1FFFFFFFF4F666.
2020-09-04 11:19:44.985 DEBUG Smtp(4)[1] TLS: Applicable cipher suites: 0x0C1FFFFFFFF4F666.
2020-09-04 11:19:44.985 DEBUG Smtp(4)[1] TLS: HandshakeMessage:ClientHello was sent.
2020-09-04 11:19:45.103 DEBUG Smtp(4)[1] TLS: HandshakeMessage:ServerHello was received.
2020-09-04 11:19:45.103 INFO Smtp(4)[1] TLS: Negotiating TLS 1.2, RSA with ephemeral Diffie-Hellman, AES with 256-bit key in GCM mode, AEAD.
2020-09-04 11:19:45.103 DEBUG Smtp(4)[1] TLS: The server supports secure renegotiation.
2020-09-04 11:19:45.104 DEBUG Smtp(4)[1] TLS: HandshakeMessage:Certificate was received.
2020-09-04 11:19:45.104 DEBUG Smtp(4)[1] TLS: HandshakeMessage:ServerKeyExchange was received.
2020-09-04 11:19:45.104 DEBUG Smtp(4)[1] TLS: HandshakeMessage:ServerHelloDone was received.
2020-09-04 11:19:45.104 DEBUG Smtp(4)[1] TLS: Verifying server certificate ('CN=*.software-concept.de').
2020-09-04 11:19:45.107 DEBUG Smtp(4)[1] TLS: Certificate verification result: Accept
2020-09-04 11:19:45.107 DEBUG Smtp(4)[1] TLS: Verifying server key exchange signature.
2020-09-04 11:19:45.109 DEBUG Smtp(4)[1] TLS: Received ephemeral Diffie-Hellman prime.
2020-09-04 11:19:45.128 DEBUG Smtp(4)[1] TLS: Ephemeral Diffie-Hellman prime size is 2048 bits (minimum allowed size is 1024 bits).
2020-09-04 11:19:45.190 DEBUG Smtp(4)[1] TLS: HandshakeMessage:ClientKeyExchange was sent.
2020-09-04 11:19:45.190 DEBUG Smtp(4)[1] TLS: CipherSpec:ChangeCipherSpec was sent.
2020-09-04 11:19:45.190 DEBUG Smtp(4)[1] TLS: HandshakeMessage:Finished was sent.
2020-09-04 11:19:45.273 DEBUG Smtp(4)[1] TLS: CipherSpec:ChangeCipherSpec was received.
2020-09-04 11:19:45.273 DEBUG Smtp(4)[1] TLS: HandshakeMessage:Finished was received.
2020-09-04 11:19:45.274 INFO Smtp(4)[1] TLS: Connection secured using cipher: TLS 1.2, RSA with ephemeral Diffie-Hellman, AES with 256-bit key in GCM mode, AEAD.
2020-09-04 11:19:45.274 DEBUG Smtp(4)[1] Info: Connection upgraded to TLS 1.2.
2020-09-04 11:19:45.274 DEBUG Smtp(4)[1] Info: State changed from 'Connecting' to 'Reading'.
2020-09-04 11:19:45.331 INFO Smtp(4)[1] Response: 220 mail.software-concept.de ESMTP ready.
2020-09-04 11:19:45.331 DEBUG Smtp(4)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:19:45.331 DEBUG Smtp(4)[1] Info: State changed from 'Ready' to 'Sending'.
2020-09-04 11:19:45.331 INFO Smtp(4)[1] Command: EHLO nb-fardy****
2020-09-04 11:19:45.331 DEBUG Smtp(4)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:19:45.338 INFO Smtp(4)[1] Response: 250-mail.software-concept.de Hello nb-fardy**** [192.168.51.39]
2020-09-04 11:19:45.338 INFO Smtp(4)[1] Response: 250-SIZE 52428800
2020-09-04 11:19:45.338 INFO Smtp(4)[1] Response: 250-8BITMIME
2020-09-04 11:19:45.338 INFO Smtp(4)[1] Response: 250-PIPELINING
2020-09-04 11:19:45.338 INFO Smtp(4)[1] Response: 250 HELP
2020-09-04 11:19:45.338 DEBUG Smtp(4)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:19:45.369 ERROR Smtp(4)[1] Info: Rebex.Net.SmtpException: None of the supported authentication methods is accepted by the server.
   bei Rebex.Net.Smtp.kjyf(String fg, String fh, SmtpAuthentication fi)
2020-09-04 11:19:45.439 DEBUG Smtp(4)[1] Info: State changed from 'Ready' to 'Sending'.
2020-09-04 11:19:45.439 INFO Smtp(4)[1] Command: MAIL FROM:<**@conceptoffice.onmicrosoft.com> SIZE=401
2020-09-04 11:19:45.439 DEBUG Smtp(4)[1] Info: State changed from 'Sending' to 'Reading'.
2020-09-04 11:19:45.443 INFO Smtp(4)[1] Response: 250 OK
2020-09-04 11:19:45.443 DEBUG Smtp(4)[1] Info: State changed from 'Reading' to 'Ready'.
2020-09-04 11:19:45.443 DEBUG Smtp(4)[1] Info: State changed from 'Ready' to 'Pipelining'.
2020-09-04 11:19:45.443 INFO Smtp(4)[1] Command: RCPT TO:<e.fardy****@software-concept.de>
2020-09-04 11:19:45.458 INFO Smtp(4)[1] Response: 250 Accepted
2020-09-04 11:19:45.458 INFO Smtp(4)[1] Command: DATA
2020-09-04 11:19:45.461 INFO Smtp(4)[1] Response: 354 Enter message, ending with "." on a line by itself
2020-09-04 11:19:45.466 INFO Smtp(4)[1] Response: 250 OK id=1kE7sm-00062D-29
2020-09-04 11:19:45.466 DEBUG Smtp(4)[1] Info: State changed from 'Pipelining' to 'Ready'.

1 Answer

0 votes
by (148k points)

According to the logs, the SMTP client is apparently not communicating with any Office365 server. This is strange, because it did actually attempt to connect to 'smtp.office365.com', which was correctly resolved to 52.97.163.2 and 52.97.176.34 (both are actually Office365 servers).

However, the actual communication shows otherwise:

Response: 220 mail.software-concept.de ESMTP ready.
...
Response: 250-mail.software-concept.de Hello nb-fardy**** [192.168.51.39]
...
TLS: Verifying server certificate ('CN=*.software-concept.de').

These log entries prove beyond reasonable doubt that the application was not communicating with Office365 servers. What remains is to determine the reason.

a) One possibility is that your application uses a custom transport layer that routes connections to different IP addresses than those specified in Connect method call.

b) A more likely possibility is that your customer have configured their router or firewall so that it intercepts some or all SMTP connections, and silently passes them to a different IP address. To determine whether this is the case, ask the customer to try running "telnet 52.97.176.34 587" or "telnet outlook.office365.com 587" from Windows command line (at the same machine). The responses are supposed to look like "220 AM0PR10CA0009.outlook.office365.com Microsoft ESMTP MAIL Service ready at Fri, 4 Sep 2020 13:58:58 +0000".

As a side note, it looks like your application (or your customer) disabled some essential parts of certificate validation (such as the host name check). This is dangerous and strongly discouraged.

When the Smtp class connects to outlook.office365.com, but the server responds with a mail.software-concept.de certificate, it should have failed (and it would have failed with default settings). Please be advised that disabling parts of certificate validation makes your application vulnerable to trivial man-in-the-middle attacks, making TLS essentially useless.

...