From 16416b1d976a55ce1f31a7cadd2209313ca97832 Mon Sep 17 00:00:00 2001 From: Marc Gravell Date: Fri, 8 Mar 2024 16:44:50 +0000 Subject: [PATCH 1/4] investigate #54251 (more details will be in PR) 1. handle MRTVS cascading fault breaking the accept loop 2. log any expectation failures # Conflicts: # src/Servers/HttpSys/src/AsyncAcceptContext.cs --- .../HttpSys/src/AsyncAcceptContext.Log.cs | 24 ++++ src/Servers/HttpSys/src/AsyncAcceptContext.cs | 132 +++++++++++++----- src/Servers/HttpSys/src/LoggerEventIds.cs | 4 + src/Servers/HttpSys/src/MessagePump.cs | 2 +- .../FunctionalTests/Listener/Utilities.cs | 2 +- 5 files changed, 126 insertions(+), 38 deletions(-) create mode 100644 src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs diff --git a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs new file mode 100644 index 000000000000..a4bf41598722 --- /dev/null +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs @@ -0,0 +1,24 @@ +// 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); + + [LoggerMessage(LoggerEventIds.AcceptSetExpectationMismatch, LogLevel.Error, "Mismatch setting callback expectation {Value}", EventName = "AcceptSetExpectationMismatch")] + public static partial void AcceptSetExpectationMismatch(ILogger logger, int value); + + [LoggerMessage(LoggerEventIds.AcceptCancelExpectationMismatch, LogLevel.Error, "Mismatch canceling accept state - {Value}", EventName = "AcceptCancelExpectationMismatch")] + public static partial void AcceptCancelExpectationMismatch(ILogger logger, int value); + + [LoggerMessage(LoggerEventIds.AcceptObserveExpectationMismatch, LogLevel.Error, "Mismatch observing accept callback - {Value}", EventName = "AcceptObserveExpectationMismatch")] + public static partial void AcceptObserveExpectationMismatch(ILogger logger, int value); + } +} diff --git a/src/Servers/HttpSys/src/AsyncAcceptContext.cs b/src/Servers/HttpSys/src/AsyncAcceptContext.cs index 72131695aed6..f977b40a0e68 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.cs @@ -4,14 +4,17 @@ 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, IDisposable +internal sealed unsafe partial class AsyncAcceptContext : IValueTaskSource, 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; @@ -24,11 +27,12 @@ internal sealed unsafe class AsyncAcceptContext : IValueTaskSource AcceptAsync(this HttpSysListener server, TimeSpan timeout) { var factory = new TestRequestContextFactory(server); - using var acceptContext = new AsyncAcceptContext(server, factory); + using var acceptContext = new AsyncAcceptContext(server, factory, server.Logger); async Task AcceptAsync() { From 42cc0250c02dcfc8ad18f5980ec557d64becc2af Mon Sep 17 00:00:00 2001 From: Marc Gravell Date: Tue, 5 Mar 2024 12:22:14 +0000 Subject: [PATCH 2/4] make log text consistent --- src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs index a4bf41598722..f594fd931739 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs @@ -12,7 +12,7 @@ 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); - [LoggerMessage(LoggerEventIds.AcceptSetExpectationMismatch, LogLevel.Error, "Mismatch setting callback expectation {Value}", EventName = "AcceptSetExpectationMismatch")] + [LoggerMessage(LoggerEventIds.AcceptSetExpectationMismatch, LogLevel.Error, "Mismatch setting callback expectation - {Value}", EventName = "AcceptSetExpectationMismatch")] public static partial void AcceptSetExpectationMismatch(ILogger logger, int value); [LoggerMessage(LoggerEventIds.AcceptCancelExpectationMismatch, LogLevel.Error, "Mismatch canceling accept state - {Value}", EventName = "AcceptCancelExpectationMismatch")] From 81771165311c180cf427ce2869d069e60b6c0d09 Mon Sep 17 00:00:00 2001 From: Marc Gravell Date: Tue, 5 Mar 2024 12:27:38 +0000 Subject: [PATCH 3/4] upgrade log to "critical" on the actual state error --- src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs index f594fd931739..7179b3c99025 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs @@ -12,13 +12,15 @@ 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); - [LoggerMessage(LoggerEventIds.AcceptSetExpectationMismatch, LogLevel.Error, "Mismatch setting callback expectation - {Value}", EventName = "AcceptSetExpectationMismatch")] + // 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.Error, "Mismatch canceling accept state - {Value}", EventName = "AcceptCancelExpectationMismatch")] + [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.Error, "Mismatch observing accept callback - {Value}", EventName = "AcceptObserveExpectationMismatch")] + [LoggerMessage(LoggerEventIds.AcceptObserveExpectationMismatch, LogLevel.Critical, "Mismatch observing accept callback - {Value}", EventName = "AcceptObserveExpectationMismatch")] public static partial void AcceptObserveExpectationMismatch(ILogger logger, int value); } } From 28706b9fd8964f64a9df9fbe1cb80aa999fc4aaa Mon Sep 17 00:00:00 2001 From: Marc Gravell Date: Fri, 8 Mar 2024 10:46:04 +0000 Subject: [PATCH 4/4] - capture whether it is the managed vs unmanaged code-path that is glitching - lock new critical log messages behind app-context switch --- .../HttpSys/src/AsyncAcceptContext.Log.cs | 4 +-- src/Servers/HttpSys/src/AsyncAcceptContext.cs | 28 +++++++++++++------ 2 files changed, 22 insertions(+), 10 deletions(-) diff --git a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs index 7179b3c99025..93d811b6e3ec 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.Log.cs @@ -20,7 +20,7 @@ private static partial class Log [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 accept callback - {Value}", EventName = "AcceptObserveExpectationMismatch")] - public static partial void AcceptObserveExpectationMismatch(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); } } diff --git a/src/Servers/HttpSys/src/AsyncAcceptContext.cs b/src/Servers/HttpSys/src/AsyncAcceptContext.cs index f977b40a0e68..a210c19bb4ef 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.cs @@ -18,6 +18,9 @@ internal sealed unsafe partial class AsyncAcceptContext : IValueTaskSource _mrvts = new() { @@ -55,11 +58,11 @@ internal ValueTask AcceptAsync() return new ValueTask(this, _mrvts.Version); } - private void IOCompleted(uint errorCode, uint numBytes) + private void IOCompleted(uint errorCode, uint numBytes, bool managed) { try { - ObserveCompletion(); // expectation tracking + ObserveCompletion(managed); // expectation tracking if (errorCode != UnsafeNclNativeMethods.ErrorCodes.ERROR_SUCCESS && errorCode != UnsafeNclNativeMethods.ErrorCodes.ERROR_MORE_DATA) { @@ -119,7 +122,7 @@ private void IOCompleted(uint errorCode, uint numBytes) 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 @@ -129,7 +132,10 @@ private void SetExpectCompletion() // we anticipate a completion *might* occur var value = Interlocked.Exchange(ref _expectedCompletionCount, 1); // should have been 0 if (value != 0) { - Log.AcceptSetExpectationMismatch(_logger, value); + if (_logExpectationFailures) + { + Log.AcceptSetExpectationMismatch(_logger, value); + } Debug.Assert(false, nameof(SetExpectCompletion)); // fail hard in debug } } @@ -138,16 +144,22 @@ private void CancelExpectCompletion() // due to error-code etc, we no longer ant var value = Interlocked.Decrement(ref _expectedCompletionCount); // should have been 1, so now 0 if (value != 0) { - Log.AcceptCancelExpectationMismatch(_logger, value); + if (_logExpectationFailures) + { + Log.AcceptCancelExpectationMismatch(_logger, value); + } Debug.Assert(false, nameof(CancelExpectCompletion)); // fail hard in debug } } - private void ObserveCompletion() // a completion was invoked + 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) { - Log.AcceptObserveExpectationMismatch(_logger, value); + if (_logExpectationFailures) + { + Log.AcceptObserveExpectationMismatch(_logger, managed ? "managed" : "unmanaged", value); + } Debug.Assert(false, nameof(ObserveCompletion)); // fail hard in debug } } @@ -202,7 +214,7 @@ private uint QueueBeginGetContext() if (HttpSysListener.SkipIOCPCallbackOnSuccess) { // IO operation completed synchronously - callback won't be called to signal completion. - IOCompleted(statusCode, bytesTransferred); // marks completion + IOCompleted(statusCode, bytesTransferred, true); // marks completion } // else: callback fired by IOCP (at some point), which marks completion break;