diff --git a/src/ReverseProxy/Forwarder/HttpForwarder.cs b/src/ReverseProxy/Forwarder/HttpForwarder.cs index 1d0160451..2e61f7744 100644 --- a/src/ReverseProxy/Forwarder/HttpForwarder.cs +++ b/src/ReverseProxy/Forwarder/HttpForwarder.cs @@ -982,6 +982,11 @@ private static class Log EventIds.ForwardingError, "{error}: {message}"); + private static readonly Action _proxyRequestCancelled = LoggerMessage.Define( + LogLevel.Debug, + EventIds.ForwardingRequestCancelled, + "{error}: {message}"); + private static readonly Action _notProxying = LoggerMessage.Define( LogLevel.Information, EventIds.NotForwarding, @@ -1031,7 +1036,21 @@ public static void InvalidSecWebSocketKeyHeader(ILogger logger, string? key) public static void ErrorProxying(ILogger logger, ForwarderError error, Exception ex) { - _proxyError(logger, error, GetMessage(error), ex); + var message = GetMessage(error); + + if (error is + ForwarderError.RequestCanceled or + ForwarderError.RequestBodyCanceled or + ForwarderError.UpgradeRequestCanceled) + { + // These error conditions are triggered by the client and are not generally indicative of a problem with the proxy. + // It's unlikely that they will be useful in most cases, so we log them at Debug level to reduce noise. + _proxyRequestCancelled(logger, error, message, ex); + } + else + { + _proxyError(logger, error, message, ex); + } } public static void RetryingWebSocketDowngradeNoConnect(ILogger logger) diff --git a/src/ReverseProxy/Utilities/EventIds.cs b/src/ReverseProxy/Utilities/EventIds.cs index 4c28e9b35..2b90d53ca 100644 --- a/src/ReverseProxy/Utilities/EventIds.cs +++ b/src/ReverseProxy/Utilities/EventIds.cs @@ -69,4 +69,5 @@ internal static class EventIds public static readonly EventId InvalidSecWebSocketKeyHeader = new EventId(63, "InvalidSecWebSocketKeyHeader"); public static readonly EventId TimeoutNotApplied = new(64, nameof(TimeoutNotApplied)); public static readonly EventId DelegationQueueNoLongerExists = new(65, nameof(DelegationQueueNoLongerExists)); + public static readonly EventId ForwardingRequestCancelled = new(66, nameof(ForwardingRequestCancelled)); } diff --git a/test/ReverseProxy.Tests/Common/TestEventListener.cs b/test/ReverseProxy.Tests/Common/TestEventListener.cs index 8e98108bb..9c241369f 100644 --- a/test/ReverseProxy.Tests/Common/TestEventListener.cs +++ b/test/ReverseProxy.Tests/Common/TestEventListener.cs @@ -1,7 +1,6 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. -using System; using System.Collections.Generic; using System.Diagnostics.Tracing; using System.Threading; @@ -10,13 +9,12 @@ namespace Yarp.Tests.Common; internal static class TestEventListener { - private static readonly AsyncLocal> _eventsAsyncLocal = new AsyncLocal>(); - private static readonly InternalEventListener _listener = new InternalEventListener(); + private static readonly AsyncLocal> _eventsAsyncLocal = new(); +#pragma warning disable IDE0052 // Remove unread private members + private static readonly InternalEventListener _listener = new(); +#pragma warning restore IDE0052 - public static List Collect() - { - return _eventsAsyncLocal.Value = new List(); - } + public static List Collect() => _eventsAsyncLocal.Value ??= []; private sealed class InternalEventListener : EventListener { @@ -28,14 +26,7 @@ protected override void OnEventSourceCreated(EventSource eventSource) } } - protected override void OnEventWritten(EventWrittenEventArgs eventData) - { - if (eventData.EventId == 0) - { - throw new Exception($"EventSource error received: {eventData.Payload[0]}"); - } - + protected override void OnEventWritten(EventWrittenEventArgs eventData) => _eventsAsyncLocal.Value?.Add(eventData); - } } } diff --git a/test/ReverseProxy.Tests/Common/TestLogger.cs b/test/ReverseProxy.Tests/Common/TestLogger.cs new file mode 100644 index 000000000..651662f3d --- /dev/null +++ b/test/ReverseProxy.Tests/Common/TestLogger.cs @@ -0,0 +1,29 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Threading; +using Microsoft.Extensions.Logging; + +namespace Yarp.ReverseProxy.Common; + +internal sealed class TestLogger(ILogger xunitLogger, string categoryName) : ILogger +{ + public record LogEntry(string CategoryName, LogLevel LogLevel, EventId EventId, string Message, Exception Exception); + + private static readonly AsyncLocal> _logsAsyncLocal = new(); + + public static List Collect() => _logsAsyncLocal.Value ??= []; + + public IDisposable BeginScope(TState state) where TState : notnull => xunitLogger.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _logsAsyncLocal.Value?.Add(new LogEntry(categoryName, logLevel, eventId, formatter(state, exception), exception)); + + xunitLogger.Log(logLevel, eventId, state, exception, formatter); + } +} diff --git a/test/ReverseProxy.Tests/Common/TestLoggerProvider.cs b/test/ReverseProxy.Tests/Common/TestLoggerProvider.cs new file mode 100644 index 000000000..98a40858d --- /dev/null +++ b/test/ReverseProxy.Tests/Common/TestLoggerProvider.cs @@ -0,0 +1,17 @@ +// 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; +using Microsoft.Extensions.Logging.Testing; +using Xunit.Abstractions; + +namespace Yarp.ReverseProxy.Common; + +internal sealed class TestLoggerProvider(ITestOutputHelper output) : ILoggerProvider +{ + private readonly XunitLoggerProvider _xunitLoggerProvider = new(output); + + public ILogger CreateLogger(string categoryName) => new TestLogger(_xunitLoggerProvider.CreateLogger(categoryName), categoryName); + + public void Dispose() => _xunitLoggerProvider.Dispose(); +} diff --git a/test/ReverseProxy.Tests/Forwarder/HttpForwarderTests.cs b/test/ReverseProxy.Tests/Forwarder/HttpForwarderTests.cs index db6c761ac..fe36680fc 100644 --- a/test/ReverseProxy.Tests/Forwarder/HttpForwarderTests.cs +++ b/test/ReverseProxy.Tests/Forwarder/HttpForwarderTests.cs @@ -18,11 +18,13 @@ using Microsoft.AspNetCore.WebUtilities; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Primitives; using Microsoft.Net.Http.Headers; using Moq; using Xunit; using Xunit.Abstractions; +using Yarp.ReverseProxy.Common; using Yarp.ReverseProxy.Transforms; using Yarp.ReverseProxy.Transforms.Builder.Tests; using Yarp.ReverseProxy.Utilities; @@ -42,7 +44,11 @@ public HttpForwarderTests(ITestOutputHelper output) private IHttpForwarder CreateProxy() { var services = new ServiceCollection(); - services.AddLogging(b => b.AddXunit(_output)); + services.AddLogging(b => + { + b.SetMinimumLevel(LogLevel.Trace); + b.Services.AddSingleton(new TestLoggerProvider(_output)); + }); services.AddHttpForwarder(); var provider = services.BuildServiceProvider(); return provider.GetRequiredService(); @@ -850,7 +856,8 @@ public async Task RequestWithBodies_HasHttpContent(string method, string protoco [InlineData("2.0", 2, "a")] public async Task RequestWithBodies_WrongContentLength(string version, long contentLength, string body) { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -887,14 +894,7 @@ public async Task RequestWithBodies_WrongContentLength(string version, long cont var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client, options); - Assert.Equal(ForwarderError.RequestBodyClient, proxyError); - Assert.Equal(StatusCodes.Status400BadRequest, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyClient, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart, ForwarderStage.RequestContentTransferStart }); + AssertErrorInfoAndStages(ForwarderError.RequestBodyClient, StatusCodes.Status400BadRequest, proxyError, httpContext, destinationPrefix, ForwarderStage.RequestContentTransferStart); } [Fact] @@ -1342,7 +1342,8 @@ public async Task OptionsWithVersion_Transformed() [Fact] public async Task UnableToConnect_Returns502() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1361,21 +1362,15 @@ public async Task UnableToConnect_Returns502() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.Request, proxyError); - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.Request, StatusCodes.Status502BadGateway, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.Request, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] public async Task UnableToConnectWithBody_Returns502() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1396,21 +1391,15 @@ public async Task UnableToConnectWithBody_Returns502() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.Request, proxyError); - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.Request, StatusCodes.Status502BadGateway, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.Request, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] public async Task RequestTimedOut_Returns504() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1434,21 +1423,15 @@ public async Task RequestTimedOut_Returns504() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client, requestOptions); - Assert.Equal(ForwarderError.RequestTimedOut, proxyError); - Assert.Equal(StatusCodes.Status504GatewayTimeout, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestTimedOut, StatusCodes.Status504GatewayTimeout, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestTimedOut, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] public async Task RequestConnectTimedOut_Returns504() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1468,21 +1451,15 @@ public async Task RequestConnectTimedOut_Returns504() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestTimedOut, proxyError); - Assert.Equal(StatusCodes.Status504GatewayTimeout, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestTimedOut, StatusCodes.Status504GatewayTimeout, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestTimedOut, errorFeature.Error); - Assert.IsAssignableFrom(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] public async Task RequestCanceled_Returns400() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1503,21 +1480,15 @@ public async Task RequestCanceled_Returns400() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestCanceled, proxyError); - Assert.Equal(StatusCodes.Status400BadRequest, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestCanceled, StatusCodes.Status400BadRequest, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestCanceled, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] public async Task RequestWithBodyTimedOut_Returns504() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1543,15 +1514,8 @@ public async Task RequestWithBodyTimedOut_Returns504() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client, requestOptions); - Assert.Equal(ForwarderError.RequestTimedOut, proxyError); - Assert.Equal(StatusCodes.Status504GatewayTimeout, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestTimedOut, StatusCodes.Status504GatewayTimeout, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestTimedOut, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] @@ -1610,14 +1574,15 @@ public async Task RequestWithBody_KeptAliveByActivity() Assert.Equal(0, proxyResponseStream.Length); AssertProxyStartStop(events, destinationPrefix, httpContext.Response.StatusCode); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart, ForwarderStage.SendAsyncStop, - ForwarderStage.RequestContentTransferStart, ForwarderStage.ResponseContentTransferStart, }); + events.AssertContainProxyStages([ForwarderStage.SendAsyncStart, ForwarderStage.SendAsyncStop, + ForwarderStage.RequestContentTransferStart, ForwarderStage.ResponseContentTransferStart]); } [Fact] public async Task RequestWithBodyCanceled_Returns400() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1640,21 +1605,15 @@ public async Task RequestWithBodyCanceled_Returns400() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestCanceled, proxyError); - Assert.Equal(StatusCodes.Status400BadRequest, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestCanceled, StatusCodes.Status400BadRequest, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestCanceled, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] public async Task RequestBodyClientErrorBeforeResponseError_Returns400() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1677,25 +1636,16 @@ public async Task RequestBodyClientErrorBeforeResponseError_Returns400() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyClient, proxyError); - Assert.Equal(StatusCodes.Status400BadRequest, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestBodyClient, StatusCodes.Status400BadRequest, proxyError, httpContext, destinationPrefix, ForwarderStage.RequestContentTransferStart); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyClient, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { - ForwarderStage.SendAsyncStart, - ForwarderStage.RequestContentTransferStart - }); } [Theory] [InlineData(StatusCodes.Status413PayloadTooLarge)] public async Task NonGenericRequestBodyClientErrorCode_ReturnsNonGenericClientErrorCode(int statusCode) { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1717,20 +1667,14 @@ public async Task NonGenericRequestBodyClientErrorCode_ReturnsNonGenericClientEr var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyClient, proxyError); - Assert.Equal(statusCode, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyClient, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart, ForwarderStage.RequestContentTransferStart }); + AssertErrorInfoAndStages(ForwarderError.RequestBodyClient, statusCode, proxyError, httpContext, destinationPrefix, ForwarderStage.RequestContentTransferStart); } [Fact] public async Task RequestBodyDestinationErrorBeforeResponseError_Returns502() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1753,24 +1697,15 @@ public async Task RequestBodyDestinationErrorBeforeResponseError_Returns502() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyDestination, proxyError); - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestBodyDestination, StatusCodes.Status502BadGateway, proxyError, httpContext, destinationPrefix, ForwarderStage.RequestContentTransferStart); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyDestination, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { - ForwarderStage.SendAsyncStart, - ForwarderStage.RequestContentTransferStart - }); } [Fact] public async Task RequestBodyCanceledBeforeResponseError_Returns502() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "POST"; @@ -1798,15 +1733,8 @@ public async Task RequestBodyCanceledBeforeResponseError_Returns502() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyCanceled, proxyError); - Assert.Equal(StatusCodes.Status400BadRequest, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.RequestBodyCanceled, StatusCodes.Status400BadRequest, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyCanceled, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(new[] { ForwarderStage.SendAsyncStart }); } [Fact] @@ -1858,7 +1786,8 @@ public async Task ResponseBodySuppressedByTransform_ReturnsStatusCodeAndHeaders( [Fact] public async Task ResponseBodyDestionationErrorFirstRead_Returns502() { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1882,22 +1811,16 @@ public async Task ResponseBodyDestionationErrorFirstRead_Returns502() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.ResponseBodyDestination, proxyError); - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); + AssertErrorInfoAndStages(ForwarderError.ResponseBodyDestination, StatusCodes.Status502BadGateway, proxyError, httpContext, destinationPrefix, ForwarderStage.SendAsyncStop, ForwarderStage.ResponseContentTransferStart); Assert.Equal(0, proxyResponseStream.Length); Assert.Empty(httpContext.Response.Headers); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.ResponseBodyDestination, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(hasRequestContent: false); } [Fact] public async Task ResponseBodyDestionationErrorSecondRead_Aborted() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1922,16 +1845,12 @@ public async Task ResponseBodyDestionationErrorSecondRead_Aborted() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.ResponseBodyDestination, proxyError); - Assert.Equal(StatusCodes.Status200OK, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.ResponseBodyDestination, StatusCodes.Status200OK, proxyError, httpContext, destinationPrefix); + Assert.Equal(1, responseBody.InnerStream.Length); Assert.True(responseBody.Aborted); Assert.Equal("bytes", httpContext.Response.Headers[HeaderNames.AcceptRanges]); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.ResponseBodyDestination, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(hasRequestContent: false); } @@ -1939,6 +1858,7 @@ public async Task ResponseBodyDestionationErrorSecondRead_Aborted() public async Task ResponseBodyClientError_Aborted() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -1963,15 +1883,11 @@ public async Task ResponseBodyClientError_Aborted() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.ResponseBodyClient, proxyError); - Assert.Equal(StatusCodes.Status200OK, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.ResponseBodyClient, StatusCodes.Status200OK, proxyError, httpContext, destinationPrefix); + Assert.True(responseBody.Aborted); Assert.Equal("bytes", httpContext.Response.Headers[HeaderNames.AcceptRanges]); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.ResponseBodyClient, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(hasRequestContent: false); } @@ -1979,6 +1895,7 @@ public async Task ResponseBodyClientError_Aborted() public async Task ResponseBodyCancelled_502() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -2004,15 +1921,11 @@ public async Task ResponseBodyCancelled_502() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.ResponseBodyCanceled, proxyError); - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.ResponseBodyCanceled, StatusCodes.Status502BadGateway, proxyError, httpContext, destinationPrefix); + Assert.False(responseBody.Aborted); Assert.Empty(httpContext.Response.Headers); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.ResponseBodyCanceled, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(hasRequestContent: false); } @@ -2020,6 +1933,7 @@ public async Task ResponseBodyCancelled_502() public async Task ResponseBodyCancelledAfterStart_Aborted() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -2052,15 +1966,11 @@ public async Task ResponseBodyCancelledAfterStart_Aborted() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client, ForwarderRequestConfig.Empty, HttpTransformer.Empty, cts.Token); - Assert.Equal(ForwarderError.ResponseBodyCanceled, proxyError); - Assert.Equal(StatusCodes.Status200OK, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.ResponseBodyCanceled, StatusCodes.Status200OK, proxyError, httpContext, destinationPrefix); + Assert.True(responseBody.Aborted); Assert.Equal("bytes", httpContext.Response.Headers[HeaderNames.AcceptRanges]); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.ResponseBodyCanceled, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(hasRequestContent: false); } @@ -2101,6 +2011,7 @@ public async Task ResponseBodyDisableBuffering_Success(bool? enableBuffering) public async Task RequestBodyCanceledAfterResponse_Reported() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var waitTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var httpContext = new DefaultHttpContext(); @@ -2135,14 +2046,9 @@ public async Task RequestBodyCanceledAfterResponse_Reported() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyCanceled, proxyError); - Assert.Equal(StatusCodes.Status200OK, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.RequestBodyCanceled, StatusCodes.Status200OK, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyCanceled, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(); } @@ -2150,6 +2056,7 @@ public async Task RequestBodyCanceledAfterResponse_Reported() public async Task RequestBodyClientErrorAfterResponse_Reported() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var waitTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var httpContext = new DefaultHttpContext(); @@ -2177,14 +2084,9 @@ public async Task RequestBodyClientErrorAfterResponse_Reported() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyClient, proxyError); - Assert.Equal(StatusCodes.Status200OK, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.RequestBodyClient, StatusCodes.Status200OK, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyClient, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(); } @@ -2192,6 +2094,7 @@ public async Task RequestBodyClientErrorAfterResponse_Reported() public async Task RequestBodyDestinationErrorAfterResponse_Reported() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var waitTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var httpContext = new DefaultHttpContext(); @@ -2219,14 +2122,9 @@ public async Task RequestBodyDestinationErrorAfterResponse_Reported() var proxyError = await sut.SendAsync(httpContext, destinationPrefix, client); - Assert.Equal(ForwarderError.RequestBodyDestination, proxyError); - Assert.Equal(StatusCodes.Status200OK, httpContext.Response.StatusCode); + AssertErrorInfo(ForwarderError.RequestBodyDestination, StatusCodes.Status200OK, proxyError, httpContext, destinationPrefix); Assert.Equal(0, proxyResponseStream.Length); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.RequestBodyDestination, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(); } @@ -2234,6 +2132,7 @@ public async Task RequestBodyDestinationErrorAfterResponse_Reported() public async Task UpgradableRequest_RequestBodyCopyError_CancelsResponseBody() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -2280,13 +2179,8 @@ public async Task UpgradableRequest_RequestBodyCopyError_CancelsResponseBody() Version = HttpVersion.Version11, }); - Assert.Equal(ForwarderError.UpgradeRequestClient, proxyError); - Assert.Equal(StatusCodes.Status101SwitchingProtocols, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.UpgradeRequestClient, errorFeature.Error); - Assert.IsType(errorFeature.Exception); + AssertErrorInfo(ForwarderError.UpgradeRequestClient, StatusCodes.Status101SwitchingProtocols, proxyError, httpContext, destinationPrefix); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(upgrade: true); } @@ -2294,6 +2188,7 @@ public async Task UpgradableRequest_RequestBodyCopyError_CancelsResponseBody() public async Task UpgradableRequest_ResponseBodyCopyError_CancelsRequestBody() { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -2340,13 +2235,8 @@ public async Task UpgradableRequest_ResponseBodyCopyError_CancelsRequestBody() Version = HttpVersion.Version11, }); - Assert.Equal(ForwarderError.UpgradeResponseDestination, proxyError); - Assert.Equal(StatusCodes.Status101SwitchingProtocols, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.UpgradeResponseDestination, errorFeature.Error); - Assert.IsType(errorFeature.Exception); + AssertErrorInfo(ForwarderError.UpgradeResponseDestination, StatusCodes.Status101SwitchingProtocols, proxyError, httpContext, destinationPrefix); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); events.AssertContainProxyStages(upgrade: true); } @@ -2641,6 +2531,7 @@ public async Task Response_RemoveProhibitedHeaders(string protocol, string prohi public async Task RequestFailure_ResponseTransformsAreCalled(bool failureInRequestTransform) { var events = TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -2686,14 +2577,9 @@ public async Task RequestFailure_ResponseTransformsAreCalled(bool failureInReque ? ForwarderError.RequestCreation : ForwarderError.Request; - Assert.Equal(expectedError, proxyError); - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(expectedError, errorFeature.Error); - Assert.IsType(errorFeature.Exception); + AssertErrorInfo(expectedError, StatusCodes.Status502BadGateway, proxyError, httpContext, destinationPrefix); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(failureInRequestTransform ? Array.Empty() : new [] { ForwarderStage.SendAsyncStart }); + events.AssertContainProxyStages(failureInRequestTransform ? [] : [ForwarderStage.SendAsyncStart]); } [Theory] @@ -2701,7 +2587,8 @@ public async Task RequestFailure_ResponseTransformsAreCalled(bool failureInReque [InlineData(false)] public async Task RequestFailure_CancellationExceptionInResponseTransformIsIgnored(bool throwOce) { - var events = TestEventListener.Collect(); + TestEventListener.Collect(); + TestLogger.Collect(); var httpContext = new DefaultHttpContext(); httpContext.Request.Method = "GET"; @@ -2758,13 +2645,7 @@ public async Task RequestFailure_CancellationExceptionInResponseTransformIsIgnor Assert.NotNull(exceptionThrownBySendAsync); } - Assert.Equal(StatusCodes.Status502BadGateway, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(ForwarderError.Request, errorFeature.Error); - Assert.IsType(errorFeature.Exception); - - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages([ForwarderStage.SendAsyncStart]); + AssertErrorInfoAndStages(ForwarderError.Request, StatusCodes.Status502BadGateway, ForwarderError.Request, httpContext, destinationPrefix); } public enum CancellationScenario @@ -2781,6 +2662,7 @@ public enum CancellationScenario public async Task ForwarderCancellations_CancellationsAreVisibleInTransforms(CancellationScenario cancellationScenario) { var events = TestEventListener.Collect(); + TestLogger.Collect(); using var requestAbortedCts = new CancellationTokenSource(); using var parameterCts = new CancellationTokenSource(); @@ -2852,14 +2734,9 @@ public async Task ForwarderCancellations_CancellationsAreVisibleInTransforms(Can _ => throw new NotImplementedException(cancellationScenario.ToString()), }; - Assert.Equal(expectedError, proxyError); - Assert.Equal(expectedStatusCode, httpContext.Response.StatusCode); - var errorFeature = httpContext.Features.Get(); - Assert.Equal(expectedError, errorFeature.Error); - Assert.IsType(errorFeature.Exception); + AssertErrorInfo(expectedError, expectedStatusCode, proxyError, httpContext, destinationPrefix); - AssertProxyStartFailedStop(events, destinationPrefix, httpContext.Response.StatusCode, errorFeature.Error); - events.AssertContainProxyStages(Array.Empty()); + events.AssertContainProxyStages([]); } public static IEnumerable GetProhibitedHeaders() @@ -2909,6 +2786,41 @@ public static IEnumerable GetHeadersWithNewLines() } } + private static void AssertErrorInfoAndStages( + ForwarderError expectedError, int expectedStatusCode, + ForwarderError error, HttpContext context, string destinationPrefix, + params ForwarderStage[] otherStages) + where TException : Exception + { + AssertErrorInfo(expectedError, expectedStatusCode, error, context, destinationPrefix); + + TestEventListener.Collect().AssertContainProxyStages([ForwarderStage.SendAsyncStart, .. otherStages]); + } + + private static void AssertErrorInfo( + ForwarderError expectedError, int expectedStatusCode, + ForwarderError error, HttpContext context, string destinationPrefix) + where TException : Exception + { + Assert.Equal(expectedError, error); + Assert.Equal(expectedStatusCode, context.Response.StatusCode); + var errorFeature = context.Features.Get(); + Assert.NotNull(errorFeature); + Assert.Equal(error, errorFeature.Error); + Assert.IsAssignableFrom(errorFeature.Exception); + + var expectedId = error is ForwarderError.RequestCanceled or ForwarderError.RequestBodyCanceled or ForwarderError.UpgradeRequestCanceled + ? EventIds.ForwardingRequestCancelled + : EventIds.ForwardingError; + + var log = Assert.Single(TestLogger.Collect(), l => l.EventId == expectedId); + Assert.Equal(typeof(HttpForwarder).FullName, log.CategoryName); + Assert.Contains(error.ToString(), log.Message); + Assert.NotNull(log.Exception); + + AssertProxyStartFailedStop(TestEventListener.Collect(), destinationPrefix, context.Response.StatusCode, errorFeature.Error); + } + private static void AssertProxyStartStop(List events, string destinationPrefix, int statusCode) { AssertProxyStartFailedStop(events, destinationPrefix, statusCode, error: null);