Exchange 2010 Outbound Delivery Queue Latency

Posted on 2012-09-05
Last Modified: 2013-11-12

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
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.
Question by:terminalb
    LVL 52

    Expert Comment

    by:Manpreet SIngh Khatra
    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
    LVL 2

    Author Comment

    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.
    LVL 52

    Expert Comment

    by:Manpreet SIngh Khatra
    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
    LVL 63

    Expert Comment

    by:Simon Butler (Sembee)
    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.

    LVL 2

    Author Comment

    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 (Postfix) with ESMTP id C26FA12C83C5 for <>; 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?
    LVL 63

    Expert Comment

    by:Simon Butler (Sembee)
    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.

    LVL 2

    Author Comment

    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      <      
    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:<>      
    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:<>      
    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:<> 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!
    LVL 63

    Accepted Solution

      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.

    LVL 2

    Author Closing Comment

    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!

    Featured Post

    IT, Stop Being Called Into Every Meeting

    Highfive is so simple that setting up every meeting room takes just minutes and every employee will be able to start or join a call from any room with ease. Never be called into a meeting just to get it started again. This is how video conferencing should work!

    Join & Write a Comment

    "Migrate" an SMTP relay receive connector to a new server using info from an old server.
    Disabling the Directory Sync Service Account in Office 365 will stop directory synchronization from working.
    In this Micro Video tutorial you will learn the basics about Database Availability Groups and How to configure one using a live Exchange Server Environment. The video tutorial explains the basics of the Exchange server Database Availability grou…
    how to add IIS SMTP to handle application/Scanner relays into office 365.

    745 members asked questions and received personalized solutions in the past 7 days.

    Join the community of 500,000 technology professionals and ask your questions.

    Join & Ask a Question

    Need Help in Real-Time?

    Connect with top rated Experts

    20 Experts available now in Live!

    Get 1:1 Help Now