SmtpClient DisconnectAsync may not exit with an improperly closed remote connection

[tvalenta]

Describe the bug
DisconnectAsync can block when packets to a previously functioning session are suddenly dropped. Despite many attempts, I'm unable to get a cancellation token to end the task by setting a timer with CancelAfter.

I have a process which terminates a client session as such:

      var client = new SmtpClient ();   
     .... mail processing here...
     // Send and close
      await client.SendAsync(mimeMessage).ConfigureAwait(false);
      await client.DisconnectAsync(true).ConfigureAwait(false);

Occasionally, this job will hang -- typically always while connecting to an office365.com MTA. I'm unable to reproduce the behavior in production, and resorted to creating an artificial experience with packet filtering on a FreeBSD-based mail server. When dropping packets from the client just prior to the invocation of DisconnectAsync, my client session never ends. I attempted to rectify by passing a Cancellation Token to DisconnectAsync, but the connection continued to hang indefinitely. Calling instead Disconnect(true), it appears the session will close when the stream timeout is reached. (i.e. to whatever value I've set client.Timeout)

To Reproduce
Steps to reproduce the behavior:

1. Create a new SmtpClient connection to a remote mail server.
2. Prior to calling DisconnectAsync(), sleep for 10 seconds
3. While MailKit SMTP client process sleeps, use a firewall to drop packets from the client to the mail server.
   • For my tests, I used the FreeBSD packet filtering abilities, but I could have used any intermediate firewall. e.g.
   • sudo ipfw add 1000 drop ip from me to <client IP address> src-port 25
4. See session not close

Expected behavior
Expected would be the session to close after the default 120 second timeout, or allow a cancellation token to abort the task.

Screenshots
If applicable, add screenshots to help explain your problem.

Desktop (please complete the following information):

• OS: MacOS Mojave

Additional context
Add any other context about the problem here.

[jstedfast]

Are you saying you switched from DisconnectAsync(true) to Disconnect (true)? Or DisconnectAsync (false) to DisconnectAsync (true)?

[tvalenta]

I switched from DisconnectAsync(true) to Disconnect(true).

[jstedfast]

I can't actually test your scenario because I do not have a system where I can easily use firewall commands such as ipfw.

Can you test the above fix?

[tvalenta]

Is there a test build that I can reference in my project, or do I need to build from the Github sources?

[jstedfast]

https://dev.azure.com/jestedfa/_apis/resources/Containers/780959?itemPath=MailKit-2.1.3.3%2FMailKit.2.1.3.3.nupkg

[tvalenta]

My login to live.com wasn't working, but I'd built a local copy. (Note - I'm running on MacOS with netcoreapp2.1. I failed to mention this earlier). This is what I've observed:

1. Calling Disconnect with CTS token

   Thread.Sleep(5000);
   CancellationTokenSource cts = new CancellationTokenSource(); 
   cts.CancelAfter(TimeSpan.FromSeconds(10));
   client.Disconnect(true,cts.Token); 
   

   • this cancels after the Token expires. In the following wireshark output, Thread.Sleep occurred at line 21. Line 22 starts Disconnect, and 10 seconds later the socket is closed. (Local connection goes into FIN_WAIT_1 as would be expected). I tried to catch the TaskCanceledException so I could log something being amiss, but I see where it's swallowed by OperationCanceledException in DisconnectAsync.

   20   1.567275 192.168.2.32 → 192.168.2.25 SMTP 122 S: 250 2.0.0 x2BK2anR089726 Message accepted for delivery
   21   1.567335 192.168.2.25 → 192.168.2.32 TCP 66 51976 → 25 [ACK] Seq=279 Ack=484 Win=131264 Len=0 TSval=2228714155 TSecr=2484318041
   22   6.577782 192.168.2.25 → 192.168.2.32 SMTP 72 C: QUIT
   23   7.047115 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228719609 TSecr=2484318041
   24   7.562430 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228720122 TSecr=2484318041
   25   8.388257 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228720946 TSecr=2484318041
   26   9.842146 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228722394 TSecr=2484318041
   27  12.563808 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228725090 TSecr=2484318041
   28  16.669305 192.168.2.25 → 192.168.2.32 TCP 66 51976 → 25 [FIN, ACK] Seq=285 Ack=484 Win=131264 Len=0 TSval=2228729183 TSecr=2484318041
   29  17.772403 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [FIN, PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228730283 TSecr=2484318041
   30  26.928900 192.168.2.25 → 192.168.2.32 TCP 72 [TCP Retransmission] 51976 → 25 [FIN, PSH, ACK] Seq=279 Ack=484 Win=131264 Len=6 TSval=2228739411 TSecr=2484318041
   

2. Calling Disconnect(true,cts.Token) and also setting client.Timeout

   Thread.Sleep(5000);
   client.Timeout = 5000;
   CancellationTokenSource cts = new CancellationTokenSource(); 
   cts.CancelAfter(TimeSpan.FromSeconds(10));
   client.Disconnect(true,cts.Token); 
   

   • Client disconnects after 10 seconds (token expiration reached). The client.Timeout value doesn't end things earlier.
3. Calling Disconnect(true) and also setting client.Timeout to a shorter value.

   Thread.Sleep(5000);
   client.Timeout = 5000;
   CancellationTokenSource cts = new CancellationTokenSource(); 
   cts.CancelAfter(TimeSpan.FromSeconds(10));
   client.Disconnect(true); 
   

   • Client disconnects after 5 seconds.
4. Calling DisconnectAsync(true,cts.Token)

     await client.DisconnectAsync(true,cts.Token).ConfigureAwait(false);
   

   • Connection closes after 105-110 seconds. CancellationToken does not appear to matter.
5. Calling DisconnectAsync(true)

     await client.DisconnectAsync(true).ConfigureAwait(false);
   

   • Connection closes after 105-110 seconds. Same behavior as with the cancellation token.

With any of these, it appears I should no longer risk a connection permanently blocking. I don't understand why DisconnectAsync waits the 105-110 seconds before returning. Can you illuminate me?

[jstedfast]

I can explain 2:

In the non-async case, if the cancellation token is cancellable, then the client polls the socket waiting for it to be ready to accept a write while also listening for a cancel event from the cancellation token. Because the socket is not actually being used to read or write, the Timeout property is never used.

And 3:

Since the token isn't cancellable (no token used), it immediately goes to write the data to the socket which then expires after the timeout.

4 and 5:

Why doesn't that work for async? I have no idea. It should unless the NetworkStream/SslStream don't respect the Timeout property for their WriteAsync method.

[jstedfast]

The change I made forces the disconnect of the socket as soon as the token is cancelled, so I don't understand how that would not cause NetworkStream/SslStream.WriteAsync() to not immediately get an IOException or SocketException or something, which should abort the WriteAsync.

[jstedfast]

BTW, I now have a MyGet nuget feed that you can use to test this: https://www.myget.org/feed/mimekit/package/nuget/MailKit

Would you mind checking to see if the latest builds work for you?

[tvalenta]

This build worked for me. As before, I'm unable to get DisconnectAsync to follow the CancellationToken.

await client.DisconnectAsync(true,cts.Token).ConfigureAwait(false);
await client.DisconnectAsync(true).ConfigureAwait(false);
await client.DisconnectAsync(true);

The following all behaved identically for me -- returning after 105 seconds, regardless of the cancellation token. This would no longer block on the occasional network failure, but for now I've chosenclient.Disconnect(true,cts.Token); since I a) can control the timeout value and b) understand what triggers it.

Thank you for the help!

[jstedfast]

I just committed another potential fix that may improve things which will show up in the myget feed as soon as CI finishes building it. Could you test that as well? I want to try and make it so that cancelling the cancellationToken is immediate.

[tvalenta]

Same behavior. Could it be related to the topic of this thread? https://stackoverflow.com/questions/12421989/networkstream-readasync-with-a-cancellation-token-never-cancels