Lower severity of logs caused by request body IOExceptions

Author: halter73

src/Http/Routing/src/Internal/MapActionExpressionTreeBuilder.cs

@@ -5,6 +5,7 @@
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Globalization;
+using System.IO;
 using System.Linq;
 using System.Linq.Expressions;
 using System.Reflection;
@@ -14,6 +15,7 @@
 using Microsoft.AspNetCore.Http.Metadata;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Internal;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Routing.Internal
 {
@@ -262,7 +264,16 @@ public static RequestDelegate BuildRequestDelegate(Delegate action)
                     }
                     else
                     {
-                        bodyValue = await httpContext.Request.ReadFromJsonAsync(bodyType!);
+                        try
+                        {
+                            bodyValue = await httpContext.Request.ReadFromJsonAsync(bodyType!);
+                        }
+                        catch (IOException ex)
+                        {
+                            LogRequestBodyIOException(httpContext, ex);
+                            httpContext.Abort();
+                            return;
+                        }
                     }
 
                     await invoker(target, httpContext, bodyValue);
@@ -277,7 +288,16 @@ public static RequestDelegate BuildRequestDelegate(Delegate action)
                 {
                     // Generating async code would just be insane so if the method needs the form populate it here
                     // so the within the method it's cached
-                    await httpContext.Request.ReadFormAsync();
+                    try
+                    {
+                        await httpContext.Request.ReadFormAsync();
+                    }
+                    catch (IOException ex)
+                    {
+                        LogRequestBodyIOException(httpContext, ex);
+                        httpContext.Abort();
+                        return;
+                    }
 
                     await invoker(target, httpContext);
                 };
@@ -296,6 +316,18 @@ public static RequestDelegate BuildRequestDelegate(Delegate action)
             };
         }
 
+        private static void LogRequestBodyIOException(HttpContext httpContext, IOException exception)
+        {
+            var loggerFactory = httpContext.RequestServices.GetRequiredService<ILoggerFactory>();
+
+            // REVIEW: I'm not sure how we feel about using an internal type as a category name, but this is what was done in other
+            // internal classes like DfaMather and DefaultLinkGenerator. My main concern is if we want to use the same category for
+            // other MapAction implementations (e.g. Roslyn source generators)
+            var logger = loggerFactory.CreateLogger(typeof(MapActionExpressionTreeBuilder).FullName!);
+
+            Log.RequestBodyIOException(logger, exception);
+        }
+
         private static Expression BindParamenter(Expression sourceExpression, ParameterInfo parameter, string? name)
         {
             var key = name ?? parameter.Name;
@@ -398,5 +430,18 @@ private static void ThrowCannotReadBodyDirectlyAndAsForm()
         {
             throw new InvalidOperationException("Action cannot mix FromBody and FromForm on the same method.");
         }
+
+        private static class Log
+        {
+            private static readonly Action<ILogger, Exception> _requestBodyIOException = LoggerMessage.Define(
+                LogLevel.Debug,
+                new EventId(1, "RequestBodyIOException"),
+                "Reading the request body failed with an IOException.");
+
+            public static void RequestBodyIOException(ILogger logger, IOException exception)
+            {
+                _requestBodyIOException(logger, exception);
+            }
+        }
     }
 }

src/Http/Routing/test/UnitTests/Internal/MapActionExpressionTreeBuilderTest.cs

@@ -9,10 +9,14 @@
 using System.IO;
 using System.Text;
 using System.Text.Json;
+using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
+using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Http.Metadata;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.Primitives;
 using Xunit;
 
@@ -24,6 +28,7 @@ public class MapActionExpressionTreeBuilderTest
         public async Task RequestDelegateInvokesAction()
         {
             var invoked = false;
+
             void TestAction()
             {
                 invoked = true;
@@ -87,6 +92,10 @@ public async Task UsesDefaultValueIfNoMatchingRouteValue()
         {
             const string unmatchedName = "value";
             const int unmatchedRouteParam = 42;
+            var structToBeZeroed = new BodyStruct
+            {
+                Id = 42
+            };
 
             int? deserializedRouteParam = null;
 
@@ -246,6 +255,42 @@ void TestAction([FromBody(AllowEmpty = true)] BodyStruct bodyStruct)
             Assert.Equal(default, structToBeZeroed);
         }
 
+        [Fact]
+        public async Task RequestDelegateLogsFromBodyIOExceptionsAsDebug()
+        {
+            var invoked = false;
+
+            var sink = new TestSink(context => context.LoggerName == typeof(MapActionExpressionTreeBuilder).FullName);
+            var testLoggerFactory = new TestLoggerFactory(sink, enabled: true);
+
+            void TestAction([FromBody] Todo todo)
+            {
+                invoked = true;
+            }
+
+            var ioException = new IOException();
+            var serviceCollection = new ServiceCollection();
+            serviceCollection.AddSingleton<ILoggerFactory>(testLoggerFactory);
+
+            var httpContext = new DefaultHttpContext();
+            httpContext.Request.Headers["Content-Type"] = "application/json";
+            httpContext.Request.Body = new IOExceptionThrowingRequestBodyStream(ioException);
+            httpContext.Features.Set<IHttpRequestLifetimeFeature>(new TestHttpRequestLifetimeFeature());
+            httpContext.RequestServices = serviceCollection.BuildServiceProvider();
+
+            var requestDelegate = MapActionExpressionTreeBuilder.BuildRequestDelegate((Action<Todo>)TestAction);
+
+            await requestDelegate(httpContext);
+
+            Assert.False(invoked);
+            Assert.True(httpContext.RequestAborted.IsCancellationRequested);
+
+            var logMessage = Assert.Single(sink.Writes);
+            Assert.Equal(new EventId(1, "RequestBodyIOException"), logMessage.EventId);
+            Assert.Equal(LogLevel.Debug, logMessage.LogLevel);
+            Assert.Same(ioException, logMessage.Exception);
+        }
+
         [Fact]
         public async Task RequestDelegatePopulatesFromFormParameterBasedOnParameterName()
         {
@@ -274,6 +319,42 @@ void TestAction([FromForm] int value)
             Assert.Equal(originalQueryParam, deserializedRouteParam);
         }
 
+        [Fact]
+        public async Task RequestDelegateLogsFromFormIOExceptionsAsDebug()
+        {
+            var invoked = false;
+
+            var sink = new TestSink(context => context.LoggerName == typeof(MapActionExpressionTreeBuilder).FullName);
+            var testLoggerFactory = new TestLoggerFactory(sink, enabled: true);
+
+            void TestAction([FromForm] int value)
+            {
+                invoked = true;
+            }
+
+            var ioException = new IOException();
+            var serviceCollection = new ServiceCollection();
+            serviceCollection.AddSingleton<ILoggerFactory>(testLoggerFactory);
+
+            var httpContext = new DefaultHttpContext();
+            httpContext.Request.Headers["Content-Type"] = "application/x-www-form-urlencoded";
+            httpContext.Request.Body = new IOExceptionThrowingRequestBodyStream(ioException);
+            httpContext.Features.Set<IHttpRequestLifetimeFeature>(new TestHttpRequestLifetimeFeature());
+            httpContext.RequestServices = serviceCollection.BuildServiceProvider();
+
+            var requestDelegate = MapActionExpressionTreeBuilder.BuildRequestDelegate((Action<int>)TestAction);
+
+            await requestDelegate(httpContext);
+
+            Assert.False(invoked);
+            Assert.True(httpContext.RequestAborted.IsCancellationRequested);
+
+            var logMessage = Assert.Single(sink.Writes);
+            Assert.Equal(new EventId(1, "RequestBodyIOException"), logMessage.EventId);
+            Assert.Equal(LogLevel.Debug, logMessage.LogLevel);
+            Assert.Same(ioException, logMessage.Exception);
+        }
+
         [Fact]
         public void BuildRequestDelegateThrowsInvalidOperationExceptionGivenBothFromBodyAndFromFormOnDifferentParameters()
         {
@@ -463,5 +544,62 @@ public Task ExecuteAsync(HttpContext httpContext)
                 return httpContext.Response.WriteAsync(_resultString);
             }
         }
+
+        private class IOExceptionThrowingRequestBodyStream : Stream
+        {
+            private readonly Exception _exceptionToThrow;
+
+            public IOExceptionThrowingRequestBodyStream(Exception exceptionToThrow)
+            {
+                _exceptionToThrow = exceptionToThrow;
+            }
+
+            public override bool CanRead => true;
+
+            public override bool CanSeek => false;
+
+            public override bool CanWrite => false;
+
+            public override long Length => throw new NotImplementedException();
+
+            public override long Position { get => throw new NotImplementedException(); set => throw new NotImplementedException(); }
+
+            public override void Flush()
+            {
+                throw new NotImplementedException();
+            }
+
+            public override int Read(byte[] buffer, int offset, int count)
+            {
+                throw _exceptionToThrow;
+            }
+
+            public override long Seek(long offset, SeekOrigin origin)
+            {
+                throw new NotImplementedException();
+            }
+
+            public override void SetLength(long value)
+            {
+                throw new NotImplementedException();
+            }
+
+            public override void Write(byte[] buffer, int offset, int count)
+            {
+                throw new NotImplementedException();
+            }
+        }
+
+        private class TestHttpRequestLifetimeFeature : IHttpRequestLifetimeFeature
+        {
+            private readonly CancellationTokenSource _requestAbortedCts = new CancellationTokenSource();
+
+            public CancellationToken RequestAborted { get => _requestAbortedCts.Token; set => throw new NotImplementedException(); }
+
+            public void Abort()
+            {
+                _requestAbortedCts.Cancel();
+            }
+        }
     }
 }