From bcf7b7271010d2d9a1e91523c13eeb662766eba2 Mon Sep 17 00:00:00 2001
From: Miguel Veloso <mvelosop@gmail.com>
Date: Fri, 31 May 2019 17:19:42 +0100
Subject: [PATCH] Add logging middleware

---
 docker-compose.override.yml                   |  2 +
 .../WebMVC/Middleware/SerilogMiddleware.cs    | 95 +++++++++++++++++++
 src/Web/WebMVC/Startup.cs                     |  5 +-
 3 files changed, 101 insertions(+), 1 deletion(-)
 create mode 100644 src/Web/WebMVC/Middleware/SerilogMiddleware.cs

diff --git a/docker-compose.override.yml b/docker-compose.override.yml
index 563d712c1..2c6617fc9 100644
--- a/docker-compose.override.yml
+++ b/docker-compose.override.yml
@@ -403,6 +403,8 @@ services:
       - ApplicationInsights__InstrumentationKey=${INSTRUMENTATION_KEY}
       - OrchestratorType=${ORCHESTRATOR_TYPE}
       - UseLoadTest=${USE_LOADTEST:-False}
+      - Serilog__MinimumLevel__Default=Verbose
+      - Serilog__MinimumLevel__Override__Microsoft.eShopOnContainers=Verbose
     ports:
       - "5100:80"
 
diff --git a/src/Web/WebMVC/Middleware/SerilogMiddleware.cs b/src/Web/WebMVC/Middleware/SerilogMiddleware.cs
new file mode 100644
index 000000000..ee6e4dd89
--- /dev/null
+++ b/src/Web/WebMVC/Middleware/SerilogMiddleware.cs
@@ -0,0 +1,95 @@
+using Microsoft.AspNetCore.Http;
+using Serilog;
+using Serilog.Events;
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.IO;
+using System.Linq;
+using System.Threading.Tasks;
+
+// taken from https://blog.datalust.co/smart-logging-middleware-for-asp-net-core/
+
+namespace Datalust.SerilogMiddlewareExample.Diagnostics
+{
+    public class SerilogMiddleware
+    {
+        private const string MessageTemplate =
+            "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms";
+
+        private static readonly ILogger Logger = Serilog.Log.ForContext<SerilogMiddleware>();
+
+        private readonly RequestDelegate _next;
+
+        public SerilogMiddleware(RequestDelegate next)
+        {
+            if (next == null) throw new ArgumentNullException(nameof(next));
+            _next = next;
+        }
+
+        public async Task Invoke(HttpContext httpContext)
+        {
+            if (httpContext == null) throw new ArgumentNullException(nameof(httpContext));
+
+            var sw = Stopwatch.StartNew();
+            try
+            {
+                var request = httpContext.Request;
+
+                request.EnableBuffering();
+
+                using (var reader = new StreamReader(request.Body))
+                {
+                    var headers = string.Join("\n", request.Headers.Select(h => $"{h.Key}: {h.Value}").ToList());
+                    var body = await reader.ReadToEndAsync();
+
+                    Logger
+                        .ForContext("RequestHeaders", headers)
+                        .ForContext("RequestBody", body)
+                        .ForContext("RequestQuery", request.QueryString)
+                        .Verbose("Request details - {Protocol} {RequestMethod} {Scheme}://{Host}{RequestPath}",
+                            request.Protocol, request.Method, request.Scheme, request.Host, request.Path);
+
+                    httpContext.Request.Body.Position = 0;
+
+                    await _next(httpContext);
+                }
+
+                sw.Stop();
+
+                var statusCode = httpContext.Response?.StatusCode;
+                var level = statusCode > 499 ? LogEventLevel.Error : LogEventLevel.Verbose;
+
+                var log = level == LogEventLevel.Error ? LogForErrorContext(httpContext) : Logger;
+                log.Write(level, MessageTemplate, httpContext.Request.Method, httpContext.Request.Path, statusCode, sw.Elapsed.TotalMilliseconds);
+            }
+            // Never caught, because `LogException()` returns false.
+            catch (Exception ex) when (LogException(httpContext, sw, ex)) { }
+        }
+
+        static bool LogException(HttpContext httpContext, Stopwatch sw, Exception ex)
+        {
+            sw.Stop();
+
+            LogForErrorContext(httpContext)
+                .Error(ex, MessageTemplate, httpContext.Request.Method, httpContext.Request.Path, 500, sw.Elapsed.TotalMilliseconds);
+
+            return false;
+        }
+
+        static ILogger LogForErrorContext(HttpContext httpContext)
+        {
+            var request = httpContext.Request;
+
+            var result = Logger
+                .ForContext("RequestHeaders", request.Headers.ToDictionary(h => h.Key, h => h.Value.ToString()), destructureObjects: true)
+                .ForContext("RequestHost", request.Host)
+                .ForContext("RequestProtocol", request.Protocol);
+
+            if (request.HasFormContentType)
+                result = result.ForContext("RequestForm", request.Form.ToDictionary(v => v.Key, v => v.Value.ToString()));
+
+            return result;
+        }
+    }
+}
\ No newline at end of file
diff --git a/src/Web/WebMVC/Startup.cs b/src/Web/WebMVC/Startup.cs
index 52a311369..330be6410 100644
--- a/src/Web/WebMVC/Startup.cs
+++ b/src/Web/WebMVC/Startup.cs
@@ -1,4 +1,5 @@
-using Devspaces.Support;
+using Datalust.SerilogMiddlewareExample.Diagnostics;
+using Devspaces.Support;
 using HealthChecks.UI.Client;
 using Microsoft.ApplicationInsights.Extensibility;
 using Microsoft.ApplicationInsights.ServiceFabric;
@@ -93,6 +94,8 @@ namespace Microsoft.eShopOnContainers.WebMVC
                 app.UseMiddleware<ByPassAuthMiddleware>();
             }
 
+            app.UseMiddleware<SerilogMiddleware>();
+
             app.UseAuthentication();
 
             WebContextSeed.Seed(app, env, loggerFactory);