• Status: Solved
  • Priority: Medium
  • Security: Public
  • Views: 2553
  • Last Modified:

Exchange 2010 Outbound Delivery Queue Latency

Hello,

Exchange 2010 SP2, Server 2008 R2 environment.  I recently received an email from one of my users reporting a 6 hour delay in the delivery of an outbound email to an external Distribution Group.  This type of delay is not typical, and is the first of it's kind since we brought Exchange online 6 months ago.  I ran a Get-MessageTrackingLog and found that the latency occurred during the SMTP Send event.  Here's a snippet of the logs:

Source                  : SMTP
EventId                 : SEND
MessageInfo             : 2012-09-04T15:57:11.911Z;SRV=SERVER.DOMAIN.local:TOTAL=0;SRV=SERVER.DOMAIN.local:TOTAL=23
                          855|QD=23855
MessageLatency          : 06:37:35.9810000
MessageLatencyType      : EndToEnd
EventData               :

I then used the .\ConvertTo-MessageLatency.ps1 script from the Scripts folder and filtered so only end-to-end hops were included:

Get-messagetrackinglog -messageid:6AA6EE34802B304788BED339F0EFB0691BC4D@SERVER.DOMAIN.local | ? {$_.MessageLatencyType -eq 'EndToEnd'} | .\ConvertTo-MessageLatency.ps1 | Fl

InternalMessageId   : 339985
MessageId           : <6AA6EE34802B304788BED330039F0EFB0691BC4D@SERVER.DOMAIN.local>
MessageLatency      : 06:37:35.9810000
MessageLatencyType  : EndToEnd
ComponentServerFqdn : SERVER.DOMAIN.local
ComponentCode       : TOTAL
ComponentName       : Total Server Latency
ComponentLatency    : 06:37:35

InternalMessageId   : 339985
MessageId           : <6AA6EE34802B304788BED330039F0EFB0691BC4D@SERVER.DOMAIN.local>
MessageLatency      : 06:37:35.9810000
MessageLatencyType  : EndToEnd
ComponentServerFqdn : SERVER.DOMAIN.local
ComponentCode       : QD
ComponentName       : Delivery Queue
ComponentLatency    : 06:37:35

So you can see, I'm looking at a six and a half hour delay from what looks like occurred in the Delivery Queue.

Here's my questions:  

1. Where can I find more information on ComponentCodes, ie QD, TOTAL, CRSL, etc.

2. Knowing the Delivery Queue is the last stop in our environment, how can I verify what caused the latency?  Could it be throttling on the recipient end?  Our end?

3. Was the delay during the handoff from the Categorizer to the Delivery Queue?  How would I know?

Thanks in advance.
0
terminalb
Asked:
terminalb
  • 4
  • 3
  • 2
1 Solution
 
Manpreet SIngh KhatraSolutions Architect, Project LeadCommented:
If the end user has Outlook you can check the Header to get ecatly where the delay might have happened :)
The delay would have happened in about 2 hops and there you can then concerntrate where the issue might have happened.

- Rancy
0
 
terminalbAuthor Commented:
Unfortunately I have not been able to get my hands on the email as it was received by the recipient.  The only documentation I have is the message from the sender's Sent Items and a copy of the DSN sent by my own Exchange server:

"This message hasn't been delivered yet. Delivery will continue to be attempted.

The server will keep trying to deliver this message for the next 1 days, 19 hours and 55 minutes. You'll be notified if the message can't be delivered by that time."

Not very informative.
0
 
Manpreet SIngh KhatraSolutions Architect, Project LeadCommented:
The delay message comes if the first handshake between you and the Recipient server doesnt goes well :(
As you might have set retry to it gives you a message that it will try after sometime.

- Rancy
0
What does it mean to be "Always On"?

Is your cloud always on? With an Always On cloud you won't have to worry about downtime for maintenance or software application code updates, ensuring that your bottom line isn't affected.

 
Simon Butler (Sembee)ConsultantCommented:
Without the header from the other side, it is impossible to know where the delay occured.
The NDR that you received would tend to indicate Exchange was having a problem communicating with the next hop. That means that most of the potential cause is out of your control, could be a routing issue, or a problem with the remote server.

Simon.
0
 
terminalbAuthor Commented:
Here's two hops from a recently affected email.  You can see the first hop is at 12:42:57 CDT received from our server.  The next hop is received from our server by the recipient server 1 hour and 5 minutes later at 1:46:58 CDT (11:46:58 PDT):

Second hop - Received:  from MYSERVER.MYDOMAIN.local by RECIPIENITSERVER.org (Postfix) with ESMTP id C26FA12C83C5 for <ALIAS@DOMAIN.org>; Wed,  5 Sep 2012 11:46:58 -0700 (PDT)

First hop - Received:  from MYSERVER.MYDOMAIN.local ([::1]) by MYSERVER.MYDOMAIN.local ([::1]) with mapi id 14.02.0247.003; Wed, 5 Sep 2012 12:42:57 -0500

So based on this, I know the delay occurs during the handoff from my server to the recipient's Postfix server, but I still can't determine if the delay is in sending the message or receiving it.  Any suggestions here?
0
 
Simon Butler (Sembee)ConsultantCommented:
You cannot differentiate betwen sending the message or receiving it. They are the same thing.
If it is only happening with one domain then it is an issue with the remote server, with Exchange failing to connect to it.

Simon.
0
 
terminalbAuthor Commented:
I agree, Simon and I'm leaning towards a recipient issue at this point; however, before I close this thread, I wanted to add what I found today in our SMTPSend protocol logs:

sequence-number      local-endpoint      remote-endpoint      event      data      context
0            X.X.X.X:25      *            attempting to connect
1      10.254.X.X:39545      X.X.X.X:25      +            
2      10.254.X.X:39545      X.X.X.X:25      <      220 ******************************      
3      10.254.X.X:39545      X.X.X.X:25      >      EHLO DOMAIN.local      
4      10.254.X.X:39545      X.X.X.X:25      <      250-DOMAIN.org      
5      10.254.X.X:39545      X.X.X.X:25      <      250-PIPELINING      
6      10.254.X.X:39545      X.X.X.X:25      <      250-SIZE 104857600      
7      10.254.X.X:39545      X.X.X.X:25      <      250-VRFY      
8      10.254.X.X:39545      X.X.X.X:25      <      250-ETRN      
9      10.254.X.X:39545      X.X.X.X:25      <      250-ENHANCEDSTATUSCODES      
10      10.254.X.X:39545      X.X.X.X:25      <      250-8BITMIME      
11      10.254.X.X:39545      X.X.X.X:25      <      250 DSN      
12      10.254.X.X:39545      X.X.X.X:25      *      339758      sending message
13      10.254.X.X:39545      X.X.X.X:25      >      MAIL FROM:<USERA@DOMAIN.ORG> SIZE=18193      
14      10.254.X.X:39545      X.X.X.X:25      >      RCPT TO:<RECIPIENTA@DOMAIN.ORG>      
15      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.0 Ok      
16      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.5 Ok      
17      10.254.X.X:39545      X.X.X.X:25      >      DATA      
18      10.254.X.X:39545      X.X.X.X:25      <      354 End data with <CR><LF>.<CR><LF>      
19      10.254.X.X:39545      X.X.X.X:25      <      250 2.0.0 Ok: queued as 0D92D12C829C      
20      10.254.X.X:39545      X.X.X.X:25      *      339985      sending message
21      10.254.X.X:39545      X.X.X.X:25      >      MAIL FROM:<USERA@DOMAIN.ORG> SIZE=95340      
22      10.254.X.X:39545      X.X.X.X:25      >      RCPT TO:<RECIPIENTA@DOMAIN.ORG>>      
23      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.0 Ok      
24      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.5 Ok      
25      10.254.X.X:39545      X.X.X.X:25      >      DATA      
26      10.254.X.X:39545      X.X.X.X:25      <      354 End data with <CR><LF>.<CR><LF>      
27      10.254.X.X:39545      X.X.X.X:25      <      250 2.0.0 Ok: queued as 5A2C71638383      
28      10.254.X.X:39545      X.X.X.X:25      *      340276      sending message
29      10.254.X.X:39545      X.X.X.X:25      >      MAIL FROM:<USERB@DOMAIN.ORG> SIZE=7652      
30      10.254.X.X:39545      X.X.X.X:25      >      RCPT TO:<RECIPIENTB@DOMAIN.org>      
31      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.0 Ok      
32      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.5 Ok      
33      10.254.X.X:39545      X.X.X.X:25      >      DATA      
34      10.254.X.X:39545      X.X.X.X:25      <      354 End data with <CR><LF>.<CR><LF>      
35      10.254.X.X:39545      X.X.X.X:25      <      250 2.0.0 Ok: queued as C7B0812C8514      
36      10.254.X.X:39545      X.X.X.X:25      *      340644      sending message
37      10.254.X.X:39545      X.X.X.X:25      >      MAIL FROM:<USERC@DOMAIN.ORG> SIZE=5896      
38      10.254.X.X:39545      X.X.X.X:25      >      RCPT TO:<RECIPIENTC@DOMAIN.org>      
39      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.0 Ok      
40      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.5 Ok      
41      10.254.X.X:39545      X.X.X.X:25      >      DATA      
42      10.254.X.X:39545      X.X.X.X:25      <      354 End data with <CR><LF>.<CR><LF>      
43      10.254.X.X:39545      X.X.X.X:25      <      250 2.0.0 Ok: queued as 03A2D1638385      
44      10.254.X.X:39545      X.X.X.X:25      *      341039      sending message
45      10.254.X.X:39545      X.X.X.X:25      >      MAIL FROM:<USERD@DOMAIN.org> SIZE=8952      
46      10.254.X.X:39545      X.X.X.X:25      >      RCPT TO:<RECIPIENTD@DOMAIN.ORG>      
47      10.254.X.X:39545      X.X.X.X:25      >      RCPT TO:<RECIPIENTD@DOMAIN.ORG>      
48      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.0 Ok      
49      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.5 Ok      
50      10.254.X.X:39545      X.X.X.X:25      <      250 2.1.5 Ok      
51      10.254.X.X:39545      X.X.X.X:25      >      DATA      
52      10.254.X.X:39545      X.X.X.X:25      <      354 End data with <CR><LF>.<CR><LF>      
53      10.254.X.X:39545      X.X.X.X:25      <      250 2.0.0 Ok: queued as 349DC16383B2      
54      10.254.X.X:39545      X.X.X.X:25      >      QUIT      
55      10.254.X.X:39545      X.X.X.X:25      <      221 2.0.0 Bye      
56      10.254.X.X:39545      X.X.X.X:25      -            Local

You can tell by the sequence numbers that all of these emails were sent on the same SMTP connection to the recipient server but we see multiple emails sent from various users in my organization to different addresses in the same domain.  I know that not all of these emails were sent at the same time so this looks very much like throttling to me.  We are using all default settings for our ThrottlingPolicy so I doubt it's on our end.  I could be completely off-base here so I just wanted to get the opinion of Exchange Admins before I bring this to the attention of the recipient's IT dept.  Thanks!
0
 
Simon Butler (Sembee)ConsultantCommented:
This:
  220 ******************************      

Means a Cisco PIX/ASA is involved.
Well known for causing delivery problems. If it is your device, then turn off the SMTP guard feature.
http://support.microsoft.com/kb/320027

Simon.
0
 
terminalbAuthor Commented:
The left and right facing carats show the direction of communication.  In the case of both the initial 220************* greeting and the subsequent SMTP verbs, the carats are left facing so that communication was generated by the recipient MTA which in this case is a Postfix Linux mail server.

Ok well I'm going to chalk this up to either a firewall setting or throttling on the recipient side.  Thanks Simon!
0

Featured Post

Independent Software Vendors: We Want Your Opinion

We value your feedback.

Take our survey and automatically be enter to win anyone of the following:
Yeti Cooler, Amazon eGift Card, and Movie eGift Card!

  • 4
  • 3
  • 2
Tackle projects and never again get stuck behind a technical roadblock.
Join Now