Logging for content-negotiation

src/Microsoft.AspNet.Mvc.Core/ActionResults/ObjectResult.cs

@@ -2,7 +2,6 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Collections;
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading.Tasks;
@@ -11,6 +10,7 @@ using Microsoft.AspNet.Mvc.Core;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
 using Microsoft.Framework.Internal;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Microsoft.Net.Http.Headers;
 
@@ -40,9 +40,12 @@ namespace Microsoft.AspNet.Mvc
 
         public override async Task ExecuteResultAsync(ActionContext context)
         {
+            var logger = context.HttpContext.RequestServices.GetRequiredService<ILogger<ObjectResult>>();
+                            
             // See if the list of content types added to this object result is valid.
             ThrowIfUnsupportedContentType();
             var formatters = GetDefaultFormatters(context);
+
             var formatterContext = new OutputFormatterContext()
             {
                 DeclaredType = DeclaredType,
@@ -55,10 +58,18 @@ namespace Microsoft.AspNet.Mvc
             if (selectedFormatter == null)
             {
                 // No formatter supports this.
+                logger.LogWarning("No output formatter was found to write the response.");
+
                 context.HttpContext.Response.StatusCode = StatusCodes.Status406NotAcceptable;
                 return;
             }
 
+            logger.LogVerbose(
+                "Selected output formatter '{OutputFormatter}'and content type " +
+                "'{ContentType}' to write the response.", 
+                selectedFormatter.GetType().FullName,
+                formatterContext.SelectedContentType);
+
             if (StatusCode.HasValue)
             {
                 context.HttpContext.Response.StatusCode = StatusCode.Value;
@@ -72,10 +83,17 @@ namespace Microsoft.AspNet.Mvc
             OutputFormatterContext formatterContext,
             IEnumerable<IOutputFormatter> formatters)
         {
+            var logger = formatterContext.ActionContext.HttpContext.RequestServices
+                .GetRequiredService<ILogger<ObjectResult>>();
+
             // Check if any content-type was explicitly set (for example, via ProducesAttribute 
             // or Url path extension mapping). If yes, then ignore content-negotiation and use this content-type.
             if (ContentTypes.Count == 1)
             {
+                logger.LogVerbose(
+                    "Skipped content negotiation as content type '{ContentType}' is explicitly set for the response.", 
+                    ContentTypes[0]);
+
                 return SelectFormatterUsingAnyAcceptableContentType(formatterContext,
                                                                     formatters,
                                                                     ContentTypes);
@@ -94,6 +112,8 @@ namespace Microsoft.AspNet.Mvc
                     out requestContentType);
                 if (!sortedAcceptHeaderMediaTypes.Any() && requestContentType == null)
                 {
+                    logger.LogVerbose("No information found on request to perform content negotiation.");
+
                     return SelectFormatterBasedOnTypeMatch(formatterContext, formatters);
                 }
 
@@ -123,6 +143,8 @@ namespace Microsoft.AspNet.Mvc
                 // fallback on type based match.
                 if (selectedFormatter == null)
                 {
+                    logger.LogVerbose("Could not find an output formatter based on content negotiation.");
+
                     // Set this flag to indicate that content-negotiation has failed to let formatters decide
                     // if they want to write the response or not.
                     formatterContext.FailedContentNegotiation = true;

test/Microsoft.AspNet.Mvc.Core.Test/ActionResults/CreatedAtActionResultTests.cs

@@ -12,6 +12,7 @@ using Microsoft.AspNet.Http.Core.Collections;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.Testing;
 using Microsoft.AspNet.WebUtilities;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -101,6 +102,8 @@ namespace Microsoft.AspNet.Mvc
             optionsAccessor.Options.OutputFormatters.Add(new JsonOutputFormatter());
             services.Setup(p => p.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor);
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                       .Returns(new Mock<ILogger<ObjectResult>>().Object);
 
             var mockContextAccessor = new Mock<IScopedInstance<ActionBindingContext>>();
             mockContextAccessor

test/Microsoft.AspNet.Mvc.Core.Test/ActionResults/CreatedAtRouteResultTests.cs

@@ -11,6 +11,7 @@ using Microsoft.AspNet.Http.Core;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.Testing;
 using Microsoft.AspNet.WebUtilities;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -105,6 +106,8 @@ namespace Microsoft.AspNet.Mvc
             optionsAccessor.Options.OutputFormatters.Add(new JsonOutputFormatter());
             httpContext.Setup(o => o.RequestServices.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor);
+            httpContext.Setup(o => o.RequestServices.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
             httpContext.Setup(o => o.Response)
                        .Returns(response);
 

test/Microsoft.AspNet.Mvc.Core.Test/ActionResults/CreatedResultTests.cs

@@ -9,6 +9,7 @@ using Microsoft.AspNet.Http;
 using Microsoft.AspNet.Http.Core;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -94,6 +95,9 @@ namespace Microsoft.AspNet.Mvc
             httpContext
                 .Setup(p => p.RequestServices.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor);
+            httpContext
+                .Setup(p => p.RequestServices.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
 
             var mockActionBindingContext = new Mock<IScopedInstance<ActionBindingContext>>();
             mockActionBindingContext

test/Microsoft.AspNet.Mvc.Core.Test/ActionResults/HttpNotFoundObjectResultTest.cs

@@ -12,6 +12,7 @@ using Microsoft.AspNet.Http.Core;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -104,6 +105,8 @@ namespace Microsoft.AspNet.Mvc
                        .Returns(mockContextAccessor.Object);
             httpContext.Setup(o => o.RequestServices.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor);
+            httpContext.Setup(o => o.RequestServices.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
 
             return new ActionContext(httpContext.Object, new RouteData(), new ActionDescriptor());
         }

test/Microsoft.AspNet.Mvc.Core.Test/ActionResults/ObjectResultTests.cs

@@ -13,10 +13,10 @@ using Microsoft.AspNet.Mvc.Xml;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Microsoft.Net.Http.Headers;
 using Moq;
-using Newtonsoft.Json.Utilities;
 using Xunit;
 
 namespace Microsoft.AspNet.Mvc.Core.Test.ActionResults
@@ -671,10 +671,11 @@ namespace Microsoft.AspNet.Mvc.Core.Test.ActionResults
             var objectResult = new ObjectResult(new Person() { Name = "John" });
             objectResult.ContentTypes = contentTypes.Select(contentType => MediaTypeHeaderValue.Parse(contentType))
                                                     .ToList();
+            var actionContext = CreateMockActionContext();
 
             // Act & Assert
             var exception = await Assert.ThrowsAsync<InvalidOperationException>(
-                () => objectResult.ExecuteResultAsync(null));
+                () => objectResult.ExecuteResultAsync(actionContext));
 
             var expectedMessage = string.Format("The content-type '{0}' added in the 'ContentTypes' property is " +
               "invalid. Media types which match all types or match all subtypes are not supported.",
@@ -896,6 +897,8 @@ namespace Microsoft.AspNet.Mvc.Core.Test.ActionResults
             optionsAccessor.Options.RespectBrowserAcceptHeader = respectBrowserAcceptHeader;
             httpContext.Setup(o => o.RequestServices.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor);
+            httpContext.Setup(o => o.RequestServices.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
 
             var mockActionBindingContext = new Mock<IScopedInstance<ActionBindingContext>>();
 

test/Microsoft.AspNet.Mvc.Core.Test/ControllerActionInvokerTest.cs

@@ -14,6 +14,8 @@ using Microsoft.AspNet.Mvc.ModelBinding;
 using Microsoft.AspNet.Mvc.ModelBinding.Validation;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.Testing;
+using Microsoft.Framework.Logging;
+using Microsoft.Framework.Logging.Testing;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -1995,6 +1997,8 @@ namespace Microsoft.AspNet.Mvc
             httpContext.SetupGet(c => c.Response).Returns(httpResponse);
             httpContext.Setup(o => o.RequestServices.GetService(typeof(ITempDataDictionary)))
                        .Returns(tempData);
+            httpContext.Setup(o => o.RequestServices.GetService(typeof(ILogger<ObjectResult>)))
+                       .Returns(new Mock<ILogger<ObjectResult>>().Object);
             httpResponse.Body = new MemoryStream();
 
             var options = new MvcOptions();
@@ -2078,6 +2082,8 @@ namespace Microsoft.AspNet.Mvc
                    .Returns(new Dictionary<object, object>());
             context.Setup(c => c.RequestServices.GetService(typeof(ITempDataDictionary)))
                        .Returns(new Mock<ITempDataDictionary>().Object);
+            context.Setup(c => c.RequestServices.GetService(typeof(ILoggerFactory)))
+                       .Returns(new NullLoggerFactory());
 
             var actionContext = new ActionContext(context.Object, new RouteData(), actionDescriptor);
 

test/Microsoft.AspNet.Mvc.Core.Test/JsonResultTest.cs

@@ -15,6 +15,7 @@ using Microsoft.Framework.OptionsModel;
 using Microsoft.Net.Http.Headers;
 using Moq;
 using Xunit;
+using Microsoft.Framework.Logging;
 
 namespace Microsoft.AspNet.Mvc
 {
@@ -200,6 +201,8 @@ namespace Microsoft.AspNet.Mvc
 
             services.Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor.Object);
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
 
             // This is the ultimate fallback, it will be used if none of the formatters from options
             // work.

test/Microsoft.AspNet.Mvc.WebApiCompatShimTest/ActionResults/BadRequestErrorMessageResultTest.cs

@@ -10,6 +10,8 @@ using Microsoft.AspNet.Mvc;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
+using Microsoft.Framework.Logging.Testing;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -86,6 +88,9 @@ namespace System.Web.Http
             services.Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor.Object);
 
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
+
             return services.Object;
         }
     }

test/Microsoft.AspNet.Mvc.WebApiCompatShimTest/ActionResults/ExceptionResultTest.cs

@@ -10,6 +10,7 @@ using Microsoft.AspNet.Mvc;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -86,6 +87,8 @@ namespace System.Web.Http
             services.Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor.Object);
 
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
 
             return services.Object;
         }

test/Microsoft.AspNet.Mvc.WebApiCompatShimTest/ActionResults/InvalidModelStateResultTest.cs

@@ -11,6 +11,8 @@ using Microsoft.AspNet.Mvc.ModelBinding;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
+using Microsoft.Framework.Logging.Testing;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -100,6 +102,9 @@ namespace System.Web.Http
             services.Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor.Object);
 
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
+
             return services.Object;
         }
     }

test/Microsoft.AspNet.Mvc.WebApiCompatShimTest/ActionResults/NegotiatedContentResultTest.cs

@@ -10,6 +10,8 @@ using Microsoft.AspNet.Http.Core;
 using Microsoft.AspNet.Mvc;
 using Microsoft.AspNet.Routing;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
+using Microsoft.Framework.Logging.Testing;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -87,6 +89,9 @@ namespace System.Web.Http
             services.Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor.Object);
 
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
+
             return services.Object;
         }
 

test/Microsoft.AspNet.Mvc.WebApiCompatShimTest/ActionResults/OkNegotiatedContentResultTest.cs

@@ -9,6 +9,8 @@ using Microsoft.AspNet.Mvc;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.WebUtilities;
 using Microsoft.Framework.DependencyInjection;
+using Microsoft.Framework.Logging;
+using Microsoft.Framework.Logging.Testing;
 using Microsoft.Framework.OptionsModel;
 using Moq;
 using Xunit;
@@ -60,6 +62,9 @@ namespace System.Web.Http
             services.Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor.Object);
 
+            services.Setup(s => s.GetService(typeof(ILogger<ObjectResult>)))
+                .Returns(new Mock<ILogger<ObjectResult>>().Object);
+
             return services.Object;
         }
 

test/Microsoft.AspNet.Mvc.WebApiCompatShimTest/project.json

@@ -5,6 +5,7 @@
     "dependencies": {
         "Microsoft.AspNet.Mvc.WebApiCompatShim": "6.0.0-*",
         "Microsoft.AspNet.Testing": "1.0.0-*",
+        "Microsoft.Framework.Logging.Testing": "1.0.0-*",
         "Moq": "4.2.1312.1622",
         "xunit.runner.aspnet": "2.0.0-aspnet-*"
     },