Added JSON request/response logging

Bart Koelman · Bart Koelman · commit d5dbf7243eb3 · 2020-04-07T08:21:11.000+02:00
diff --git a/benchmarks/Query/QueryParserBenchmarks.cs b/benchmarks/Query/QueryParserBenchmarks.cs
@@ -9,6 +9,7 @@
 using JsonApiDotNetCore.Services;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.WebUtilities;
+using Microsoft.Extensions.Logging.Abstractions;
 
 namespace Benchmarks.Query
 {
@@ -44,7 +45,7 @@ private static QueryParameterParser CreateQueryParameterDiscoveryForSort(IResour
                 sortService
             };
 
-            return new QueryParameterParser(options, queryStringAccessor, queryServices);
+            return new QueryParameterParser(options, queryStringAccessor, queryServices, NullLoggerFactory.Instance);
         }
 
         private static QueryParameterParser CreateQueryParameterDiscoveryForAll(IResourceGraph resourceGraph,
@@ -65,7 +66,7 @@ private static QueryParameterParser CreateQueryParameterDiscoveryForAll(IResourc
                 omitNullService
             };
 
-            return new QueryParameterParser(options, queryStringAccessor, queryServices);
+            return new QueryParameterParser(options, queryStringAccessor, queryServices, NullLoggerFactory.Instance);
         }
 
         [Benchmark]
diff --git a/src/JsonApiDotNetCore/Formatters/JsonApiReader.cs b/src/JsonApiDotNetCore/Formatters/JsonApiReader.cs
@@ -3,9 +3,9 @@
 using System.IO;
 using System.Threading.Tasks;
 using JsonApiDotNetCore.Exceptions;
-using JsonApiDotNetCore.Internal;
 using JsonApiDotNetCore.Models;
 using JsonApiDotNetCore.Serialization.Server;
+using Microsoft.AspNetCore.Http.Extensions;
 using Microsoft.AspNetCore.Mvc.Formatters;
 using Microsoft.Extensions.Logging;
 
@@ -22,8 +22,6 @@ public JsonApiReader(IJsonApiDeserializer deserializer,
         {
             _deserializer = deserializer;
             _logger = loggerFactory.CreateLogger<JsonApiReader>();
-
-            _logger.LogTrace("Executing constructor.");
         }
 
         public async Task<InputFormatterResult> ReadAsync(InputFormatterContext context)
@@ -39,6 +37,9 @@ public async Task<InputFormatterResult> ReadAsync(InputFormatterContext context)
 
             string body = await GetRequestBody(context.HttpContext.Request.Body);
 
+            string url = context.HttpContext.Request.GetEncodedUrl();
+            _logger.LogTrace($"Received request at '{url}' with body: <<{body}>>");
+
             object model;
             try
             {
diff --git a/src/JsonApiDotNetCore/Formatters/JsonApiWriter.cs b/src/JsonApiDotNetCore/Formatters/JsonApiWriter.cs
@@ -9,8 +9,10 @@
 using JsonApiDotNetCore.Middleware;
 using JsonApiDotNetCore.Models.JsonApiDocuments;
 using JsonApiDotNetCore.Serialization.Server;
+using Microsoft.AspNetCore.Http.Extensions;
 using Microsoft.AspNetCore.Mvc;
 using Microsoft.AspNetCore.Mvc.Formatters;
+using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
 
 namespace JsonApiDotNetCore.Formatters
@@ -23,11 +25,14 @@ public class JsonApiWriter : IJsonApiWriter
     {
         private readonly IJsonApiSerializer _serializer;
         private readonly IExceptionHandler _exceptionHandler;
+        private readonly ILogger<JsonApiWriter> _logger;
 
-        public JsonApiWriter(IJsonApiSerializer serializer, IExceptionHandler exceptionHandler)
+        public JsonApiWriter(IJsonApiSerializer serializer, IExceptionHandler exceptionHandler, ILoggerFactory loggerFactory)
         {
             _serializer = serializer;
             _exceptionHandler = exceptionHandler;
+
+            _logger = loggerFactory.CreateLogger<JsonApiWriter>();
         }
 
         public async Task WriteAsync(OutputFormatterWriteContext context)
@@ -59,6 +64,9 @@ public async Task WriteAsync(OutputFormatterWriteContext context)
                 }
             }
 
+            var url = context.HttpContext.Request.GetEncodedUrl();
+            _logger.LogTrace($"Sending {response.StatusCode} response for request at '{url}' with body: <<{responseContent}>>");
+
             await writer.WriteAsync(responseContent);
             await writer.FlushAsync();
         }
diff --git a/test/JsonApiDotNetCoreExampleTests/Acceptance/Extensibility/CustomErrorHandlingTests.cs b/test/JsonApiDotNetCoreExampleTests/Acceptance/Extensibility/CustomErrorHandlingTests.cs
@@ -76,40 +76,5 @@ public NoPermissionException(string customerCode) : base(new Error(HttpStatusCod
                 CustomerCode = customerCode;
             }
         }
-
-        internal sealed class FakeLoggerFactory : ILoggerFactory
-        {
-            public FakeLogger Logger { get; }
-
-            public FakeLoggerFactory()
-            {
-                Logger = new FakeLogger();
-            }
-
-            public ILogger CreateLogger(string categoryName) => Logger;
-
-            public void AddProvider(ILoggerProvider provider)
-            {
-            }
-
-            public void Dispose()
-            {
-            }
-
-            internal sealed class FakeLogger : ILogger
-            {
-                public List<(LogLevel LogLevel, string Text)> Messages = new List<(LogLevel, string)>();
-
-                public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
-                    Func<TState, Exception, string> formatter)
-                {
-                    var message = formatter(state, exception);
-                    Messages.Add((logLevel, message));
-                }
-
-                public bool IsEnabled(LogLevel logLevel) => true;
-                public IDisposable BeginScope<TState>(TState state) => null;
-            }
-        }
     }
 }
diff --git a/test/JsonApiDotNetCoreExampleTests/Acceptance/Spec/UpdatingDataTests.cs b/test/JsonApiDotNetCoreExampleTests/Acceptance/Spec/UpdatingDataTests.cs
@@ -5,6 +5,7 @@
 using System.Net.Http.Headers;
 using System.Threading.Tasks;
 using Bogus;
+using JsonApiDotNetCore.Formatters;
 using JsonApiDotNetCore.Models;
 using JsonApiDotNetCore.Models.JsonApiDocuments;
 using JsonApiDotNetCoreExample;
@@ -13,7 +14,9 @@
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.AspNetCore.TestHost;
 using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.Logging;
 using Newtonsoft.Json;
+using NLog.Extensions.Logging;
 using Xunit;
 using Person = JsonApiDotNetCoreExample.Models.Person;
 
@@ -64,6 +67,16 @@ public async Task Response422IfUpdatingNotSettableAttribute()
         {
             // Arrange
             var builder = new WebHostBuilder().UseStartup<Startup>();
+
+            var loggerFactory = new FakeLoggerFactory();
+            builder.ConfigureLogging(options =>
+            {
+                options.AddProvider(loggerFactory);
+                options.SetMinimumLevel(LogLevel.Trace);
+                options.AddFilter((category, level) => level == LogLevel.Trace && 
+                    (category == typeof(JsonApiReader).FullName || category == typeof(JsonApiWriter).FullName));
+            });
+
             var server = new TestServer(builder);
             var client = server.CreateClient();
 
@@ -89,6 +102,12 @@ public async Task Response422IfUpdatingNotSettableAttribute()
             Assert.Equal(HttpStatusCode.UnprocessableEntity, error.StatusCode);
             Assert.Equal("Failed to deserialize request body.", error.Title);
             Assert.StartsWith("Property set method not found. - Request body: <<", error.Detail);
+
+            Assert.NotEmpty(loggerFactory.Logger.Messages);
+            Assert.Contains(loggerFactory.Logger.Messages,
+                x => x.Text.StartsWith("Received request at ") && x.Text.Contains("with body:"));
+            Assert.Contains(loggerFactory.Logger.Messages,
+                x => x.Text.StartsWith("Sending 422 response for request at ") && x.Text.Contains("Failed to deserialize request body."));
         }
 
         [Fact]
diff --git a/test/JsonApiDotNetCoreExampleTests/FakeLoggerFactory.cs b/test/JsonApiDotNetCoreExampleTests/FakeLoggerFactory.cs
@@ -0,0 +1,41 @@
+using System;
+using System.Collections.Generic;
+using Microsoft.Extensions.Logging;
+
+namespace JsonApiDotNetCoreExampleTests
+{
+    internal sealed class FakeLoggerFactory : ILoggerFactory, ILoggerProvider
+    {
+        public FakeLogger Logger { get; }
+
+        public FakeLoggerFactory()
+        {
+            Logger = new FakeLogger();
+        }
+
+        public ILogger CreateLogger(string categoryName) => Logger;
+
+        public void AddProvider(ILoggerProvider provider)
+        {
+        }
+
+        public void Dispose()
+        {
+        }
+
+        internal sealed class FakeLogger : ILogger
+        {
+            public List<(LogLevel LogLevel, string Text)> Messages = new List<(LogLevel, string)>();
+
+            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
+                Func<TState, Exception, string> formatter)
+            {
+                var message = formatter(state, exception);
+                Messages.Add((logLevel, message));
+            }
+
+            public bool IsEnabled(LogLevel logLevel) => true;
+            public IDisposable BeginScope<TState>(TState state) => null;
+        }
+    }
+}

Original file line number	Diff line number	Diff line change
`@@ -9,6 +9,7 @@`
`9`	`9`	`using JsonApiDotNetCore.Services;`
`10`	`10`	`using Microsoft.AspNetCore.Http;`
`11`	`11`	`using Microsoft.AspNetCore.WebUtilities;`
	`12`	`+using Microsoft.Extensions.Logging.Abstractions;`
`12`	`13`
`13`	`14`	`namespace Benchmarks.Query`
`14`	`15`	`{`
`@@ -44,7 +45,7 @@ private static QueryParameterParser CreateQueryParameterDiscoveryForSort(IResour`
`44`	`45`	`sortService`
`45`	`46`	`};`
`46`	`47`
`47`		`- return new QueryParameterParser(options, queryStringAccessor, queryServices);`
	`48`	`+ return new QueryParameterParser(options, queryStringAccessor, queryServices, NullLoggerFactory.Instance);`
`48`	`49`	`}`
`49`	`50`
`50`	`51`	`private static QueryParameterParser CreateQueryParameterDiscoveryForAll(IResourceGraph resourceGraph,`
`@@ -65,7 +66,7 @@ private static QueryParameterParser CreateQueryParameterDiscoveryForAll(IResourc`
`65`	`66`	`omitNullService`
`66`	`67`	`};`
`67`	`68`
`68`		`- return new QueryParameterParser(options, queryStringAccessor, queryServices);`
	`69`	`+ return new QueryParameterParser(options, queryStringAccessor, queryServices, NullLoggerFactory.Instance);`
`69`	`70`	`}`
`70`	`71`
`71`	`72`	`[Benchmark]`
Original file line number	Diff line number	Diff line change
`@@ -9,8 +9,10 @@`
`9`	`9`	`using JsonApiDotNetCore.Middleware;`
`10`	`10`	`using JsonApiDotNetCore.Models.JsonApiDocuments;`
`11`	`11`	`using JsonApiDotNetCore.Serialization.Server;`
	`12`	`+using Microsoft.AspNetCore.Http.Extensions;`
`12`	`13`	`using Microsoft.AspNetCore.Mvc;`
`13`	`14`	`using Microsoft.AspNetCore.Mvc.Formatters;`
	`15`	`+using Microsoft.Extensions.Logging;`
`14`	`16`	`using Newtonsoft.Json;`
`15`	`17`
`16`	`18`	`namespace JsonApiDotNetCore.Formatters`
`@@ -23,11 +25,14 @@ public class JsonApiWriter : IJsonApiWriter`
`23`	`25`	`{`
`24`	`26`	`private readonly IJsonApiSerializer _serializer;`
`25`	`27`	`private readonly IExceptionHandler _exceptionHandler;`
	`28`	`+ private readonly ILogger<JsonApiWriter> _logger;`
`26`	`29`
`27`		`- public JsonApiWriter(IJsonApiSerializer serializer, IExceptionHandler exceptionHandler)`
	`30`	`+ public JsonApiWriter(IJsonApiSerializer serializer, IExceptionHandler exceptionHandler, ILoggerFactory loggerFactory)`
`28`	`31`	`{`
`29`	`32`	`_serializer = serializer;`
`30`	`33`	`_exceptionHandler = exceptionHandler;`
	`34`	`+`
	`35`	`+ _logger = loggerFactory.CreateLogger<JsonApiWriter>();`
`31`	`36`	`}`
`32`	`37`
`33`	`38`	`public async Task WriteAsync(OutputFormatterWriteContext context)`
`@@ -59,6 +64,9 @@ public async Task WriteAsync(OutputFormatterWriteContext context)`
`59`	`64`	`}`
`60`	`65`	`}`
`61`	`66`
	`67`	`+ var url = context.HttpContext.Request.GetEncodedUrl();`
	`68`	`+ _logger.LogTrace($"Sending {response.StatusCode} response for request at '{url}' with body: <<{responseContent}>>");`
	`69`	`+`
`62`	`70`	`await writer.WriteAsync(responseContent);`
`63`	`71`	`await writer.FlushAsync();`
`64`	`72`	`}`