-
Notifications
You must be signed in to change notification settings - Fork 10.4k
backport 8.0 - http.sys accept loop - mitigate against break due to possible conflicting IO callbacks #54437
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Merged
Merged
Changes from all commits
Commits
Show all changes
4 commits
Select commit
Hold shift + click to select a range
16416b1
investigate #54251 (more details will be in PR)
mgravell 42cc025
make log text consistent
mgravell 8177116
upgrade log to "critical" on the actual state error
mgravell 28706b9
- capture whether it is the managed vs unmanaged code-path that is gl…
mgravell File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,26 @@ | ||
// Licensed to the .NET Foundation under one or more agreements. | ||
// The .NET Foundation licenses this file to you under the MIT license. | ||
|
||
using Microsoft.Extensions.Logging; | ||
|
||
namespace Microsoft.AspNetCore.Server.HttpSys; | ||
|
||
internal partial class AsyncAcceptContext | ||
{ | ||
private static partial class Log | ||
{ | ||
[LoggerMessage(LoggerEventIds.AcceptSetResultFailed, LogLevel.Error, "Error attempting to set 'accept' outcome", EventName = "AcceptSetResultFailed")] | ||
public static partial void AcceptSetResultFailed(ILogger logger, Exception exception); | ||
|
||
// note on "critical": these represent an unexpected IO callback state that needs investigation; see https://github.com/dotnet/aspnetcore/pull/54368/ | ||
|
||
[LoggerMessage(LoggerEventIds.AcceptSetExpectationMismatch, LogLevel.Critical, "Mismatch setting callback expectation - {Value}", EventName = "AcceptSetExpectationMismatch")] | ||
public static partial void AcceptSetExpectationMismatch(ILogger logger, int value); | ||
|
||
[LoggerMessage(LoggerEventIds.AcceptCancelExpectationMismatch, LogLevel.Critical, "Mismatch canceling accept state - {Value}", EventName = "AcceptCancelExpectationMismatch")] | ||
public static partial void AcceptCancelExpectationMismatch(ILogger logger, int value); | ||
|
||
[LoggerMessage(LoggerEventIds.AcceptObserveExpectationMismatch, LogLevel.Critical, "Mismatch observing {Kind} accept callback - {Value}", EventName = "AcceptObserveExpectationMismatch")] | ||
public static partial void AcceptObserveExpectationMismatch(ILogger logger, string kind, int value); | ||
} | ||
} |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change | ||||
---|---|---|---|---|---|---|
|
@@ -4,17 +4,23 @@ | |||||
using System.Diagnostics; | ||||||
using System.Threading.Tasks.Sources; | ||||||
using Microsoft.AspNetCore.HttpSys.Internal; | ||||||
using Microsoft.Extensions.Logging; | ||||||
|
||||||
namespace Microsoft.AspNetCore.Server.HttpSys; | ||||||
|
||||||
internal sealed unsafe class AsyncAcceptContext : IValueTaskSource<RequestContext>, IDisposable | ||||||
internal sealed unsafe partial class AsyncAcceptContext : IValueTaskSource<RequestContext>, IDisposable | ||||||
{ | ||||||
private static readonly IOCompletionCallback IOCallback = IOWaitCallback; | ||||||
private readonly PreAllocatedOverlapped _preallocatedOverlapped; | ||||||
private readonly IRequestContextFactory _requestContextFactory; | ||||||
private readonly ILogger _logger; | ||||||
private int _expectedCompletionCount; | ||||||
|
||||||
private NativeOverlapped* _overlapped; | ||||||
|
||||||
private readonly bool _logExpectationFailures = AppContext.TryGetSwitch( | ||||||
"Microsoft.AspNetCore.Server.HttpSys.LogAcceptExpectationFailure", out var enabled) && enabled; | ||||||
|
||||||
// mutable struct; do not make this readonly | ||||||
private ManualResetValueTaskSourceCore<RequestContext> _mrvts = new() | ||||||
{ | ||||||
|
@@ -24,11 +30,12 @@ internal sealed unsafe class AsyncAcceptContext : IValueTaskSource<RequestContex | |||||
|
||||||
private RequestContext? _requestContext; | ||||||
|
||||||
internal AsyncAcceptContext(HttpSysListener server, IRequestContextFactory requestContextFactory) | ||||||
internal AsyncAcceptContext(HttpSysListener server, IRequestContextFactory requestContextFactory, ILogger logger) | ||||||
{ | ||||||
Server = server; | ||||||
_requestContextFactory = requestContextFactory; | ||||||
_preallocatedOverlapped = new(IOCallback, state: this, pinData: null); | ||||||
_logger = logger; | ||||||
} | ||||||
|
||||||
internal HttpSysListener Server { get; } | ||||||
|
@@ -51,15 +58,16 @@ internal ValueTask<RequestContext> AcceptAsync() | |||||
return new ValueTask<RequestContext>(this, _mrvts.Version); | ||||||
} | ||||||
|
||||||
private void IOCompleted(uint errorCode, uint numBytes) | ||||||
private void IOCompleted(uint errorCode, uint numBytes, bool managed) | ||||||
{ | ||||||
try | ||||||
{ | ||||||
ObserveCompletion(managed); // expectation tracking | ||||||
if (errorCode != UnsafeNclNativeMethods.ErrorCodes.ERROR_SUCCESS && | ||||||
errorCode != UnsafeNclNativeMethods.ErrorCodes.ERROR_MORE_DATA) | ||||||
{ | ||||||
_mrvts.SetException(new HttpSysException((int)errorCode)); | ||||||
return; | ||||||
// (keep all the error handling in one place) | ||||||
throw new HttpSysException((int)errorCode); | ||||||
} | ||||||
|
||||||
Debug.Assert(_requestContext != null); | ||||||
|
@@ -71,7 +79,14 @@ private void IOCompleted(uint errorCode, uint numBytes) | |||||
// we want to reuse the acceptContext object for future accepts. | ||||||
_requestContext = null; | ||||||
|
||||||
_mrvts.SetResult(requestContext); | ||||||
try | ||||||
{ | ||||||
_mrvts.SetResult(requestContext); | ||||||
} | ||||||
catch (Exception ex) | ||||||
{ | ||||||
Log.AcceptSetResultFailed(_logger, ex); | ||||||
} | ||||||
} | ||||||
else | ||||||
{ | ||||||
|
@@ -84,22 +99,69 @@ private void IOCompleted(uint errorCode, uint numBytes) | |||||
if (statusCode != UnsafeNclNativeMethods.ErrorCodes.ERROR_SUCCESS && | ||||||
statusCode != UnsafeNclNativeMethods.ErrorCodes.ERROR_IO_PENDING) | ||||||
{ | ||||||
// someother bad error, possible(?) return values are: | ||||||
// some other bad error, possible(?) return values are: | ||||||
// ERROR_INVALID_HANDLE, ERROR_INSUFFICIENT_BUFFER, ERROR_OPERATION_ABORTED | ||||||
_mrvts.SetException(new HttpSysException((int)statusCode)); | ||||||
// (keep all the error handling in one place) | ||||||
throw new HttpSysException((int)statusCode); | ||||||
} | ||||||
} | ||||||
} | ||||||
catch (Exception exception) | ||||||
{ | ||||||
_mrvts.SetException(exception); | ||||||
try | ||||||
{ | ||||||
_mrvts.SetException(exception); | ||||||
} | ||||||
catch (Exception ex) | ||||||
{ | ||||||
Log.AcceptSetResultFailed(_logger, ex); | ||||||
} | ||||||
} | ||||||
} | ||||||
|
||||||
private static unsafe void IOWaitCallback(uint errorCode, uint numBytes, NativeOverlapped* nativeOverlapped) | ||||||
{ | ||||||
var acceptContext = (AsyncAcceptContext)ThreadPoolBoundHandle.GetNativeOverlappedState(nativeOverlapped)!; | ||||||
acceptContext.IOCompleted(errorCode, numBytes); | ||||||
acceptContext.IOCompleted(errorCode, numBytes, false); | ||||||
} | ||||||
|
||||||
private void SetExpectCompletion() // we anticipate a completion *might* occur | ||||||
{ | ||||||
// note this is intentionally a "reset and check" rather than Increment, so that we don't spam | ||||||
// the logs forever if a glitch occurs | ||||||
var value = Interlocked.Exchange(ref _expectedCompletionCount, 1); // should have been 0 | ||||||
if (value != 0) | ||||||
{ | ||||||
if (_logExpectationFailures) | ||||||
{ | ||||||
Log.AcceptSetExpectationMismatch(_logger, value); | ||||||
} | ||||||
Debug.Assert(false, nameof(SetExpectCompletion)); // fail hard in debug | ||||||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Nit:
Suggested change
|
||||||
} | ||||||
} | ||||||
private void CancelExpectCompletion() // due to error-code etc, we no longer anticipate a completion | ||||||
{ | ||||||
var value = Interlocked.Decrement(ref _expectedCompletionCount); // should have been 1, so now 0 | ||||||
if (value != 0) | ||||||
{ | ||||||
if (_logExpectationFailures) | ||||||
{ | ||||||
Log.AcceptCancelExpectationMismatch(_logger, value); | ||||||
} | ||||||
Debug.Assert(false, nameof(CancelExpectCompletion)); // fail hard in debug | ||||||
} | ||||||
} | ||||||
private void ObserveCompletion(bool managed) // a completion was invoked | ||||||
{ | ||||||
var value = Interlocked.Decrement(ref _expectedCompletionCount); // should have been 1, so now 0 | ||||||
if (value != 0) | ||||||
{ | ||||||
if (_logExpectationFailures) | ||||||
{ | ||||||
Log.AcceptObserveExpectationMismatch(_logger, managed ? "managed" : "unmanaged", value); | ||||||
} | ||||||
Debug.Assert(false, nameof(ObserveCompletion)); // fail hard in debug | ||||||
} | ||||||
} | ||||||
|
||||||
private uint QueueBeginGetContext() | ||||||
|
@@ -112,6 +174,7 @@ private uint QueueBeginGetContext() | |||||
|
||||||
retry = false; | ||||||
uint bytesTransferred = 0; | ||||||
SetExpectCompletion(); // track this *before*, because of timing vs IOCP (could even be effectively synchronous) | ||||||
statusCode = HttpApi.HttpReceiveHttpRequest( | ||||||
Server.RequestQueue.Handle, | ||||||
_requestContext.RequestId, | ||||||
|
@@ -123,35 +186,44 @@ private uint QueueBeginGetContext() | |||||
&bytesTransferred, | ||||||
_overlapped); | ||||||
|
||||||
if ((statusCode == UnsafeNclNativeMethods.ErrorCodes.ERROR_CONNECTION_INVALID | ||||||
|| statusCode == UnsafeNclNativeMethods.ErrorCodes.ERROR_INVALID_PARAMETER) | ||||||
&& _requestContext.RequestId != 0) | ||||||
{ | ||||||
// ERROR_CONNECTION_INVALID: | ||||||
// The client reset the connection between the time we got the MORE_DATA error and when we called HttpReceiveHttpRequest | ||||||
// with the new buffer. We can clear the request id and move on to the next request. | ||||||
// | ||||||
// ERROR_INVALID_PARAMETER: Historical check from HttpListener. | ||||||
// https://referencesource.microsoft.com/#System/net/System/Net/_ListenerAsyncResult.cs,137 | ||||||
// we might get this if somebody stole our RequestId, | ||||||
// set RequestId to 0 and start all over again with the buffer we just allocated | ||||||
// BUGBUG: how can someone steal our request ID? seems really bad and in need of fix. | ||||||
_requestContext.RequestId = 0; | ||||||
retry = true; | ||||||
} | ||||||
else if (statusCode == UnsafeNclNativeMethods.ErrorCodes.ERROR_MORE_DATA) | ||||||
{ | ||||||
// the buffer was not big enough to fit the headers, we need | ||||||
// to read the RequestId returned, allocate a new buffer of the required size | ||||||
// (uint)backingBuffer.Length - AlignmentPadding | ||||||
AllocateNativeRequest(bytesTransferred); | ||||||
retry = true; | ||||||
} | ||||||
else if (statusCode == UnsafeNclNativeMethods.ErrorCodes.ERROR_SUCCESS | ||||||
&& HttpSysListener.SkipIOCPCallbackOnSuccess) | ||||||
switch (statusCode) | ||||||
{ | ||||||
// IO operation completed synchronously - callback won't be called to signal completion. | ||||||
IOCompleted(statusCode, bytesTransferred); | ||||||
case (UnsafeNclNativeMethods.ErrorCodes.ERROR_CONNECTION_INVALID or UnsafeNclNativeMethods.ErrorCodes.ERROR_INVALID_PARAMETER) when _requestContext.RequestId != 0: | ||||||
// ERROR_CONNECTION_INVALID: | ||||||
// The client reset the connection between the time we got the MORE_DATA error and when we called HttpReceiveHttpRequest | ||||||
// with the new buffer. We can clear the request id and move on to the next request. | ||||||
// | ||||||
// ERROR_INVALID_PARAMETER: Historical check from HttpListener. | ||||||
// https://referencesource.microsoft.com/#System/net/System/Net/_ListenerAsyncResult.cs,137 | ||||||
// we might get this if somebody stole our RequestId, | ||||||
// set RequestId to 0 and start all over again with the buffer we just allocated | ||||||
// BUGBUG: how can someone steal our request ID? seems really bad and in need of fix. | ||||||
CancelExpectCompletion(); | ||||||
_requestContext.RequestId = 0; | ||||||
retry = true; | ||||||
break; | ||||||
case UnsafeNclNativeMethods.ErrorCodes.ERROR_MORE_DATA: | ||||||
// the buffer was not big enough to fit the headers, we need | ||||||
// to read the RequestId returned, allocate a new buffer of the required size | ||||||
// (uint)backingBuffer.Length - AlignmentPadding | ||||||
CancelExpectCompletion(); // we'll "expect" again when we retry | ||||||
AllocateNativeRequest(bytesTransferred); | ||||||
retry = true; | ||||||
break; | ||||||
case UnsafeNclNativeMethods.ErrorCodes.ERROR_SUCCESS: | ||||||
if (HttpSysListener.SkipIOCPCallbackOnSuccess) | ||||||
{ | ||||||
// IO operation completed synchronously - callback won't be called to signal completion. | ||||||
IOCompleted(statusCode, bytesTransferred, true); // marks completion | ||||||
} | ||||||
// else: callback fired by IOCP (at some point), which marks completion | ||||||
break; | ||||||
case UnsafeNclNativeMethods.ErrorCodes.ERROR_IO_PENDING: | ||||||
break; // no change to state - callback will occur at some point | ||||||
default: | ||||||
// fault code, not expecting an IOCP callback | ||||||
CancelExpectCompletion(); | ||||||
break; | ||||||
} | ||||||
} | ||||||
while (retry); | ||||||
|
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Uh oh!
There was an error while loading. Please reload this page.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why even gate this behind a flag? I doubt many people will know to turn it on, and if these are failing commonly, wouldn't we want to hear about it? You could disable the HttpSysListener logger if it's too noisy.
Or at least make it opt-out. This is another case where being able to filter logs by event ID would be nice. dotnet/runtime#49924