Troubleshooting Delayed Message Delivery in Exchange


Post to Twitter Post to Facebook Post to StumbleUpon

As more and more anti-spam solutions start doing “interesting” things with SMTP and mail delivery, there is an increased chance of users reporting that mail messages to certain domains are delayed. Unlike a full non-delivery report (NDR) which will list the SMTP error codes for easy identification of the reason for the rejection, a delayed delivery report could be the result of an Internet connection issue, spam filter, offline server, or any number of other causes. The remainder of this post details how to track down possible causes for Internet delivery issues.

First, start with Exchange System Manager. After you open Exchange System Manager, expand Servers, expand the server, then select Queues.

Viewing the SMTP queues in ESM

Viewing the SMTP queues in ESM

Look for the connector with the domain that you are having trouble sending to. In the image above, it’s the last queue in the list. We can tell from ESM that there is a problem with this queue because it shows to be in a Retry status under the State column. And when you select the queue, look under Additional Queue Information at the bottom of the screen and you’ll see the result of the last connection attempt. In this case, we can see that the connection was dropped by the remote host. So, in this case, we were able to connect to the remote mail host, which rules out internet connectivity issues, and now we need to see why the remote host is dropping the connection. Before we can do that, we need a couple of other pieces of information.

If you double-click on the connector for the problematic domain, you will get the Find Messages window to open. Click on the Find Now button to see all the messages that are stuck in the queue:

Using Find Messages to view the hung messages in the queue

Using Find Messages to view the hung messages in the queue

In this example, we can see two messages that have been sent by the Administrator account are waiting in a Retry state in the queue. Now, we need one more piece of information, so double-click one of the messages.

Looking for the recipient in the hung message

Looking for the recipient in the hung message

If you look in the Recipients block, you can see the e-mail address of the recipient for this message. Remember that for later.

Next, we want to look in the SMTP logs to see if the remote server sent a valid SMTP code before it dropped the connection. Usually, when a remote host drops a connection, the SMTP service on the Exchange server does not log the code sent by the remote host before the connection is dropped, but we might get lucky. So, let’s open the LogFiles folder and see what the SMTP logs have to say. Open the start menu and enter the path to the LogFiles folder, usually C:WINDOWSsystem32LogFiles

Opening the LogFiles folder

Opening the LogFiles folder

Now, if SMTP logging has been enabled on your server, you will have an SMTPSVC1 or similarly-named folder inside of the LogFiles folder.

SMTPSVC1 folder missing from LogFiles

SMTPSVC1 folder missing from LogFiles

In this example, we can see that the SMTP service has not had logging enabled. No worries, we can quickly and easily enable logging for our testing. Go back into ESM, expand Protocols under the server, expand SMTP, right-click on the Default SMTP Virtual Server, and select Properties.

Opening the properties of the Default SMTP Virtual Server

Opening the properties of the Default SMTP Virtual Server

Once you open the Properties, turn on the Enable Logging checkbox, then select Microsoft IIS Log File Format from the Active Log Format drop-down menu.

Enable the Microsoft IIS Log format logging

Enable the Microsoft IIS Log format logging

Close the Properties window and stop and restart the SMTP service on the server. You will probably need to force the connection again after you restart the SMTP service to ensure that SMTP makes another delivery attempt on the messages. Back in the Queues node, right-click on the problematic SMTP connector and select Force Connection.

Forcing teh SMTP connector to retry a connection

Forcing the SMTP connector to retry a connection

After the connection attempts and fails, you can go into the SMTPSVC1 folder that now appears under the LogFiles folder and open the log file to review the connection. If you already had logging enabled, you can force the connection attempt and then open the most recent SMTP log file to look for the connection data.

Here is the pertinent information from the log file in this example:

71.n.n.n, OutboundConnectionResponse, z/z/2009, 17:34:33, SMTPSVC1, SERVER, -, 31, 0, 117, 0, 0, -, -, 220 xx.com Microsoft ESMTP MAIL Service, Version: 6.0.3790.3959
71.n.n.n, OutboundConnectionCommand, z/z/2009, 17:34:33, SMTPSVC1, SERVER, -, 31, 0, 4, 0, 0, EHLO, -, yy.com,
71.n.n.n, OutboundConnectionResponse, z/z/2009, 17:34:33, SMTPSVC1, SERVER, -, 62, 0, 45, 0, 0, -, -, 250-xx.com Hello [70.n.n.n.n],
71.n.n.n, OutboundConnectionCommand, z/z/2009, 17:34:33, SMTPSVC1, SERVER, -, 62, 0, 4, 0, 0, MAIL, -, FROM:<
Administrator@yy.com>,
71.n.n.n, OutboundConnectionResponse, z/z/2009, 17:34:33, SMTPSVC1, SERVER, -, 78, 0, 59, 0, 0, -, -, 250 2.1.0 
Administrator@yy.com....Sender OK,
71.n.n.n, OutboundConnectionCommand, z/z/2009, 17:34:33, SMTPSVC1, SERVER, -, 78, 0, 4, 0, 0, RCPT, -, TO:<
mm@xx.com>,
71.n.n.n, OutboundConnectionResponse, z/z/2009, 17:34:44, SMTPSVC1, SERVER, -, 15, 0, 117, 0, 0, -, -, 220 xx.com Microsoft ESMTP MAIL Service, Version: 6.0.3790.3959
71.n.n.n, OutboundConnectionCommand, z/z/2009, 17:34:44, SMTPSVC1, SERVER, -, 15, 0, 4, 0, 0, EHLO, -, yy.com,
71.n.n.n, OutboundConnectionResponse, z/z/2009, 17:34:44, SMTPSVC1, SERVER, -, 47, 0, 45, 0, 0, -, -, 250-xx.com Hello [70.n.n.n.n],
71.n.n.n, OutboundConnectionCommand, z/z/2009, 17:34:44, SMTPSVC1, SERVER, -, 47, 0, 4, 0, 0, MAIL, -, FROM:<
Administrator@yy.com>,
71.n.n.n, OutboundConnectionResponse, z/z/2009, 17:34:44, SMTPSVC1, SERVER, -, 78, 0, 59, 0, 0, -, -, 250 2.1.0 
Administrator@yy.com....Sender OK,
71.n.n.n, OutboundConnectionCommand, z/z/2009, 17:34:44, SMTPSVC1, SERVER, -, 78, 0, 4, 0, 0, RCPT, -, TO:<
mm@xx.com>,

As suspected, the dropped connection from the remote site does not give us a complete SMTP transaction log on our Exchange server. We see the initial connection attempt, the EHLO command our server sends, the MAIL command out server sends, and the RCPT command our server sends. After that, the connection is reset by the other end, and the SMTP process on our server does not capture the information. Not to worry, we can still get that information. How? Telnet.

Open a command prompt on your server. Run the nslookup command. At the nslookup prompt, enter set type=mx and press Enter. Then enter the domain name of the site you are trying to send to and press Enter. You’ll get a response similar to:

Reading the results from the nslookup command

Reading the results from the nslookup command

The key piece of information needed is the mail exchanger, which will be the last item listed in the response. Make note of that server name. Now, in the same command prompt, type telnet mailserver 25, where mailserver is the name of the server you identified from the nslookup command. When the connection is made, type ehlo and press return. You should get a response similar to:

 

Connecting to the remote mail server

Connecting to the remote mail server

Now, type the following commands and press Enter after each one. You will use the FROM address that you got from the Find Now search in the ESM Queues, and you will use the TO address that you got earlier as well.

mail from: sender@domain.com
rcpt to: recipient@domain.com

In our case, we get our answer as soon as we provide the recipient’s address:

Responses from the remote SMTP server

Responses from the remote SMTP server

The remote mail server responds to the rcpt command with a 550 5.7.1 response, indicating that it will not accept the message. In this case, the remote host is using Trend Micro’s Email Reputation service, and that service, for whatever reason, has denied access for the sender to send mail to that recipient.

Unfortunately, because the remote server issues the response and then immediately drops the connection, the sending server never has an opportunity to log the response, so the message goes into a retry state, and the server will continue to try to deliver the message until the timeout value is reached (72 hours by default in Exchange) and then the sender will get an NDR indicating that the message could not be delivered within the timeout window. This doesn’t tell the sender that their message was blocked by a spam filter, and their only real recourse, without our troubleshooting, is to try to contact the recipient some other way and let the receipient know that the sender had problems getting an e-mail through.

I’m afraid that this type of SMTP behavior is only going to become more prominent, meaning that we will likely get called into action to try to figure out why a message never got delivered. So long as we have access to the sending mail server, it’s not that hard to figure out. Just follow these steps to find the SMTP code returned by the receiving mail server, and you can then continue troubleshooting from there.