Log exceptions in JsonInputFormatter

src/Microsoft.AspNet.Mvc.Formatters.Json/Internal/MvcJsonMvcOptionsSetup.cs

@@ -1,6 +1,7 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.OptionsModel;
 using Microsoft.Net.Http.Headers;
 using Newtonsoft.Json;
@@ -10,18 +11,23 @@ namespace Microsoft.AspNet.Mvc.Formatters.Json.Internal
 {
     public class MvcJsonMvcOptionsSetup : ConfigureOptions<MvcOptions>
     {
-        public MvcJsonMvcOptionsSetup(IOptions<MvcJsonOptions> jsonOptions)
-            : base((_) => ConfigureMvc(_, jsonOptions.Value.SerializerSettings))
+        public MvcJsonMvcOptionsSetup(ILoggerFactory loggerFactory, IOptions<MvcJsonOptions> jsonOptions)
+            : base((_) => ConfigureMvc(_, jsonOptions.Value.SerializerSettings, loggerFactory))
         {
         }
 
-        public static void ConfigureMvc(MvcOptions options, JsonSerializerSettings serializerSettings)
+        public static void ConfigureMvc(
+            MvcOptions options,
+            JsonSerializerSettings serializerSettings,
+            ILoggerFactory loggerFactory)
         {
-            options.OutputFormatters.Add(new JsonOutputFormatter(serializerSettings));
-
-            options.InputFormatters.Add(new JsonInputFormatter(serializerSettings));
-            options.InputFormatters.Add(new JsonPatchInputFormatter(serializerSettings));
+            var jsonInputLogger = loggerFactory.CreateLogger<JsonInputFormatter>();
+            var jsonInputPatchLogger = loggerFactory.CreateLogger<JsonPatchInputFormatter>();
 
+            options.OutputFormatters.Add(new JsonOutputFormatter(serializerSettings));
+            options.InputFormatters.Add(new JsonInputFormatter(jsonInputLogger, serializerSettings));
+            options.InputFormatters.Add(new JsonPatchInputFormatter(jsonInputPatchLogger, serializerSettings));
+
             options.FormatterMappings.SetMediaTypeMappingForFormat("json", MediaTypeHeaderValue.Parse("application/json"));
 
             options.ValidationExcludeFilters.Add(typeof(JToken));

src/Microsoft.AspNet.Mvc.Formatters.Json/JsonInputFormatter.cs

@@ -2,32 +2,39 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.IO;
-using System.Text;
 using System.Threading.Tasks;
-using Microsoft.AspNet.Mvc.Infrastructure;
+using Microsoft.AspNet.Mvc.Formatters.Json.Logging;
 using Microsoft.AspNet.Mvc.Internal;
 using Microsoft.AspNet.Mvc.ModelBinding;
+using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
 
 namespace Microsoft.AspNet.Mvc.Formatters
 {
     public class JsonInputFormatter : InputFormatter
     {
         private JsonSerializerSettings _serializerSettings;
+        private ILogger _logger;
 
-        public JsonInputFormatter()
-            : this(SerializerSettingsProvider.CreateSerializerSettings())
+
+        public JsonInputFormatter(ILogger logger)
+            : this(logger, SerializerSettingsProvider.CreateSerializerSettings())
         {
         }
 
-        public JsonInputFormatter(JsonSerializerSettings serializerSettings)
+        public JsonInputFormatter(ILogger logger, JsonSerializerSettings serializerSettings)
         {
             if (serializerSettings == null)
             {
                 throw new ArgumentNullException(nameof(serializerSettings));
             }
 
+            if (logger == null)
+            {
+                throw new ArgumentNullException(nameof(logger));
+            }
+
+            _logger = logger;
             _serializerSettings = serializerSettings;
 
             SupportedEncodings.Add(UTF8EncodingWithoutBOM);
@@ -107,6 +114,8 @@ public override Task<InputFormatterResult> ReadRequestBodyAsync(InputFormatterCo
                         var metadata = GetPathMetadata(context.Metadata, eventArgs.ErrorContext.Path);
                         context.ModelState.TryAddModelError(key, eventArgs.ErrorContext.Error, metadata);
 
+                        _logger.JsonInputException(eventArgs.ErrorContext.Error);
+
                         // Error must always be marked as handled
                         // Failure to do so can cause the exception to be rethrown at every recursive level and
                         // overflow the stack for x64 CLR processes

src/Microsoft.AspNet.Mvc.Formatters.Json/JsonPatchInputFormatter.cs

@@ -6,19 +6,20 @@
 using System.Threading.Tasks;
 using Microsoft.AspNet.JsonPatch;
 using Microsoft.AspNet.Mvc.Internal;
+using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
 
 namespace Microsoft.AspNet.Mvc.Formatters
 {
     public class JsonPatchInputFormatter : JsonInputFormatter
     {
-        public JsonPatchInputFormatter()
-            : this(SerializerSettingsProvider.CreateSerializerSettings())
+        public JsonPatchInputFormatter(ILogger logger)
+            : this(logger, SerializerSettingsProvider.CreateSerializerSettings())
         {
         }
 
-        public JsonPatchInputFormatter(JsonSerializerSettings serializerSettings)
-            : base(serializerSettings)
+        public JsonPatchInputFormatter(ILogger logger, JsonSerializerSettings serializerSettings)
+            : base(logger, serializerSettings)
         {
             // Clear all values and only include json-patch+json value.
             SupportedMediaTypes.Clear();

src/Microsoft.AspNet.Mvc.Formatters.Json/Logging/JsonInputFormatterLoggerExtensions.cs

@@ -0,0 +1,23 @@
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNet.Mvc.Formatters.Json.Logging
+{
+    internal static class JsonInputFormatterLoggerExtensions
+    {
+        private static readonly Action<ILogger, string, Exception> _jsonInputFormatterCrashed;
+
+        static JsonInputFormatterLoggerExtensions()
+        {
+            _jsonInputFormatterCrashed = LoggerMessage.Define<string>(
+                LogLevel.Verbose,
+                1,
+                "JSON input formatter threw an exception.");
+        }
+
+        public static void JsonInputException(this ILogger logger, Exception exception)
+        {
+            _jsonInputFormatterCrashed(logger, exception.ToString(), exception);
+        }
+    }
+}

test/Microsoft.AspNet.Mvc.Formatters.Json.Test/JsonInputFormatterTest.cs

@@ -9,6 +9,8 @@
 using System.Threading.Tasks;
 using Microsoft.AspNet.Http;
 using Microsoft.AspNet.Mvc.ModelBinding;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Moq;
 using Newtonsoft.Json;
 using Newtonsoft.Json.Serialization;
@@ -33,7 +35,9 @@ public class JsonInputFormatterTest
         public void CanRead_ReturnsTrueForAnySupportedContentType(string requestContentType, bool expectedCanRead)
         {
             // Arrange
-            var formatter = new JsonInputFormatter();
+            var loggerMock = GetLogger();
+
+            var formatter = new JsonInputFormatter(loggerMock);
             var contentBytes = Encoding.UTF8.GetBytes("content");
 
             var httpContext = GetHttpContext(contentBytes, contentType: requestContentType);
@@ -57,7 +61,8 @@ public void CanRead_ReturnsTrueForAnySupportedContentType(string requestContentT
         public void DefaultMediaType_ReturnsApplicationJson()
         {
             // Arrange
-            var formatter = new JsonInputFormatter();
+            var loggerMock = GetLogger();
+            var formatter = new JsonInputFormatter(loggerMock);
 
             // Act
             var mediaType = formatter.SupportedMediaTypes[0];
@@ -82,7 +87,8 @@ public static IEnumerable<object[]> JsonFormatterReadSimpleTypesData
         public async Task JsonFormatterReadsSimpleTypes(string content, Type type, object expected)
         {
             // Arrange
-            var formatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonInputFormatter(logger);
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
             var httpContext = GetHttpContext(contentBytes);
@@ -108,7 +114,8 @@ public async Task JsonFormatterReadsComplexTypes()
         {
             // Arrange
             var content = "{name: 'Person Name', Age: '30'}";
-            var formatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonInputFormatter(logger);
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
             var httpContext = GetHttpContext(contentBytes);
@@ -136,7 +143,8 @@ public async Task ReadAsync_AddsModelValidationErrorsToModelState()
         {
             // Arrange
             var content = "{name: 'Person Name', Age: 'not-an-age'}";
-            var formatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonInputFormatter(logger);
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
             var modelState = new ModelStateDictionary();
@@ -165,7 +173,8 @@ public async Task ReadAsync_InvalidArray_AddsOverflowErrorsToModelState()
         {
             // Arrange
             var content = "[0, 23, 300]";
-            var formatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonInputFormatter(logger);
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
             var modelState = new ModelStateDictionary();
@@ -193,7 +202,8 @@ public async Task ReadAsync_InvalidComplexArray_AddsOverflowErrorsToModelState()
         {
             // Arrange
             var content = "[{name: 'Name One', Age: 30}, {name: 'Name Two', Small: 300}]";
-            var formatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonInputFormatter(logger);
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
             var modelState = new ModelStateDictionary();
@@ -222,7 +232,8 @@ public async Task ReadAsync_UsesTryAddModelValidationErrorsToModelState()
         {
             // Arrange
             var content = "{name: 'Person Name', Age: 'not-an-age'}";
-            var formatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonInputFormatter(logger);
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
             var modelState = new ModelStateDictionary();
@@ -254,8 +265,10 @@ public async Task ReadAsync_UsesTryAddModelValidationErrorsToModelState()
         public void Creates_SerializerSettings_ByDefault()
         {
             // Arrange
+            var logger = GetLogger();
+
             // Act
-            var jsonFormatter = new JsonInputFormatter();
+            var jsonFormatter = new JsonInputFormatter(logger);
 
             // Assert
             Assert.NotNull(jsonFormatter.SerializerSettings);
@@ -265,9 +278,11 @@ public void Creates_SerializerSettings_ByDefault()
         public void Constructor_UsesSerializerSettings()
         {
             // Arrange
+            var logger = GetLogger();
+
             // Act
             var serializerSettings = new JsonSerializerSettings();
-            var jsonFormatter = new JsonInputFormatter(serializerSettings);
+            var jsonFormatter = new JsonInputFormatter(logger, serializerSettings);
 
             // Assert
             Assert.Same(serializerSettings, jsonFormatter.SerializerSettings);
@@ -279,8 +294,8 @@ public async Task ChangesTo_DefaultSerializerSettings_TakesEffect()
             // Arrange
             // missing password property here
             var contentBytes = Encoding.UTF8.GetBytes("{ \"UserName\" : \"John\"}");
-
-            var jsonFormatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var jsonFormatter = new JsonInputFormatter(logger);
             // by default we ignore missing members, so here explicitly changing it
             jsonFormatter.SerializerSettings.MissingMemberHandling = MissingMemberHandling.Error;
 
@@ -312,8 +327,8 @@ public async Task CustomSerializerSettingsObject_TakesEffect()
             // Arrange
             // missing password property here
             var contentBytes = Encoding.UTF8.GetBytes("{ \"UserName\" : \"John\"}");
-
-            var jsonFormatter = new JsonInputFormatter();
+            var logger = GetLogger();
+            var jsonFormatter = new JsonInputFormatter(logger);
             // by default we ignore missing members, so here explicitly changing it
             jsonFormatter.SerializerSettings = new JsonSerializerSettings()
             {
@@ -342,6 +357,11 @@ public async Task CustomSerializerSettingsObject_TakesEffect()
             Assert.Contains("Required property 'Password' not found in JSON", modelErrorMessage);
         }
 
+        private static ILogger GetLogger()
+        {
+            return NullLogger.Instance;
+        }
+
         private static HttpContext GetHttpContext(
             byte[] contentBytes,
             string contentType = "application/json")

test/Microsoft.AspNet.Mvc.Formatters.Json.Test/JsonOutputFormatterTests.cs

@@ -12,6 +12,8 @@
 using Microsoft.AspNet.Mvc.Internal;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.Testing;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Net.Http.Headers;
 using Moq;
 using Newtonsoft.Json;
@@ -40,7 +42,8 @@ public void Constructor_UsesSerializerSettings()
             // Arrange
             // Act
             var serializerSettings = new JsonSerializerSettings();
-            var jsonFormatter = new JsonInputFormatter(serializerSettings);
+            var logger = GetLogger();
+            var jsonFormatter = new JsonInputFormatter(logger, serializerSettings);
 
             // Assert
             Assert.Same(serializerSettings, jsonFormatter.SerializerSettings);
@@ -290,6 +293,11 @@ private static Encoding CreateOrGetSupportedEncoding(
             return encoding;
         }
 
+        private static ILogger GetLogger()
+        {
+            return NullLogger.Instance;
+        }
+
         private static OutputFormatterWriteContext GetOutputFormatterContext(
             object outputValue,
             Type outputType,

test/Microsoft.AspNet.Mvc.Formatters.Json.Test/JsonPatchInputFormatterTest.cs

@@ -8,6 +8,8 @@
 using Microsoft.AspNet.Http;
 using Microsoft.AspNet.JsonPatch;
 using Microsoft.AspNet.Mvc.ModelBinding;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Moq;
 using Xunit;
 
@@ -19,7 +21,8 @@ public class JsonPatchInputFormatterTest
         public async Task JsonPatchInputFormatter_ReadsOneOperation_Successfully()
         {
             // Arrange
-            var formatter = new JsonPatchInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonPatchInputFormatter(logger);
             var content = "[{\"op\":\"add\",\"path\":\"Customer/Name\",\"value\":\"John\"}]";
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
@@ -49,7 +52,8 @@ public async Task JsonPatchInputFormatter_ReadsOneOperation_Successfully()
         public async Task JsonPatchInputFormatter_ReadsMultipleOperations_Successfully()
         {
             // Arrange
-            var formatter = new JsonPatchInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonPatchInputFormatter(logger);
             var content = "[{\"op\": \"add\", \"path\" : \"Customer/Name\", \"value\":\"John\"}," +
                 "{\"op\": \"remove\", \"path\" : \"Customer/Name\"}]";
             var contentBytes = Encoding.UTF8.GetBytes(content);
@@ -86,7 +90,8 @@ public async Task JsonPatchInputFormatter_ReadsMultipleOperations_Successfully()
         public void CanRead_ReturnsTrueOnlyForJsonPatchContentType(string requestContentType, bool expectedCanRead)
         {
             // Arrange
-            var formatter = new JsonPatchInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonPatchInputFormatter(logger);
             var content = "[{\"op\": \"add\", \"path\" : \"Customer/Name\", \"value\":\"John\"}]";
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
@@ -114,7 +119,8 @@ public void CanRead_ReturnsTrueOnlyForJsonPatchContentType(string requestContent
         public void CanRead_ReturnsFalse_NonJsonPatchContentType(Type modelType)
         {
             // Arrange
-            var formatter = new JsonPatchInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonPatchInputFormatter(logger);
             var content = "[{\"op\": \"add\", \"path\" : \"Customer/Name\", \"value\":\"John\"}]";
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
@@ -143,7 +149,8 @@ public async Task JsonPatchInputFormatter_ReturnsModelStateErrors_InvalidModelTy
             var exceptionMessage = "Cannot deserialize the current JSON array (e.g. [1,2,3]) into type " +
                 $"'{typeof(Customer).FullName}' because the type requires a JSON object ";
 
-            var formatter = new JsonPatchInputFormatter();
+            var logger = GetLogger();
+            var formatter = new JsonPatchInputFormatter(logger);
             var content = "[{\"op\": \"add\", \"path\" : \"Customer/Name\", \"value\":\"John\"}]";
             var contentBytes = Encoding.UTF8.GetBytes(content);
 
@@ -166,6 +173,11 @@ public async Task JsonPatchInputFormatter_ReturnsModelStateErrors_InvalidModelTy
             Assert.Contains(exceptionMessage, modelState[""].Errors[0].Exception.Message);
         }
 
+        private static ILogger GetLogger()
+        {
+            return NullLogger.Instance;
+        }
+
         private static HttpContext GetHttpContext(
             byte[] contentBytes,
             string contentType = "application/json-patch+json")