none
Substantial delays in message sending from an internal relay connector

    Question

  • Hi,

    has anyone feedback for the following delay I see in almost all of our relayed messages? I am no exchange expert, but 14 min seems like a lot for a mail from on-premise 2013 to O365 (we run a hybrid setup). Mail is relayed from a server (status message) to an Exchange relay connector. Here the message trace of the step that takes long:

    RunspaceId              : 753829ed-7203-4bf5-ac0c-f0732ed3a655
    Timestamp               : 24-08-2017 09:21:40
    ClientIp                : 172.16.0.187
    ClientHostname          : [OUR_MAILSERVERNAME]
    ServerIp                : 94.245.120.74
    ServerHostname          : [O365_TENANTNAME]-mail-onmicrosoft-com.mail.protection.outlook.com
    SourceContext           : ;250 2.6.0 <af005da7e39a4c37aca780243290f467@[OUR_MAILSERVER]> [InternalId=57947698760025, Hostn
                              ame=HE1PR0401MB2187.eurprd04.prod.outlook.com] 7395 bytes in 0.212, 33.919 KB/sec Queued mail
                               for delivery;ClientSubmitTime:
    ConnectorId             : Outbound to Office 365
    Source                  : SMTP
    EventId                 : SEND
    InternalMessageId       : 163646843912219
    MessageId               : <af005da7e39a4c37aca780243290f467@[OUR_MAILSERVER]>
    Recipients              : {[RECIPIENT_O365_MAIL]}
    RecipientStatus         : {250 2.1.5 Recipient OK}
    TotalBytes              : 4390
    RecipientCount          : 1
    RelatedRecipientAddress :
    Reference               :
    MessageSubject          : Test mail with huge delay
    Sender                  : [SENDEREMAIL]
    ReturnPath              : [SENDEREMAIL]
    Directionality          : Incoming
    TenantId                :
    OriginalClientIp        :
    MessageInfo             : 2017-08-24T07:06:52.487Z;SRV=[OUR_MAILSERVER]:TOTAL-FE=0.062|SMRPI-FrontendProxyAgent=0.006|SMRP
                              I=0.006|SMR=0.009|SMS=0.062;SRV=[OUR_MAILSERVER]:TOTAL-HUB=888.325|SMRDE=0.002|SMRCL=0.114|SMRC=
                              0.115|SMR=0.118|CATSM-Malware Agent=0.024|CATSM=0.025|CRSL=0.008|CATRS-Prioritization Agent=0
                              .007|CATRS-Transport Rule Agent=0.018|CATRS-Index Routing Agent=0.014|CATRS=0.040|CATRT=0.001
                              |CAT=0.078|QDE=886.397|SMS=1.692
    MessageLatency          : 00:14:48.3880000
    MessageLatencyType      : EndToEnd
    EventData               : {[E2ELatency, 888.388], [ExternalSendLatency, 0.266], [Microsoft.Exchange.Transport.MailRecip
                              ient.RequiredTlsAuthLevel, DomainValidation], [Microsoft.Exchange.Transport.MailRecipient.Eff
                              ectiveTlsAuthLevel, DomainValidation], [DeliveryPriority, Normal], [AccountForest, [OUR_DOMAIN]]}

    Best and thanks in advance

    Martin

    Tuesday, August 29, 2017 6:01 AM

All replies

  • What do the message headers of a delayed message say?

    What kind of "relaying" are you doing?  Is this a message from on-premises to an Office 365 mailbox, or to an Internet mailbox via Office 365 (EOP)?


    Ed Crowley MVP "There are seldom good technological solutions to behavioral problems."
    Celebrating 20 years of providing Exchange peer support!

    Tuesday, August 29, 2017 8:50 PM
    Moderator
  • Hi,

    Thanks for contacting our forum.

    From the message tracking log we can see as below:

    ---------------------------------------------------------------------------------------

    MessageInfo             : 2017-08-24T07:06:52.487Z;SRV=[OUR_MAILSERVER]:TOTAL-FE=0.062|SMRPI-FrontendProxyAgent=0.006|SMRP                           I=0.006|SMR=0.009|SMS=0.062;SRV=[OUR_MAILSERVER]:TOTAL-HUB=888.325|SMRDE=0.002|SMRCL=0.114|SMRC=                           0.115|SMR=0.118|CATSM-Malware Agent=0.024|CATSM=0.025|CRSL=0.008|CATRS-Prioritization Agent=0                           .007|CATRS-Transport Rule Agent=0.018|CATRS-Index Routing Agent=0.014|CATRS=0.040|CATRT=0.001                           |CAT=0.078|QDE=886.397|SMS=1.692 MessageLatency          : 00:14:48.3880000

    --------------------------------------------------------------------------------------

    We can see the highlightpart QDE=886.397, it means queued for delivery. Seems cost too much time.

    Can you see any errors in the queues? You can check with the command get-queue | fl name, *last*

    Then you can check the parameter  smtpmaxmessageperconnection of the connector “ Outbound to Office 365”

    You can change it to 200, it’s 20 by default with the command set-sendconnector -identity<name> - smtpmaxmessageperconnection 200.

    It’s recommended to check if any performance related events for example 1500x, and check the performance log on the server path as below:

    Hope it helps.


    Regards,

    Jason Chao


    Please remember to mark the replies as answers if they help.
    If you have feedback for TechNet Subscriber Support, contact tnmff@microsoft.com.

    Thursday, August 31, 2017 7:12 AM
    Moderator
  • Hi,

    indeed the queue has some errors, but the below seem quite normal to me.

    The max session per connection is indeed 20 and it might be a good idea to increase, thx.

    The performance counter for disk read/write was actually quite low between 5 and 20

    So  I put my hope on the parameter, thx again for the help. I will update this when I have results.

    Best

    Martin

    LastError     :
    LastRetryTime : 31-10-2017 10:28:02

    LastError     :
    LastRetryTime : 31-10-2017 10:26:16

    LastError     :
    LastRetryTime : 31-10-2017 10:26:31

    LastError     : [{LRT=31-10-2017 10:26:56};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "421 4.4.2 Connection dropped due to SocketError." Attempted failover to alternate host, but t
                    hat did not succeed. Either there are no alternate hosts, or delivery failed to all alternate hosts. Th
                    e last endpoint attempted was 68.142.230.234:25};{FQDN=rtn1.groups.a03.yahoodns.net};{IP=68.142.230.234
                    }]
    LastRetryTime : 31-10-2017 10:26:56

    LastError     : [{LRT=31-10-2017 07:03:19};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 66.33.205.150:25};{FQDN=ds9159.dreamservers.com};{I
                    P=66.33.205.150}]
    LastRetryTime : 31-10-2017 10:27:12

    LastError     :
    LastRetryTime : 31-10-2017 10:26:39

    LastError     : [{LRT=31-10-2017 10:19:50};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 195.154.21.53:25};{FQDN=091690.com};{IP=195.154.21.
                    53}]
    LastRetryTime : 31-10-2017 10:19:50

    LastError     : [{LRT=31-10-2017 09:55:00};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 103.84.174.76:25};{FQDN=emailsendings.site};{IP=103
                    .84.174.76}]
    LastRetryTime : 31-10-2017 10:27:27

    LastError     : 451 4.4.0 DNS query failed. The error was: DNS query failed with error ErrorRetry
    LastRetryTime : 31-10-2017 10:26:17

    LastError     : [{LRT=31-10-2017 10:23:00};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 216.58.211.133:25};{FQDN=gmail.dk};{IP=216.58.211.1
                    33}]
    LastRetryTime : 31-10-2017 10:23:00

    LastError     : [{LRT=31-10-2017 10:22:24};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 63.249.140.127:25};{FQDN=nwatalent.com};{IP=63.249.
                    140.127}]
    LastRetryTime : 31-10-2017 10:22:24

    LastError     : [{LRT=31-10-2017 10:18:37};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 134.119.187.11:25};{FQDN=fglww.com};{IP=134.119.187
                    .11}]
    LastRetryTime : 31-10-2017 10:18:37

    LastError     : [{LRT=31-10-2017 10:18:09};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 37.18.145.120:25};{FQDN=ryanairemail.com};{IP=37.18
                    .145.120}]
    LastRetryTime : 31-10-2017 10:18:09

    LastError     : [{LRT=31-10-2017 04:21:00};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "Failed to connect. Winsock error code: 10060, Win32 error code: 10060." Attempted failover to
                     alternate host, but that did not succeed. Either there are no alternate hosts, or delivery failed to a
                    ll alternate hosts. The last endpoint attempted was 77.79.244.245:25};{FQDN=mikea-tychy.pl};{IP=77.79.2
                    44.245}]
    LastRetryTime : 31-10-2017 10:27:02

    LastError     : [{LRT=31-10-2017 10:22:37};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "421 4.4.2 Connection dropped due to SocketError." Attempted failover to alternate host, but t
                    hat did not succeed. Either there are no alternate hosts, or delivery failed to all alternate hosts. Th
                    e last endpoint attempted was 85.233.160.15:25};{FQDN=mx1.reg365.net};{IP=85.233.160.15}]
    LastRetryTime : 31-10-2017 10:22:37

    LastError     : [{LRT=31-10-2017 06:59:56};{LED=441 4.4.1 Error encountered while communicating with primary target IP
                    address: "421 4.4.2 Connection dropped due to TimedOut." Attempted failover to alternate host, but that
                     did not succeed. Either there are no alternate hosts, or delivery failed to all alternate hosts. The l
                    ast endpoint attempted was 212.237.0.31:25};{FQDN=mail.sanstp.tk};{IP=212.237.0.31}]
    LastRetryTime : 31-10-2017 10:27:52

    LastError     :
    LastRetryTime : 31-10-2017 10:27:32

    LastError     :

    Tuesday, October 31, 2017 9:49 AM