From 8e9ddbb7f4e9f194530de02627954373fd25288b Mon Sep 17 00:00:00 2001 From: Marc Gravell Date: Tue, 5 Mar 2024 11:45:00 +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 --- .../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 945428ab1da8..c47a603d8655 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.cs @@ -3,14 +3,17 @@ using System.Diagnostics; using System.Threading.Tasks.Sources; +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; @@ -23,11 +26,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 6170a9a42dd5210b5c49b651c4ff5d99d1f9122e 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 049844dd816d099dd0348ad64824a8d1580917c7 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 ec33b61ba4b3dbd3b67670395464e8fac8220ce6 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 c47a603d8655..a03ef4c85a67 100644 --- a/src/Servers/HttpSys/src/AsyncAcceptContext.cs +++ b/src/Servers/HttpSys/src/AsyncAcceptContext.cs @@ -17,6 +17,9 @@ internal sealed unsafe partial class AsyncAcceptContext : IValueTaskSource _mrvts = new() { @@ -54,11 +57,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 != ErrorCodes.ERROR_SUCCESS && errorCode != ErrorCodes.ERROR_MORE_DATA) { @@ -118,7 +121,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 @@ -128,7 +131,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 } } @@ -137,16 +143,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 } } @@ -201,7 +213,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;