diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Formatters/MediaType.cs b/src/Microsoft.AspNetCore.Mvc.Core/Formatters/MediaType.cs index 7aaa9715c4..4835e11606 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Formatters/MediaType.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Formatters/MediaType.cs @@ -41,7 +41,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters /// /// The with the media type. /// The offset in the where the parsing starts. - /// The of the media type to parse if provided. + /// The length of the media type to parse if provided. public MediaType(string mediaType, int offset, int? length) { if (mediaType == null) diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs index 91f1cb299c..5131e0a064 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs @@ -56,6 +56,11 @@ namespace Microsoft.AspNetCore.Mvc.Internal private static readonly Action _noAcceptForNegotiation; private static readonly Action, Exception> _noFormatterFromNegotiation; + private static readonly Action _inputFormatterSelected; + private static readonly Action _inputFormatterRejected; + private static readonly Action _noInputFormatterSelected; + private static readonly Action _removeFromBodyAttribute; + private static readonly Action _redirectResultExecuting; private static readonly Action _redirectToActionResultExecuting; @@ -184,6 +189,26 @@ namespace Microsoft.AspNetCore.Mvc.Internal 5, "Could not find an output formatter based on content negotiation. Accepted types were ({AcceptTypes})"); + _inputFormatterSelected = LoggerMessage.Define( + LogLevel.Debug, + 1, + "Selected input formatter '{InputFormatter}' for content type '{ContentType}'."); + + _inputFormatterRejected = LoggerMessage.Define( + LogLevel.Debug, + 2, + "Rejected input formatter '{InputFormatter}' for content type '{ContentType}'."); + + _noInputFormatterSelected = LoggerMessage.Define( + LogLevel.Debug, + 3, + "No input formatter was found to support the content type '{ContentType}' for use with the [FromBody] attribute."); + + _removeFromBodyAttribute = LoggerMessage.Define( + 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( LogLevel.Information, 1, @@ -401,6 +426,47 @@ namespace Microsoft.AspNetCore.Mvc.Internal _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 @@ namespace Microsoft.AspNetCore.Mvc.Internal return new KeyValuePair("ActionName", _action.DisplayName); } throw new IndexOutOfRangeException(nameof(index)); - } + } } public int Count diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreMvcOptionsSetup.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreMvcOptionsSetup.cs index 830aeeb7f6..91e138301b 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreMvcOptionsSetup.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreMvcOptionsSetup.cs @@ -9,6 +9,7 @@ using Microsoft.AspNetCore.Mvc.Formatters; 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,8 +20,14 @@ namespace Microsoft.AspNetCore.Mvc.Internal public class MvcCoreMvcOptionsSetup : IConfigureOptions { 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) { @@ -28,6 +35,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal } _readerFactory = readerFactory; + _loggerFactory = loggerFactory; } public void Configure(MvcOptions options) @@ -35,7 +43,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal // 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()); diff --git a/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinder.cs b/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinder.cs index 19b2c76e0a..183e44b204 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinder.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinder.cs @@ -9,6 +9,7 @@ using System.Threading.Tasks; 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 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders { private readonly IList _formatters; private readonly Func _readerFactory; + private readonly ILogger _logger; /// /// Creates a new . @@ -30,6 +32,20 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders /// instances for reading the request body. /// public BodyModelBinder(IList formatters, IHttpRequestStreamReaderFactory readerFactory) + : this(formatters, readerFactory, loggerFactory: null) + { + } + + /// + /// Creates a new . + /// + /// The list of . + /// + /// The , used to create + /// instances for reading the request body. + /// + /// The . + public BodyModelBinder(IList formatters, IHttpRequestStreamReaderFactory readerFactory, ILoggerFactory loggerFactory) { if (formatters == null) { @@ -43,6 +59,11 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders _formatters = formatters; _readerFactory = readerFactory.CreateReader; + + if (loggerFactory != null) + { + _logger = loggerFactory.CreateLogger(); + } } /// @@ -81,14 +102,19 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders 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; diff --git a/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinderProvider.cs b/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinderProvider.cs index d3f16b1088..f8cc052621 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinderProvider.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/ModelBinding/Binders/BodyModelBinderProvider.cs @@ -6,6 +6,7 @@ using System.Collections.Generic; 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,6 +17,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders { private readonly IList _formatters; private readonly IHttpRequestStreamReaderFactory _readerFactory; + private readonly ILoggerFactory _loggerFactory; /// /// Creates a new . @@ -23,6 +25,17 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders /// The list of . /// The . public BodyModelBinderProvider(IList formatters, IHttpRequestStreamReaderFactory readerFactory) + : this(formatters, readerFactory, loggerFactory: null) + { + } + + /// + /// Creates a new . + /// + /// The list of . + /// The . + /// The . + public BodyModelBinderProvider(IList formatters, IHttpRequestStreamReaderFactory readerFactory, ILoggerFactory loggerFactory) { if (formatters == null) { @@ -36,6 +49,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders _formatters = formatters; _readerFactory = readerFactory; + _loggerFactory = loggerFactory; } /// @@ -57,7 +71,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders typeof(IInputFormatter).FullName)); } - return new BodyModelBinder(_formatters, _readerFactory); + return new BodyModelBinder(_formatters, _readerFactory, _loggerFactory); } return null; diff --git a/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderProviderTest.cs b/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderProviderTest.cs index ff64a9bf4d..d16bffe4ba 100644 --- a/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderProviderTest.cs +++ b/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderProviderTest.cs @@ -5,6 +5,7 @@ using System; 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 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders Assert.IsType(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 { 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(formatters), - new TestHttpRequestStreamReaderFactory()); + new TestHttpRequestStreamReaderFactory(), + loggerFactory); } private class Person diff --git a/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderTests.cs b/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderTests.cs index d6b7a55f44..fda1a0c936 100644 --- a/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderTests.cs +++ b/test/Microsoft.AspNetCore.Mvc.Core.Test/ModelBinding/Binders/BodyModelBinderTests.cs @@ -4,11 +4,11 @@ using System; using System.Collections.Generic; using System.IO; -using System.Linq; using System.Text; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc.Formatters; +using Microsoft.Extensions.Logging.Testing; using Microsoft.Net.Http.Headers; using Moq; using Xunit; @@ -195,7 +195,6 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders var provider = new TestModelMetadataProvider(); provider.ForType().BindingDetails(d => d.BindingSource = BindingSource.Body); var bindingContext = GetBindingContext(typeof(Person), metadataProvider: provider); - var binder = CreateBinder(inputFormatters); // Act @@ -206,6 +205,84 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders Assert.Same(canReadFormatter1, bindingContext.Result.Model); } + [Fact] + public async Task BindModelAsync_LogsFormatterRejectionAndSelection() + { + // Arrange + var sink = new TestSink(); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var inputFormatters = new List() + { + new TestInputFormatter(canRead: false), + new TestInputFormatter(canRead: true), + }; + + var provider = new TestModelMetadataProvider(); + provider.ForType().BindingDetails(d => d.BindingSource = BindingSource.Body); + var bindingContext = GetBindingContext(typeof(Person), metadataProvider: provider); + bindingContext.HttpContext.Request.ContentType = "application/json"; + var binder = new BodyModelBinder(inputFormatters, new TestHttpRequestStreamReaderFactory(), loggerFactory); + + // Act + await binder.BindModelAsync(bindingContext); + + // Assert + Assert.Equal($"Rejected input formatter '{typeof(TestInputFormatter)}' for content type 'application/json'.", sink.Writes[0].State.ToString()); + Assert.Equal($"Selected input formatter '{typeof(TestInputFormatter)}' for content type 'application/json'.", sink.Writes[1].State.ToString()); + } + + [Fact] + public async Task BindModelAsync_LogsNoFormatterSelectedAndRemoveFromBodyAttribute() + { + // Arrange + var sink = new TestSink(); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + var inputFormatters = new List() + { + new TestInputFormatter(canRead: false), + new TestInputFormatter(canRead: false), + }; + + var provider = new TestModelMetadataProvider(); + provider.ForType().BindingDetails(d => d.BindingSource = BindingSource.Body); + var bindingContext = GetBindingContext(typeof(Person), metadataProvider: provider); + bindingContext.HttpContext.Request.ContentType = "multipart/form-data"; + bindingContext.BinderModelName = bindingContext.ModelName; + var binder = new BodyModelBinder(inputFormatters, new TestHttpRequestStreamReaderFactory(), loggerFactory); + + // Act + await binder.BindModelAsync(bindingContext); + + // Assert + Assert.Collection( + sink.Writes, + write => Assert.Equal( + $"Rejected input formatter '{typeof(TestInputFormatter)}' for content type 'multipart/form-data'.", write.State.ToString()), + write => Assert.Equal( + $"Rejected input formatter '{typeof(TestInputFormatter)}' for content type 'multipart/form-data'.", write.State.ToString()), + write => Assert.Equal( + "No input formatter was found to support the content type 'multipart/form-data' for use with the [FromBody] attribute.", write.State.ToString()), + write => Assert.Equal( + $"To use model binding, remove the [FromBody] attribute from the property or parameter named '{bindingContext.ModelName}' with model type '{bindingContext.ModelType}'.", write.State.ToString())); + } + + [Fact] + public async Task BindModelAsync_DoesNotThrowNullReferenceException() + { + // Arrange + var httpContext = new DefaultHttpContext(); + var provider = new TestModelMetadataProvider(); + provider.ForType().BindingDetails(d => d.BindingSource = BindingSource.Body); + var bindingContext = GetBindingContext( + typeof(Person), + httpContext: httpContext, + metadataProvider: provider); + var binder = new BodyModelBinder(new List(), new TestHttpRequestStreamReaderFactory()); + + // Act & Assert (does not throw) + await binder.BindModelAsync(bindingContext); + } + private static DefaultModelBindingContext GetBindingContext( Type modelType, HttpContext httpContext = null, @@ -241,7 +318,9 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders private static BodyModelBinder CreateBinder(IList formatters) { - return new BodyModelBinder(formatters, new TestHttpRequestStreamReaderFactory()); + var sink = new TestSink(); + var loggerFactory = new TestLoggerFactory(sink, enabled: true); + return new BodyModelBinder(formatters, new TestHttpRequestStreamReaderFactory(), loggerFactory); } private class Person