Log messages added to BodyModelBinder for input formatters (aspnet#5451)

Addresses aspnet#5367

src/Microsoft.AspNetCore.Mvc.Core/Formatters/MediaType.cs

@@ -41,7 +41,7 @@ public MediaType(StringSegment mediaType)
         /// </summary>
         /// <param name="mediaType">The <see cref="string"/> with the media type.</param>
         /// <param name="offset">The offset in the <paramref name="mediaType"/> where the parsing starts.</param>
-        /// <param name="length">The of the media type to parse if provided.</param>
+        /// <param name="length">The length of the media type to parse if provided.</param>
         public MediaType(string mediaType, int offset, int? length)
         {
             if (mediaType == null)

src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs

@@ -56,6 +56,11 @@ internal static class MvcCoreLoggerExtensions
         private static readonly Action<ILogger, Exception> _noAcceptForNegotiation;
         private static readonly Action<ILogger, IEnumerable<MediaTypeSegmentWithQuality>, Exception> _noFormatterFromNegotiation;
 
+        private static readonly Action<ILogger, IInputFormatter, string, Exception> _inputFormatterSelected;
+        private static readonly Action<ILogger, IInputFormatter, string, Exception> _inputFormatterRejected;
+        private static readonly Action<ILogger, string, Exception> _noInputFormatterSelected;
+        private static readonly Action<ILogger, string, string, Exception> _removeFromBodyAttribute;
+
         private static readonly Action<ILogger, string, Exception> _redirectResultExecuting;
 
         private static readonly Action<ILogger, string, Exception> _redirectToActionResultExecuting;
@@ -184,6 +189,26 @@ static MvcCoreLoggerExtensions()
                 5,
                 "Could not find an output formatter based on content negotiation. Accepted types were ({AcceptTypes})");
 
+            _inputFormatterSelected = LoggerMessage.Define<IInputFormatter, string>(
+                LogLevel.Debug,
+                1,
+                "Selected input formatter '{InputFormatter}' for content type '{ContentType}'.");
+
+            _inputFormatterRejected = LoggerMessage.Define<IInputFormatter, string>(
+                LogLevel.Debug,
+                2,
+                "Rejected input formatter '{InputFormatter}' for content type '{ContentType}'.");
+
+            _noInputFormatterSelected = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                3,
+                "No input formatter was found to support the content type '{ContentType}' for use with the [FromBody] attribute.");
+
+            _removeFromBodyAttribute = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                4,
+                "To use model binding, remove the [FromBody] attribute from the property or parameter named '{ModelName}' with model type '{ModelType}'.");
+
             _redirectResultExecuting = LoggerMessage.Define<string>(
                 LogLevel.Information,
                 1,
@@ -401,6 +426,47 @@ public static void NoFormatterFromNegotiation(this ILogger logger, IList<MediaTy
             _noFormatterFromNegotiation(logger, acceptTypes, null);
         }
 
+        public static void InputFormatterSelected(
+           this ILogger logger,
+           IInputFormatter inputFormatter,
+           InputFormatterContext formatterContext)
+        {
+            if (logger.IsEnabled(LogLevel.Debug))
+            {
+                var contentType = formatterContext.HttpContext.Request.ContentType;
+                _inputFormatterSelected(logger, inputFormatter, contentType, null);
+            }
+        }
+
+        public static void InputFormatterRejected(
+            this ILogger logger,
+            IInputFormatter inputFormatter,
+            InputFormatterContext formatterContext)
+        {
+            if (logger.IsEnabled(LogLevel.Debug))
+            {
+                var contentType = formatterContext.HttpContext.Request.ContentType;
+                _inputFormatterRejected(logger, inputFormatter, contentType, null);
+            }
+        }
+
+        public static void NoInputFormatterSelected(
+            this ILogger logger,
+            InputFormatterContext formatterContext)
+        {
+            if (logger.IsEnabled(LogLevel.Debug))
+            {
+                var contentType = formatterContext.HttpContext.Request.ContentType;
+                _noInputFormatterSelected(logger, contentType, null);
+                if (formatterContext.HttpContext.Request.HasFormContentType)
+                {
+                    var modelType = formatterContext.ModelType.FullName;
+                    var modelName = formatterContext.ModelName;
+                    _removeFromBodyAttribute(logger, modelName, modelType, null);
+                }
+            }
+        }
+
         public static void RedirectResultExecuting(this ILogger logger, string destination)
         {
             _redirectResultExecuting(logger, destination, null);
@@ -443,7 +509,7 @@ public KeyValuePair<string, object> this[int index]
                         return new KeyValuePair<string, object>("ActionName", _action.DisplayName);
                     }
                     throw new IndexOutOfRangeException(nameof(index));
-                 }
+                }
             }
 
             public int Count

src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreMvcOptionsSetup.cs

@@ -9,6 +9,7 @@
 using Microsoft.AspNetCore.Mvc.ModelBinding;
 using Microsoft.AspNetCore.Mvc.ModelBinding.Binders;
 using Microsoft.AspNetCore.Mvc.ModelBinding.Metadata;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.AspNetCore.Mvc.Internal
@@ -19,23 +20,30 @@ namespace Microsoft.AspNetCore.Mvc.Internal
     public class MvcCoreMvcOptionsSetup : IConfigureOptions<MvcOptions>
     {
         private readonly IHttpRequestStreamReaderFactory _readerFactory;
+        private readonly ILoggerFactory _loggerFactory;
 
         public MvcCoreMvcOptionsSetup(IHttpRequestStreamReaderFactory readerFactory)
+            : this(readerFactory, loggerFactory: null)
+        {
+        }
+
+        public MvcCoreMvcOptionsSetup(IHttpRequestStreamReaderFactory readerFactory, ILoggerFactory loggerFactory)
         {
             if (readerFactory == null)
             {
                 throw new ArgumentNullException(nameof(readerFactory));
             }
 
             _readerFactory = readerFactory;
+            _loggerFactory = loggerFactory;
         }
 
         public void Configure(MvcOptions options)
         {
             // Set up ModelBinding
             options.ModelBinderProviders.Add(new BinderTypeModelBinderProvider());
             options.ModelBinderProviders.Add(new ServicesModelBinderProvider());
-            options.ModelBinderProviders.Add(new BodyModelBinderProvider(options.InputFormatters, _readerFactory));
+            options.ModelBinderProviders.Add(new BodyModelBinderProvider(options.InputFormatters, _readerFactory, _loggerFactory));
             options.ModelBinderProviders.Add(new HeaderModelBinderProvider());
             options.ModelBinderProviders.Add(new SimpleTypeModelBinderProvider());
             options.ModelBinderProviders.Add(new CancellationTokenModelBinderProvider());

src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinder.cs

@@ -9,6 +9,7 @@
 using Microsoft.AspNetCore.Mvc.Core;
 using Microsoft.AspNetCore.Mvc.Formatters;
 using Microsoft.AspNetCore.Mvc.Internal;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders
 {
@@ -20,6 +21,7 @@ public class BodyModelBinder : IModelBinder
     {
         private readonly IList<IInputFormatter> _formatters;
         private readonly Func<Stream, Encoding, TextReader> _readerFactory;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Creates a new <see cref="BodyModelBinder"/>.
@@ -30,6 +32,20 @@ public class BodyModelBinder : IModelBinder
         /// instances for reading the request body.
         /// </param>
         public BodyModelBinder(IList<IInputFormatter> formatters, IHttpRequestStreamReaderFactory readerFactory)
+            : this(formatters, readerFactory, loggerFactory: null)
+        {
+        }
+
+        /// <summary>
+        /// Creates a new <see cref="BodyModelBinder"/>.
+        /// </summary>
+        /// <param name="formatters">The list of <see cref="IInputFormatter"/>.</param>
+        /// <param name="readerFactory">
+        /// The <see cref="IHttpRequestStreamReaderFactory"/>, used to create <see cref="System.IO.TextReader"/>
+        /// instances for reading the request body.
+        /// </param>
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public BodyModelBinder(IList<IInputFormatter> formatters, IHttpRequestStreamReaderFactory readerFactory, ILoggerFactory loggerFactory)
         {
             if (formatters == null)
             {
@@ -43,6 +59,11 @@ public BodyModelBinder(IList<IInputFormatter> formatters, IHttpRequestStreamRead
 
             _formatters = formatters;
             _readerFactory = readerFactory.CreateReader;
+
+            if (loggerFactory != null)
+            {
+                _logger = loggerFactory.CreateLogger<BodyModelBinder>();
+            }
         }
 
         /// <inheritdoc />
@@ -81,14 +102,19 @@ public async Task BindModelAsync(ModelBindingContext bindingContext)
                 if (_formatters[i].CanRead(formatterContext))
                 {
                     formatter = _formatters[i];
+                    _logger?.InputFormatterSelected(formatter, formatterContext);
                     break;
                 }
+                else
+                {
+                    _logger?.InputFormatterRejected(_formatters[i], formatterContext);
+                }
             }
 
             if (formatter == null)
             {
+                _logger?.NoInputFormatterSelected(formatterContext);
                 var message = Resources.FormatUnsupportedContentType(httpContext.Request.ContentType);
-
                 var exception = new UnsupportedContentTypeException(message);
                 bindingContext.ModelState.AddModelError(modelBindingKey, exception, bindingContext.ModelMetadata);
                 return;

src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinderProvider.cs

@@ -6,6 +6,7 @@
 using Microsoft.AspNetCore.Mvc.Core;
 using Microsoft.AspNetCore.Mvc.Formatters;
 using Microsoft.AspNetCore.Mvc.Internal;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders
 {
@@ -16,13 +17,25 @@ public class BodyModelBinderProvider : IModelBinderProvider
     {
         private readonly IList<IInputFormatter> _formatters;
         private readonly IHttpRequestStreamReaderFactory _readerFactory;
+        private readonly ILoggerFactory _loggerFactory;
 
         /// <summary>
         /// Creates a new <see cref="BodyModelBinderProvider"/>.
         /// </summary>
         /// <param name="formatters">The list of <see cref="IInputFormatter"/>.</param>
         /// <param name="readerFactory">The <see cref="IHttpRequestStreamReaderFactory"/>.</param>
         public BodyModelBinderProvider(IList<IInputFormatter> formatters, IHttpRequestStreamReaderFactory readerFactory)
+            : this(formatters, readerFactory, loggerFactory: null)
+        {
+        }
+
+        /// <summary>
+        /// Creates a new <see cref="BodyModelBinderProvider"/>.
+        /// </summary>
+        /// <param name="formatters">The list of <see cref="IInputFormatter"/>.</param>
+        /// <param name="readerFactory">The <see cref="IHttpRequestStreamReaderFactory"/>.</param>
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public BodyModelBinderProvider(IList<IInputFormatter> formatters, IHttpRequestStreamReaderFactory readerFactory, ILoggerFactory loggerFactory)
         {
             if (formatters == null)
             {
@@ -36,6 +49,7 @@ public BodyModelBinderProvider(IList<IInputFormatter> formatters, IHttpRequestSt
 
             _formatters = formatters;
             _readerFactory = readerFactory;
+            _loggerFactory = loggerFactory;
         }
 
         /// <inheritdoc />
@@ -57,7 +71,7 @@ public IModelBinder GetBinder(ModelBinderProviderContext context)
                         typeof(IInputFormatter).FullName));
                 }
 
-                return new BodyModelBinder(_formatters, _readerFactory);
+                return new BodyModelBinder(_formatters, _readerFactory, _loggerFactory);
             }
 
             return null;

test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderProviderTest.cs

@@ -5,6 +5,7 @@
 using System.Collections.Generic;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Mvc.Formatters;
+using Microsoft.Extensions.Logging.Testing;
 using Xunit;
 
 namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders
@@ -70,11 +71,28 @@ public void GetBinder_WhenBindingSourceIsFromBody_ReturnsBinder()
             Assert.IsType<BodyModelBinder>(result);
         }
 
+        [Fact]
+        public void GetBinder_DoesNotThrowNullReferenceException()
+        {
+            // Arrange
+            var context = new TestModelBinderProviderContext(typeof(Person));
+            context.BindingInfo.BindingSource = BindingSource.Body;
+            var formatter = new TestInputFormatter();
+            var formatterList = new List<IInputFormatter> { formatter };
+            var provider = new BodyModelBinderProvider(formatterList, new TestHttpRequestStreamReaderFactory());
+
+            // Act & Assert (does not throw)
+            provider.GetBinder(context);
+        }
+
         private static BodyModelBinderProvider CreateProvider(params IInputFormatter[] formatters)
         {
+            var sink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(sink, enabled: true);
             return new BodyModelBinderProvider(
                 new List<IInputFormatter>(formatters),
-                new TestHttpRequestStreamReaderFactory());
+                new TestHttpRequestStreamReaderFactory(),
+                loggerFactory);
         }
 
         private class Person