Ask a Question

Long pause after sending email

0 votes
by (160 points) 

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 (150k points)
selected by
 
Best answer

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

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 (150k 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 (150k 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 (150k points)
Thanks! Any updates on this would be greatly appreciated.
...