Ask a Question

Long pause after sending email

0 votes
by (160 points)

I am trying to figure out a longstanding issue we've had with sending emails. We are using an older version of the dlls (2011-03-09) but the problem is present when I use the latest trial versions available on the site.

Whenever we send the email, there is a long pause before the .send() function returns. We receive the sent email on our phones/email clients within 3-5 seconds of the send() command being called, yet it takes another 20-30 seconds before the function returns.

I attempted to use the FileLogWriter to record any debug info, but the log file contains nothing but the first two lines about "opening the log file" and "using filelogwriter version..."

Any idea what could be causing this delay? Maybe its a setting we can change on our exchange server? A command we can change in the code?

Using client As New Rebex.Net.Smtp()
    'accept any certificate, and add our.mailserver.com as a valid response name
    Dim par As New TlsParameters()
    par.CertificateRequestHandler = CertificateRequestHandler.NoCertificate
    par.CommonName = "our.mailserver.com"

    client.Connect("191.168.1.2", 587, par, SmtpSecurity.Explicit)
    client.Login("username", "password")


    Dim email As New MailMessage
    email.From = New MailAddress("doNotReply@our.mailserver.com")

    ...add the email contents...            


    client.Send(email)
    client.Disconnect()
End Using
Applies to: Rebex Secure Mail

1 Answer

+1 vote
by (148k points)
selected by
 
Best answer

The last step of the process of sending a message is waiting for the server to confirm that it accepted the message for delivery, and if it took the server 30 seconds to acknowledge the message, the Send method would wait as well.

A bit of searching revealed that people have actually encountered a similar issue with Exchange server and SMTP (log included):

Unfortunately, they have not found (or shared) a solution.

Also, we currently don't know for sure whether you encountered the same issue because we don't have the communication log... Could you please try using FileLogWriter again by adding this line before your client.Connect call?

client.LogWriter = New FileLogWriter("log.txt", LogLevel.Debug)

I tried this with the old version of Rebex Secure Mail and it worked, so hopefully it would work for you as well.

by (160 points)
edited by
Here is the contents of the log file (by the way I mess up before and only put the logfilewriter command before the send() function, I didn't realize it needed to go before the connect() function) :

2016-05-27 08:03:25.587 Opening log file.
2016-05-27 08:03:25.590 INFO Smtp(1) Info: Connecting to <our IP Address>:587 using Smtp 1.0.4086.0.
2016-05-27 08:03:25.605 DEBUG Smtp(1) Info: Connection succeeded.
2016-05-27 08:03:25.608 INFO Smtp(1) Response: 220 our.Mailserver.com Microsoft ESMTP MAIL Service ready at Fri, 27 May 2016 08:03:26 -0400
2016-05-27 08:03:25.611 INFO Smtp(1) Command: EHLO rfp219
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-our.mailserver.com Hello [10.2.2.18]
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-SIZE 36700160
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-PIPELINING
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-DSN
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-ENHANCEDSTATUSCODES
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-STARTTLS
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-AUTH GSSAPI NTLM
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-8BITMIME
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250-BINARYMIME
2016-05-27 08:03:25.613 INFO Smtp(1) Response: 250 CHUNKING
2016-05-27 08:03:25.614 INFO Smtp(1) Command: STARTTLS
2016-05-27 08:03:25.616 INFO Smtp(1) Response: 220 2.0.0 SMTP server ready
2016-05-27 08:03:25.616 DEBUG Smtp(1) Info: Upgrading connection to TLS/SSL.
2016-05-27 08:03:25.630 INFO Smtp(1) TLS: State StateChange:Negotiating
2016-05-27 08:03:25.630 DEBUG Smtp(1) TLS: HandshakeMessage:ClientHello was sent.
2016-05-27 08:03:25.638 DEBUG Smtp(1) TLS: HandshakeMessage:ServerHello was received.
2016-05-27 08:03:25.645 DEBUG Smtp(1) TLS: HandshakeMessage:Certificate was received.
2016-05-27 08:03:25.645 DEBUG Smtp(1) TLS: HandshakeMessage:ServerHelloDone was received.
2016-05-27 08:03:25.648 DEBUG Smtp(1) TLS: Verifying server certificate ('CN=our.mailserver.com, OU=IT, O=CompanyNAme, L=city, S=state, C=US').
2016-05-27 08:03:25.672 DEBUG Smtp(1) TLS: Certificate verification result: Accept
2016-05-27 08:03:25.756 DEBUG Smtp(1) TLS: HandshakeMessage:ClientKeyExchange was sent.
2016-05-27 08:03:25.764 DEBUG Smtp(1) TLS: CipherSpec:ChangeCipherSpec was sent.
2016-05-27 08:03:25.765 DEBUG Smtp(1) TLS: HandshakeMessage:Finished was sent.
2016-05-27 08:03:25.811 DEBUG Smtp(1) TLS: CipherSpec:ChangeCipherSpec was received.
2016-05-27 08:03:25.812 DEBUG Smtp(1) TLS: HandshakeMessage:Finished was received.
2016-05-27 08:03:25.813 INFO Smtp(1) TLS: State StateChange:Secured
2016-05-27 08:03:25.815 INFO Smtp(1) TLS: Connection secured using cipher: TLS 1.0, RSA, 256bit AES in CBC mode, SHA1
2016-05-27 08:03:25.816 DEBUG Smtp(1) TLS: Session ID:
    20-3F-00-00-A1-BA-A8-8C-43-98-4B-49-B3-68-00-AD-8A-7A-68-FC-66-71-C5-93
    FD-5C-0E-1E-05-23-83-DF
2016-05-27 08:03:25.816 DEBUG Smtp(1) Info: Connection upgraded to TLS/SSL.
2016-05-27 08:03:25.817 INFO Smtp(1) Command: EHLO rlp569
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-our.mailserver.com Hello [10.2.2.18]
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-SIZE 36700160
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-PIPELINING
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-DSN
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-ENHANCEDSTATUSCODES
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-AUTH GSSAPI NTLM LOGIN
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-8BITMIME
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250-BINARYMIME
2016-05-27 08:03:25.820 INFO Smtp(1) Response: 250 CHUNKING
2016-05-27 08:03:25.831 INFO Smtp(1) Command: AUTH LOGIN
2016-05-27 08:03:25.832 INFO Smtp(1) Response: 334 VXNlcm5hbWU6
2016-05-27 08:03:25.832 INFO Smtp(1) Command: a2lkc3lzdGVt
2016-05-27 08:03:25.833 INFO Smtp(1) Response: 334 UGFzc3dvcmQ6
2016-05-27 08:03:25.833 INFO Smtp(1) Command:                     
2016-05-27 08:03:25.851 INFO Smtp(1) Response: 235 2.7.0 Authentication successful
2016-05-27 08:03:25.916 INFO Smtp(1) Command: MAIL FROM:<doNotReply@our.mailserver.com> SIZE=626
2016-05-27 08:03:25.918 INFO Smtp(1) Response: 250 2.1.0 Sender OK
2016-05-27 08:03:25.919 INFO Smtp(1) Command: RCPT TO:<xcvsdf@our.mailserver.com> NOTIFY=FAILURE
2016-05-27 08:03:25.920 INFO Smtp(1) Response: 250 2.1.5 Recipient OK
2016-05-27 08:03:25.920 INFO Smtp(1) Command: RCPT TO:<bsdfbb@our.mailserver.com> NOTIFY=FAILURE
2016-05-27 08:03:25.922 INFO Smtp(1) Command: RCPT TO:<techSupport@our.mailserver.com> NOTIFY=FAILURE
2016-05-27 08:03:25.922 INFO Smtp(1) Response: 250 2.1.5 Recipient OK
2016-05-27 08:03:25.922 INFO Smtp(1) Command: RCPT TO:<sdfsdfsdfwet@our.mailserver.com> NOTIFY=FAILURE
2016-05-27 08:03:25.923 INFO Smtp(1) Response: 250 2.1.5 Recipient OK
2016-05-27 08:03:25.925 INFO Smtp(1) Response: 250 2.1.5 Recipient OK
2016-05-27 08:03:25.926 INFO Smtp(1) Command: BDAT 626 LAST
2016-05-27 08:04:00.700 INFO Smtp(1) Response: 250 2.6.0 <d5ff9af60ade6748829b72178004d353@nhy654> [InternalId=301483] Queued mail for delivery
2016-05-27 08:04:00.700 INFO Smtp(1) Command: QUIT
2016-05-27 08:04:00.701 DEBUG Smtp(1) TLS: Closing TLS socket.
2016-05-27 08:04:00.702 INFO Smtp(1) TLS: Alert Alert:Alert was sent.
2016-05-27 08:04:00.702 INFO Smtp(1) TLS: State StateChange:Closed


Looks pretty close to the log you linked. What do you think?
by (148k points)
Yes, this looks pretty close - you are running over TLS and using the `CHUNKING` extension (which is why there is a `BDAT` command instead of `DATA`), but in both cases, the delay occurs after the message has been transmitted and the client is waiting for the server response.
by (148k points)
I'm not very familiar with Exchange, but it looks like there is an option called `MaxAcknowledgementDelay` that might be partly responsible for this - see https://mikecrowley.wordpress.com/2010/07/24/delayed-smtp-acknowledgement/ for more information.
by (160 points)
Ok, thanks. It definitely looks like this is an issue with Exchange. I'll have to talk with our IT department and see if they are willing to adjust some settings for me. Not sure how long that will take. Anyway if any of the suggestions from the 2 links you have posted end up working I will update this thread with our findings.
by (148k points)
Thanks! Any updates on this would be greatly appreciated.
...