Merge pull request #3 from DFE-Digital/feature/correlation-id-logging

Feature/correlation id logging

correlationIdMiddleware/correlationIdMiddleware/CorrelationContext.cs

@@ -1,14 +1,18 @@
-using Ardalis.GuardClauses;
+namespace Dfe.Academisation.CorrelationIdMiddleware;
 
-namespace Dfe.Academisation.CorrelationIdMiddleware;
-
-public record CorrelationContext() : ICorrelationContext
+/// <inheritdoc />
+public class CorrelationContext : ICorrelationContext
 {
-    public string? CorrelationId { get; private set; }
-    public void SetContext(string correlationId)
+    /// <inheritdoc />
+    public Guid CorrelationId { get; private set; }
+
+    /// <inheritdoc />
+    public void SetContext(Guid correlationId)
     {
-        this.CorrelationId = Guard.Against.NullOrWhiteSpace(correlationId);
+        if (correlationId == Guid.Empty)
+        {
+            throw new ArgumentException("Guid cannot be empty", nameof(correlationId));
+        }
+        this.CorrelationId = correlationId;
     }
-
-    public string HeaderKey { get => "x-correlation-id"; }
 }

correlationIdMiddleware/correlationIdMiddleware/CorrelationIdMiddleware.cs

@@ -1,13 +1,11 @@
-using Ardalis.GuardClauses;
+namespace Dfe.Academisation.CorrelationIdMiddleware;
 using Microsoft.AspNetCore.Http;
 using Microsoft.Extensions.Logging;
 
-namespace Dfe.Academisation.CorrelationIdMiddleware;
-
 /// <summary>
 /// Middleware that checks incoming requests for a correlation and causation id header. If not found then default values will be created.
 /// Saves these values in the correlationContext instance. Be sure to register correlation context as scoped or the equivalent in you ioc container.
-/// Header used in requests is 'x-correlation-id'
+/// Header used in requests is 'x-correlationId'
 /// </summary>
 public class CorrelationIdMiddleware
 {
@@ -17,34 +15,43 @@ public class CorrelationIdMiddleware
     public CorrelationIdMiddleware(RequestDelegate next, ILogger<CorrelationIdMiddleware> logger)
     {
         _next = next;
-        _logger = Guard.Against.Null(logger);
+        _logger = logger ?? throw new ArgumentNullException(nameof(logger));
     }
 
     // ReSharper disable once UnusedMember.Global
     // Invoked by asp.net
     public Task Invoke(HttpContext httpContext, ICorrelationContext correlationContext)
     {
-        string thisCorrelationId;
+        Guid thisCorrelationId;
 
         // correlation id. An ID that spans many requests
-        if (httpContext.Request.Headers.ContainsKey(correlationContext.HeaderKey) &&
-            !string.IsNullOrWhiteSpace(httpContext.Request.Headers[correlationContext.HeaderKey]))
+        if (httpContext.Request.Headers.ContainsKey(Keys.HeaderKey) 
+            && !string.IsNullOrWhiteSpace(httpContext.Request.Headers[Keys.HeaderKey]))
         {
-            thisCorrelationId = httpContext.Request.Headers[correlationContext.HeaderKey];
-            _logger.LogInformation("CorrelationId detected from header: {correlationId}", thisCorrelationId);
+            if (!Guid.TryParse(httpContext.Request.Headers[Keys.HeaderKey], out thisCorrelationId))
+            {
+                thisCorrelationId = Guid.NewGuid();
+                this._logger.LogWarning("Detected header x-correlationId, but value cannot be parsed to a GUID. Other values are not supported. Generated a new one: {correlationId}", thisCorrelationId);
+            }
+            else
+            {
+                _logger.LogInformation("CorrelationIdMiddleware:Invoke - x-correlationId detected in request headers: {correlationId}", thisCorrelationId);
+            }
         }
         else
         {
-            thisCorrelationId = Guid.NewGuid().ToString();
-            _logger.LogInformation("CorrelationId not detected from headers. Generated a new one: {correlationId}",
-                thisCorrelationId);
+            thisCorrelationId = Guid.NewGuid();
+            _logger.LogWarning("CorrelationIdMiddleware:Invoke - x-correlationId not detected in request headers. Generated a new one: {correlationId}", thisCorrelationId);
         }
 
-        httpContext.Request.Headers[correlationContext.HeaderKey] = thisCorrelationId;
+        httpContext.Request.Headers[Keys.HeaderKey] = thisCorrelationId.ToString();
 
         correlationContext.SetContext(thisCorrelationId);
 
-        httpContext.Response.Headers[correlationContext.HeaderKey] = thisCorrelationId;
-        return _next(httpContext);
+        httpContext.Response.Headers[Keys.HeaderKey] = thisCorrelationId.ToString();
+        using (_logger.BeginScope("x-correlationId {x-correlationId}", correlationContext.CorrelationId.ToString()))
+        {
+            return _next(httpContext);
+        }
     }
 }

correlationIdMiddleware/correlationIdMiddleware/Dfe.Academisation.CorrelationIdMiddleware.csproj

@@ -13,7 +13,7 @@
         <PackageTags>dfe;academisation;correlation;</PackageTags>
         <UserSecretsId>4ac4e7ef-aaff-48a4-9e4d-44371c231191</UserSecretsId>
         <PackageReadmeFile>README.md</PackageReadmeFile>
-        <Version>1.0.0</Version>
+        <Version>2.0.0</Version>
         <Authors>DFE-Digital</Authors>
     </PropertyGroup>
 
@@ -25,10 +25,8 @@
     </ItemGroup>
 
     <ItemGroup>
-      <PackageReference Include="Ardalis.GuardClauses" Version="4.0.1" />
       <PackageReference Include="Microsoft.AspNetCore.Http.Abstractions" Version="2.2.0" />
-      <PackageReference Include="Microsoft.Extensions.Configuration.UserSecrets" Version="6.0.1" />
-      <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="7.0.0" />
+      <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="7.0.1" />
     </ItemGroup>
 
 </Project>

correlationIdMiddleware/correlationIdMiddleware/ICorrelationContext.cs

@@ -1,8 +1,19 @@
 namespace Dfe.Academisation.CorrelationIdMiddleware;
 
+/// <summary>
+/// Provides access to the current correlation id. You should register this as a scoped / per web request
+/// dependency in your IoC/DI container.
+/// </summary>
 public interface ICorrelationContext
 {
-    public string? CorrelationId { get; }
-    public void SetContext(string correlationId);
-    public string HeaderKey { get; }
+    /// <summary>
+    /// Returns the current correlation id if it has been set
+    /// </summary>
+    public Guid CorrelationId { get; }
+
+    /// <summary>
+    /// Used by the middleware to store the current correlation id. Do not call this method yourself.
+    /// </summary>
+    /// <param name="correlationId"></param>
+    public void SetContext(Guid correlationId);
 }

correlationIdMiddleware/correlationIdMiddleware/Keys.cs

@@ -0,0 +1,13 @@
+namespace Dfe.Academisation.CorrelationIdMiddleware;
+/// <summary>
+/// The keys used by the correlation id middleware.
+/// </summary>
+
+public class Keys
+{
+    /// <summary>
+    /// The header key use to detect incoming correlation ids, and to send them in responses.
+    /// Use this key if you are making subsequent requests so that correlation flows between services
+    /// </summary>
+    public const string HeaderKey = "x-correlationId";
+}

correlationIdMiddleware/correlationIdMiddleware/README.md

@@ -2,6 +2,50 @@
 
 ## What does this do ?
 
+This package contains middleware that you can register in your AspNet application to enable detection of `x-correlationId` request headers that can then be propagated and use in logging, further requests, and responses.
+
 ## Why does it do it ?
 
-## How to use it 
+CorrelationIds that are passed between services and recorded in all logs help to dramatically reduce the complexity involved in debugging applications, particularly where multiple services are involved.
+
+## How to use it 
+
+* Reference the Nuget package.
+
+* In your application start-up, register the correlation context as a scoped dependency. For example
+`services.AddScoped<ICorrelationContext, CorrelationContext>();`
+
+* Add the CorrelationId middleware to your AspNet middleware pipeline. You should add this as early as possible so that correlationIds can be logged.
+`app.UseMiddleware<CorrelationIdMiddleware>();`
+
+* Anywhere that you need access to the current correlation id, inject `ICorrelationContext` and access the current context using the `CorrelationId` property. It will return a `string?` that you can use in subsequent requests or wherever you need it.
+
+---
+
+## Default AspNet Logger
+The middleware will add the current correlation id as scoped data before calling the next middleware in the AspNet middleware pipeline.
+If you are using the default AspNet logger, to see this in your log output you need to enable scopes in the output.
+One simple way of doing this is to use the console output by adding the following to your logger configuration.
+Alternatively use something like Seq to view logs locally.
+
+```json
+  "Logging": {
+    "LogLevel": {
+      "Default": "Information",
+      "Microsoft": "Information",
+      "Microsoft.Hosting.Lifetime": "Information",
+      "Microsoft.AspNetCore": "Warning"
+    },
+    "Console": {
+      "FormatterName": "simple",
+      "FormatterOptions": {
+        "IncludeScopes": "true"
+      }
+    }
+  },
+```
+
+## Not using the default AspNet Logger ?
+The middleware will push an `x-correlationId` scope property onto the default Microsoft logging implementation.
+
+If you are using another logger, create a middleware and register it as the next one in the pipeline after the `CorrelationIdMiddleware`. Inject the `ICorrelationContext` into your middleware and use the `ICorrelationContext.CorrelationId` property to access the correlationId value and include it in your own logs. For example Serilog.