Testing SMTP connectivity between On-premise Exchange and Exchange Online

Having recently been troubleshooting a customers hybrid Exchange environment I thought I’d write about my experience.

The customer had an Exchange 2010 deployment and the Hybrid Configuration Wizard had already been run but they were having mail flow problems from their On-Prem to Online mailboxes.

First I decided to perform the basic SMTP connectivity test to Exchange Online Protection to make sure their address was allowed to send mail through. To do this from a command prompt I ran:

telnet [tenantname].mail.protection.outlook.com 25
mail from: onprem.mailbox@domain.com
rcpt to: cloud.mailbox@domain.com

Now, normally you should get a “250 2.1.5 Recipient OK” message back however we received:

smtp blacklist

Our IP address is blacklisted, opps! So we proceeded to resolve the blacklist issue, upon investigation I discovered that the Exchange servers were actually connecting externally as the default IP address on their internet connection, which client devices also used.

I always recommend that mail servers should be presented externally via an IP address that isn’t used by other services just to prevent issues like this.

Once removed from the blacklist we were able to perform the test again successfully, all good, or so we thought!

Email was still not flowing and building up in the queue, at this point I turned on verbose logging on the outbound SMTP connector and went to check the SmtpSend folder for the logs.

Upon opening the logs I found the following, repeated

#Fields: date-time,connector-id,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context
2015-09-29T00:08:44.653Z,Outbound to Office 365,08D2B5B9B93409D6,0,,,*,,attempting to connect
2015-09-29T00:08:44.653Z,Outbound to Office 365,08D2B5B9B93409D6,1,[INTERNAL IP]:14101,,+,,
2015-09-29T00:08:44.669Z,Outbound to Office 365,08D2B5B9B93409D6,2,[INTERNAL IP]:14101,,<,"220 AM1FFO11OLC001.mail.protection.outlook.com Microsoft ESMTP MAIL Service ready at Tue, 29 Sep 2015 00:08:43 +0000",
2015-09-29T00:08:44.669Z,Outbound to Office 365,08D2B5B9B93409D6,3,[INTERNAL IP]:14101,,>,EHLO [HOSTNAME],
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,4,[INTERNAL IP]:14101,,<,250-AM1FFO11OLC001.mail.protection.outlook.com Hello [IP ADDRESS],
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,5,[INTERNAL IP]:14101,,<,250-SIZE 157286400,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,6,[INTERNAL IP]:14101,,<,250-PIPELINING,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,7,[INTERNAL IP]:14101,,<,250-DSN,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,8,[INTERNAL IP]:14101,,<,250-ENHANCEDSTATUSCODES,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,9,[INTERNAL IP]:14101,,<,250-STARTTLS,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,10,[INTERNAL IP]:14101,,<,250-8BITMIME,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,11,[INTERNAL IP]:14101,,<,250-BINARYMIME,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,12,[INTERNAL IP]:14101,,<,250 CHUNKING,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,13,[INTERNAL IP]:14101,,>,STARTTLS,
2015-09-29T00:08:44.685Z,Outbound to Office 365,08D2B5B9B93409D6,14,[INTERNAL IP]:14101,,-,,Remote

Now, I like to play spot the difference with logs from working deployments to try and spot things that are not working or incorrect, so I got a log from a working deployment:

2015-04-11T16:24:07.627Z,Outbound to Office 365,08D21A598CD8BB94,0,,,*,,attempting to connect
2015-04-11T16:24:07.643Z,Outbound to Office 365,08D21A598CD8BB94,1,[INTERNAL IP]:30731,,+,,
2015-04-11T16:24:07.659Z,Outbound to Office 365,08D21A598CD8BB94,2,[INTERNAL IP]:30731,,<,"220 AM1FFO11FD013.mail.protection.outlook.com Microsoft ESMTP MAIL Service ready at Sat, 11 Apr 2015 16:25:42 +0000",
2015-04-11T16:24:07.659Z,Outbound to Office 365,08D21A598CD8BB94,3,[INTERNAL IP]:30731,,>,EHLO mail.[DOMAIN].com,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,4,[INTERNAL IP]:30731,,<,250-AM1FFO11FD013.mail.protection.outlook.com Hello [IP ADDRESS],
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,5,[INTERNAL IP]:30731,,<,250-SIZE 157286400,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,6,[INTERNAL IP]:30731,,<,250-PIPELINING,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,7,[INTERNAL IP]:30731,,<,250-DSN,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,8,[INTERNAL IP]:30731,,<,250-ENHANCEDSTATUSCODES,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,9,[INTERNAL IP]:30731,,<,250-STARTTLS,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,10,[INTERNAL IP]:30731,,<,250-8BITMIME,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,11,[INTERNAL IP]:30731,,<,250-BINARYMIME,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,12,[INTERNAL IP]:30731,,<,250 CHUNKING,
2015-04-11T16:24:07.690Z,Outbound to Office 365,08D21A598CD8BB94,13,[INTERNAL IP]:30731,,>,STARTTLS,
2015-04-11T16:24:07.706Z,Outbound to Office 365,08D21A598CD8BB94,14,[INTERNAL IP]:30731,,<,220 2.0.0 SMTP server ready,
2015-04-11T16:24:07.706Z,Outbound to Office 365,08D21A598CD8BB94,15,[INTERNAL IP]:30731,,*,,Sending certificate
2015-04-11T16:24:07.706Z,Outbound to Office 365,08D21A598CD8BB94,16,[INTERNAL IP]:30731,,*,"CN=mail.[DOMAIN].com, OU=PositiveSSL Multi-Domain, OU=Domain Control Validated",Certificate subject
2015-04-11T16:24:07.706Z,Outbound to Office 365,08D21A598CD8BB94,17,[INTERNAL IP]:30731,,*,"CN=COMODO RSA Domain Validation Secure Server CA, O=COMODO CA Limited, L=Salford, S=Greater Manchester, C=GB",Certificate issuer name
2015-04-11T16:24:07.706Z,Outbound to Office 365,08D21A598CD8BB94,18,[INTERNAL IP]:30731,,*,[CERTIFICATE SERIAL NUMBER],Certificate serial number

As you can see, after the STARTTLS we should see the “220 2.0.0 SMTP server ready” response followed by the establishment of the TLS connection, but in our case we weren’t and presumably the “Remote” entry was to say it had timed out.

Now I had to find a way to manually establish a TLS SMTP connection, I’m not aware of a way of using the standard telnet based approach to do this so had to find an alternative.

That alternative was to use openSSL to establish the connection, to do this you can use the following command:

openssl s_client -starttls smtp -crlf -connect [tenantname].mail.protection.outlook.com:25

When run work a working machine the connection should establish and look similar to the below (full output is much longer):

smtp TLS successful

However from the customers Exchange server it would not connect

smtp TLS unsuccessful

The customer raised it with their firewall team who advised that there was some “app awareness configured and it only allowed smtp over tls” not sure how it worked from a telnet client or what they changed to resolve it but that’s the dark art of firewall appliances!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s