Improve exception handling in SocketConnection (#2844)

- Avoid race where a connection reset observed by both DoSend() and DoReceive()
  resulted in a ConnectionAbortedException being thrown from the input Pipe
  instead of a ConnectionResetException.
This commit is contained in:
Stephen Halter 2018-08-23 16:59:02 -07:00 committed by GitHub
parent 68a0863524
commit e5a1101239
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 86 additions and 75 deletions

View File

@ -30,10 +30,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal
// ConnectionWriteCallback: Reserved: 12 // ConnectionWriteCallback: Reserved: 12
private static readonly Action<ILogger, string, Exception> _connectionError = private static readonly Action<ILogger, string, Exception> _connectionError =
LoggerMessage.Define<string>(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error."); LoggerMessage.Define<string>(LogLevel.Information, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error.");
private static readonly Action<ILogger, string, Exception> _connectionReset = private static readonly Action<ILogger, string, Exception> _connectionReset =
LoggerMessage.Define<string>(LogLevel.Debug, 19, @"Connection id ""{ConnectionId}"" reset."); LoggerMessage.Define<string>(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset.");
private static readonly Action<ILogger, string, Exception> _connectionAborted = private static readonly Action<ILogger, string, Exception> _connectionAborted =
LoggerMessage.Define<string>(LogLevel.Debug, new EventId(20, nameof(ConnectionAborted)), @"Connection id ""{ConnectionId}"" aborted."); LoggerMessage.Define<string>(LogLevel.Debug, new EventId(20, nameof(ConnectionAborted)), @"Connection id ""{ConnectionId}"" aborted.");

View File

@ -0,0 +1,6 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System.Runtime.CompilerServices;
[assembly: InternalsVisibleTo("Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100f33a29044fa9d740c9b3213a93e57c84b472c84e0b8a0e1ae48e67a9f8f6de9d5f7f3d52ac23e48ac51801f1dc950abe901da34d2a9e3baadb141a17c77ef3c565dd5ee5054b91cf63bb3c6ab83f72ab3aafe93d0fc3c2348b764fafb0b1c0733de51459aeab46580384bf9d74c4e28164b7cde247f891ba07891c9d872ad2bb")]

View File

@ -4,7 +4,6 @@
using System; using System;
using System.Buffers; using System.Buffers;
using System.Diagnostics; using System.Diagnostics;
using System.IO;
using System.IO.Pipelines; using System.IO.Pipelines;
using System.Net; using System.Net;
using System.Net.Sockets; using System.Net.Sockets;
@ -31,8 +30,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
private readonly CancellationTokenSource _connectionClosedTokenSource = new CancellationTokenSource(); private readonly CancellationTokenSource _connectionClosedTokenSource = new CancellationTokenSource();
private readonly object _shutdownLock = new object(); private readonly object _shutdownLock = new object();
private volatile bool _aborted; private volatile bool _socketDisposed;
private volatile ConnectionAbortedException _abortReason; private volatile Exception _shutdownReason;
private long _totalBytesWritten; private long _totalBytesWritten;
internal SocketConnection(Socket socket, MemoryPool<byte> memoryPool, PipeScheduler scheduler, ISocketsTrace trace) internal SocketConnection(Socket socket, MemoryPool<byte> memoryPool, PipeScheduler scheduler, ISocketsTrace trace)
@ -97,11 +96,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
{ {
_trace.ConnectionAborted(ConnectionId); _trace.ConnectionAborted(ConnectionId);
_abortReason = abortReason;
Output.CancelPendingRead();
// Try to gracefully close the socket to match libuv behavior. // Try to gracefully close the socket to match libuv behavior.
Shutdown(); Shutdown(abortReason);
// Cancel ProcessSends loop after calling shutdown to ensure the correct _shutdownReason gets set.
Output.CancelPendingRead();
} }
// Only called after connection middleware is complete which means the ConnectionClosed token has fired. // Only called after connection middleware is complete which means the ConnectionClosed token has fired.
@ -121,46 +120,39 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
} }
catch (SocketException ex) when (IsConnectionResetError(ex.SocketErrorCode)) catch (SocketException ex) when (IsConnectionResetError(ex.SocketErrorCode))
{ {
// A connection reset can be reported as SocketError.ConnectionAborted on Windows // This could be ignored if _shutdownReason is already set.
if (!_aborted) error = new ConnectionResetException(ex.Message, ex);
// There's still a small chance that both DoReceive() and DoSend() can log the same connection reset.
// Both logs will have the same ConnectionId. I don't think it's worthwhile to lock just to avoid this.
if (!_socketDisposed)
{ {
error = new ConnectionResetException(ex.Message, ex);
_trace.ConnectionReset(ConnectionId); _trace.ConnectionReset(ConnectionId);
} }
} }
catch (SocketException ex) when (IsConnectionAbortError(ex.SocketErrorCode)) catch (Exception ex)
{ when ((ex is SocketException socketEx && IsConnectionAbortError(socketEx.SocketErrorCode)) ||
if (!_aborted) ex is ObjectDisposedException)
{
// Calling Dispose after ReceiveAsync can cause an "InvalidArgument" error on *nix.
_trace.ConnectionError(ConnectionId, error);
}
}
catch (ObjectDisposedException)
{
if (!_aborted)
{
_trace.ConnectionError(ConnectionId, error);
}
}
catch (IOException ex)
{ {
// This exception should always be ignored because _shutdownReason should be set.
error = ex; error = ex;
_trace.ConnectionError(ConnectionId, error);
if (!_socketDisposed)
{
// This is unexpected if the socket hasn't been disposed yet.
_trace.ConnectionError(ConnectionId, error);
}
} }
catch (Exception ex) catch (Exception ex)
{ {
error = new IOException(ex.Message, ex); // This is unexpected.
error = ex;
_trace.ConnectionError(ConnectionId, error); _trace.ConnectionError(ConnectionId, error);
} }
finally finally
{ {
if (_aborted) // If Shutdown() has already bee called, assume that was the reason ProcessReceives() exited.
{ Input.Complete(_shutdownReason ?? error);
error = error ?? _abortReason ?? new ConnectionAbortedException();
}
Input.Complete(error);
} }
} }
@ -215,7 +207,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
private async Task DoSend() private async Task DoSend()
{ {
Exception error = null; Exception shutdownReason = null;
Exception unexpectedError = null;
try try
{ {
@ -223,34 +216,28 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
} }
catch (SocketException ex) when (IsConnectionResetError(ex.SocketErrorCode)) catch (SocketException ex) when (IsConnectionResetError(ex.SocketErrorCode))
{ {
// A connection reset can be reported as SocketError.ConnectionAborted on Windows shutdownReason = new ConnectionResetException(ex.Message, ex);;
error = null;
_trace.ConnectionReset(ConnectionId); _trace.ConnectionReset(ConnectionId);
} }
catch (SocketException ex) when (IsConnectionAbortError(ex.SocketErrorCode)) catch (Exception ex)
when ((ex is SocketException socketEx && IsConnectionAbortError(socketEx.SocketErrorCode)) ||
ex is ObjectDisposedException)
{ {
error = null; // This should always be ignored since Shutdown() must have already been called by Abort().
} shutdownReason = ex;
catch (ObjectDisposedException)
{
error = null;
}
catch (IOException ex)
{
error = ex;
_trace.ConnectionError(ConnectionId, error);
} }
catch (Exception ex) catch (Exception ex)
{ {
error = new IOException(ex.Message, ex); shutdownReason = ex;
_trace.ConnectionError(ConnectionId, error); unexpectedError = ex;
_trace.ConnectionError(ConnectionId, unexpectedError);
} }
finally finally
{ {
Shutdown(); Shutdown(shutdownReason);
// Complete the output after disposing the socket // Complete the output after disposing the socket
Output.Complete(error); Output.Complete(unexpectedError);
// Cancel any pending flushes so that the input loop is un-paused // Cancel any pending flushes so that the input loop is un-paused
Input.CancelPendingFlush(); Input.CancelPendingFlush();
@ -290,30 +277,38 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
} }
} }
private void Shutdown() private void Shutdown(Exception shutdownReason)
{ {
lock (_shutdownLock) lock (_shutdownLock)
{ {
if (!_aborted) if (_socketDisposed)
{ {
// Make sure to close the connection only after the _aborted flag is set. return;
// Without this, the RequestsCanBeAbortedMidRead test will sometimes fail when
// a BadHttpRequestException is thrown instead of a TaskCanceledException.
_aborted = true;
_trace.ConnectionWriteFin(ConnectionId);
try
{
// Try to gracefully close the socket even for aborts to match libuv behavior.
_socket.Shutdown(SocketShutdown.Both);
}
catch
{
// Ignore any errors from Socket.Shutdown since we're tearing down the connection anyway.
}
_socket.Dispose();
} }
// Make sure to close the connection only after the _aborted flag is set.
// Without this, the RequestsCanBeAbortedMidRead test will sometimes fail when
// a BadHttpRequestException is thrown instead of a TaskCanceledException.
_socketDisposed = true;
// shutdownReason should only be null if the output was completed gracefully, so no one should ever
// ever observe the nondescript ConnectionAbortedException except for connection middleware attempting
// to half close the connection which is currently unsupported.
_shutdownReason = shutdownReason ?? new ConnectionAbortedException();
_trace.ConnectionWriteFin(ConnectionId);
try
{
// Try to gracefully close the socket even for aborts to match libuv behavior.
_socket.Shutdown(SocketShutdown.Both);
}
catch
{
// Ignore any errors from Socket.Shutdown() since we're tearing down the connection anyway.
}
_socket.Dispose();
} }
} }
@ -331,6 +326,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
private static bool IsConnectionResetError(SocketError errorCode) private static bool IsConnectionResetError(SocketError errorCode)
{ {
// A connection reset can be reported as SocketError.ConnectionAborted on Windows.
return errorCode == SocketError.ConnectionReset || return errorCode == SocketError.ConnectionReset ||
errorCode == SocketError.ConnectionAborted || errorCode == SocketError.ConnectionAborted ||
errorCode == SocketError.Shutdown; errorCode == SocketError.Shutdown;
@ -338,6 +334,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal
private static bool IsConnectionAbortError(SocketError errorCode) private static bool IsConnectionAbortError(SocketError errorCode)
{ {
// Calling Dispose after ReceiveAsync can cause an "InvalidArgument" error on *nix.
return errorCode == SocketError.OperationAborted || return errorCode == SocketError.OperationAborted ||
errorCode == SocketError.Interrupted || errorCode == SocketError.Interrupted ||
errorCode == SocketError.InvalidArgument; errorCode == SocketError.InvalidArgument;

View File

@ -396,7 +396,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests
// Cause all writes to fail // Cause all writes to fail
while (completeQueue.TryDequeue(out var triggerNextCompleted)) while (completeQueue.TryDequeue(out var triggerNextCompleted))
{ {
await _libuvThread.PostAsync(cb => cb(-1), triggerNextCompleted); await _libuvThread.PostAsync(cb => cb(LibuvConstants.ECONNRESET.Value), triggerNextCompleted);
} }
// Second task is now completed // Second task is now completed

View File

@ -65,10 +65,18 @@ namespace Microsoft.AspNetCore.Testing
((eventId.Id == 16 && eventId.Name == nameof(KestrelTrace.NotAllConnectionsClosedGracefully)) || ((eventId.Id == 16 && eventId.Name == nameof(KestrelTrace.NotAllConnectionsClosedGracefully)) ||
(eventId.Id == 21 && eventId.Name == nameof(KestrelTrace.NotAllConnectionsAborted)))) (eventId.Id == 21 && eventId.Name == nameof(KestrelTrace.NotAllConnectionsAborted))))
{ {
var log = $"Log {logLevel}[{eventId}]: {formatter(state, exception)} {exception?.Message}"; var log = $"Log {logLevel}[{eventId}]: {formatter(state, exception)} {exception}";
throw new Exception($"Shutdown failure. {log}"); throw new Exception($"Shutdown failure. {log}");
} }
// We don't use nameof here because this is logged by the transports and we don't know which one is
// referenced in this shared source file.
if (eventId.Id == 14 && eventId.Name == "ConnectionError")
{
var log = $"Log {logLevel}[{eventId}]: {formatter(state, exception)} {exception}";
throw new Exception($"Unexpected connection error. {log}");
}
Messages.Enqueue(new LogMessage Messages.Enqueue(new LogMessage
{ {
LogLevel = logLevel, LogLevel = logLevel,