Refactor logger grouping (#716)

* Refactors IProxyLogger to ILogger

* Prints grouped log messages to console

* Code fixes

Author: waldekmastykarz

dev-proxy-abstractions/BaseProxyPlugin.cs

@@ -3,21 +3,26 @@
 
 using System.CommandLine;
 using Microsoft.Extensions.Configuration;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.DevProxy.Abstractions;
 
 public abstract class BaseProxyPlugin : IProxyPlugin
 {
-    protected ISet<UrlToWatch>? _urlsToWatch;
-    protected IProxyLogger? _logger;
+    protected ISet<UrlToWatch> UrlsToWatch { get; }
+    protected ILogger Logger { get; }
+    protected IConfigurationSection? ConfigSection { get; }
+    protected IPluginEvents PluginEvents { get; }
+    protected IProxyContext Context { get; }
 
     public virtual string Name => throw new NotImplementedException();
 
     public virtual Option[] GetOptions() => Array.Empty<Option>();
     public virtual Command[] GetCommands() => Array.Empty<Command>();
 
-    public virtual void Register(IPluginEvents pluginEvents,
+    public BaseProxyPlugin(IPluginEvents pluginEvents,
                          IProxyContext context,
+                         ILogger logger,
                          ISet<UrlToWatch> urlsToWatch,
                          IConfigurationSection? configSection = null)
     {
@@ -26,18 +31,29 @@ public virtual void Register(IPluginEvents pluginEvents,
             throw new ArgumentNullException(nameof(pluginEvents));
         }
 
-        if (context is null || context.Logger is null)
+        if (context is null)
         {
-            throw new ArgumentException($"{nameof(context)} must not be null and must supply a non-null Logger", nameof(context));
+            throw new ArgumentNullException(nameof(context));
+        }
 
+        if (logger is null)
+        {
+            throw new ArgumentNullException(nameof(logger));
         }
 
-        if (urlsToWatch is null || urlsToWatch.Count == 0)
+        if (urlsToWatch is null || !urlsToWatch.Any())
         {
             throw new ArgumentException($"{nameof(urlsToWatch)} cannot be null or empty", nameof(urlsToWatch));
         }
 
-        _urlsToWatch = urlsToWatch;
-        _logger = context.Logger;
+        UrlsToWatch = urlsToWatch;
+        Context = context;
+        Logger = logger;
+        ConfigSection = configSection;
+        PluginEvents = pluginEvents;
+    }
+
+    public virtual void Register()
+    {
     }
 }

dev-proxy-abstractions/BaseReportingPlugin.cs

@@ -1,10 +1,17 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 
+using Microsoft.Extensions.Configuration;
+using Microsoft.Extensions.Logging;
+
 namespace Microsoft.DevProxy.Abstractions;
 
 public abstract class BaseReportingPlugin : BaseProxyPlugin
 {
+    protected BaseReportingPlugin(IPluginEvents pluginEvents, IProxyContext context, ILogger logger, ISet<UrlToWatch> urlsToWatch, IConfigurationSection? configSection = null) : base(pluginEvents, context, logger, urlsToWatch, configSection)
+    {
+    }
+
     protected virtual void StoreReport(object report, ProxyEventArgsBase e)
     {
         if (report is null)

dev-proxy-abstractions/ILoggerExtensions.cs

@@ -0,0 +1,22 @@
+using System.Text.Json;
+using Microsoft.DevProxy.Abstractions;
+
+namespace Microsoft.Extensions.Logging;
+
+public static class ILoggerExtensions
+{
+    public static void LogRequest(this ILogger logger, string[] message, MessageType messageType, LoggingContext? context = null)
+    {
+        logger.Log(new RequestLog(message, messageType, context));
+    }
+
+    public static void LogRequest(this ILogger logger, string[] message, MessageType messageType, string method, string url)
+    {
+        logger.Log(new RequestLog(message, messageType, method, url));
+    }
+
+    public static void Log(this ILogger logger, RequestLog message)
+    {
+        logger.Log(LogLevel.Information, 0, message, exception: null, (m, _) => JsonSerializer.Serialize(m));
+    }
+}

dev-proxy-abstractions/IProxyLogger.cs

@@ -15,7 +15,8 @@ public enum MessageType
     Failed,
     Chaos,
     Mocked,
-    InterceptedResponse
+    InterceptedResponse,
+    FinishedProcessingRequest
 }
 
 public class LoggingContext

dev-proxy-abstractions/IProxyPlugin.cs

@@ -2,7 +2,6 @@
 // Licensed under the MIT License.
 
 using System.CommandLine;
-using Microsoft.Extensions.Configuration;
 
 namespace Microsoft.DevProxy.Abstractions;
 
@@ -11,8 +10,5 @@ public interface IProxyPlugin
     string Name { get; }
     Option[] GetOptions();
     Command[] GetCommands();
-    void Register(IPluginEvents pluginEvents,
-                  IProxyContext context,
-                  ISet<UrlToWatch> urlsToWatch,
-                  IConfigurationSection? configSection = null);
+    void Register();
 }

dev-proxy-abstractions/MSGraphDbUtils.cs

@@ -32,7 +32,7 @@ public static SqliteConnection MSGraphDbConnection
         }
     }
 
-    public static async Task<int> GenerateMSGraphDb(IProxyLogger logger, bool skipIfUpdatedToday = false)
+    public static async Task<int> GenerateMSGraphDb(ILogger logger, bool skipIfUpdatedToday = false)
     {
         var appFolder = ProxyUtils.AppFolder;
         if (string.IsNullOrEmpty(appFolder))
@@ -75,7 +75,7 @@ public static async Task<int> GenerateMSGraphDb(IProxyLogger logger, bool skipIf
 
     }
 
-    private static void CreateDb(SqliteConnection dbConnection, IProxyLogger logger)
+    private static void CreateDb(SqliteConnection dbConnection, ILogger logger)
     {
         logger.LogInformation("Creating database...");
 
@@ -97,7 +97,7 @@ private static void CreateDb(SqliteConnection dbConnection, IProxyLogger logger)
         createIndex.ExecuteNonQuery();
     }
 
-    private static void FillData(SqliteConnection dbConnection, IProxyLogger logger)
+    private static void FillData(SqliteConnection dbConnection, ILogger logger)
     {
         logger.LogInformation("Filling database...");
 
@@ -118,20 +118,20 @@ private static void FillData(SqliteConnection dbConnection, IProxyLogger logger)
 
             foreach (var path in document.Paths)
             {
-                logger.LogDebug("Endpoint {graphVersion}{key}...", graphVersion, path.Key);
+                logger.LogTrace("Endpoint {graphVersion}{key}...", graphVersion, path.Key);
 
                 // Get the GET operation for this path
                 var getOperation = path.Value.Operations.FirstOrDefault(o => o.Key == OperationType.Get).Value;
                 if (getOperation == null)
                 {
-                    logger.LogDebug("No GET operation found for {graphVersion}{key}", graphVersion, path.Key);
+                    logger.LogTrace("No GET operation found for {graphVersion}{key}", graphVersion, path.Key);
                     continue;
                 }
 
                 // Check if the GET operation has a $select parameter
                 var hasSelect = getOperation.Parameters.Any(p => p.Name == "$select");
 
-                logger.LogDebug("Inserting endpoint {graphVersion}{key} with hasSelect={hasSelect}...", graphVersion, path.Key, hasSelect);
+                logger.LogTrace("Inserting endpoint {graphVersion}{key} with hasSelect={hasSelect}...", graphVersion, path.Key, hasSelect);
                 insertEndpoint.Parameters["@path"].Value = path.Key;
                 insertEndpoint.Parameters["@graphVersion"].Value = graphVersion;
                 insertEndpoint.Parameters["@hasSelect"].Value = hasSelect;
@@ -143,7 +143,7 @@ private static void FillData(SqliteConnection dbConnection, IProxyLogger logger)
         logger.LogInformation("Inserted {endpointCount} endpoints in the database", i);
     }
 
-    private static async Task UpdateOpenAPIGraphFilesIfNecessary(string folder, IProxyLogger logger)
+    private static async Task UpdateOpenAPIGraphFilesIfNecessary(string folder, ILogger logger)
     {
         logger.LogInformation("Checking for updated OpenAPI files...");
 
@@ -176,7 +176,7 @@ private static async Task UpdateOpenAPIGraphFilesIfNecessary(string folder, IPro
         }
     }
 
-    private static async Task LoadOpenAPIFiles(string folder, IProxyLogger logger)
+    private static async Task LoadOpenAPIFiles(string folder, ILogger logger)
     {
         logger.LogInformation("Loading OpenAPI files...");
 

dev-proxy-abstractions/PluginEvents.cs

@@ -4,6 +4,7 @@
 using System.CommandLine;
 using System.CommandLine.Invocation;
 using System.Security.Cryptography.X509Certificates;
+using System.Text.Json.Serialization;
 using Titanium.Web.Proxy;
 using Titanium.Web.Proxy.EventArguments;
 using Titanium.Web.Proxy.Http;
@@ -13,7 +14,6 @@ namespace Microsoft.DevProxy.Abstractions;
 public interface IProxyContext
 {
     IProxyConfiguration Configuration { get; }
-    IProxyLogger Logger { get; }
     X509Certificate2? Certificate { get; }
 }
 
@@ -126,13 +126,37 @@ public class RequestLog
 {
     public string[] MessageLines { get; set; }
     public MessageType MessageType { get; set; }
+    [JsonIgnore]
     public LoggingContext? Context { get; set; }
+    public string? Method { get; init; }
+    public string? Url { get; init; }
 
-    public RequestLog(string[] messageLines, MessageType messageType, LoggingContext? context)
+    public RequestLog(string[] messageLines, MessageType messageType, LoggingContext? context) :
+        this(messageLines, messageType, context?.Session.HttpClient.Request.Method, context?.Session.HttpClient.Request.Url, context)
+    {
+    }
+
+    public RequestLog(string[] messageLines, MessageType messageType, string method, string url) :
+        this(messageLines, messageType, method, url, context: null)
+    {
+    }
+
+    private RequestLog(string[] messageLines, MessageType messageType, string? method, string? url, LoggingContext? context)
     {
         MessageLines = messageLines ?? throw new ArgumentNullException(nameof(messageLines));
         MessageType = messageType;
         Context = context;
+        Method = method;
+        Url = url;
+    }
+
+    public void Deconstruct(out string[] message, out MessageType messageType, out LoggingContext? context, out string? method, out string? url)
+    {
+        message = MessageLines;
+        messageType = MessageType;
+        context = Context;
+        method = Method;
+        url = Url;
     }
 }
 

dev-proxy-plugins/Behavior/RateLimitingCustomResponseLoader.cs

@@ -9,10 +9,10 @@ namespace Microsoft.DevProxy.Plugins.Behavior;
 
 internal class RateLimitingCustomResponseLoader : IDisposable
 {
-    private readonly IProxyLogger _logger;
+    private readonly ILogger _logger;
     private readonly RateLimitConfiguration _configuration;
 
-    public RateLimitingCustomResponseLoader(IProxyLogger logger, RateLimitConfiguration configuration)
+    public RateLimitingCustomResponseLoader(ILogger logger, RateLimitConfiguration configuration)
     {
         _logger = logger ?? throw new ArgumentNullException(nameof(logger));
         _configuration = configuration ?? throw new ArgumentNullException(nameof(configuration));

dev-proxy-plugins/Behavior/RateLimitingPlugin.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License.
 
 using Microsoft.Extensions.Configuration;
+using Microsoft.Extensions.Logging;
 using Microsoft.DevProxy.Abstractions;
 using System.Net;
 using System.Text.Json;
@@ -49,6 +50,10 @@ public class RateLimitingPlugin : BaseProxyPlugin
     private DateTime _resetTime = DateTime.MinValue;
     private RateLimitingCustomResponseLoader? _loader = null;
 
+    public RateLimitingPlugin(IPluginEvents pluginEvents, IProxyContext context, ILogger logger, ISet<UrlToWatch> urlsToWatch, IConfigurationSection? configSection = null) : base(pluginEvents, context, logger, urlsToWatch, configSection)
+    {
+    }
+
     private ThrottlingInfo ShouldThrottle(Request request, string throttlingKey)
     {
         var throttleKeyForRequest = BuildThrottleKey(request);
@@ -123,31 +128,28 @@ private string BuildThrottleKey(Request r)
         }
     }
 
-    public override void Register(IPluginEvents pluginEvents,
-                         IProxyContext context,
-                         ISet<UrlToWatch> urlsToWatch,
-                         IConfigurationSection? configSection = null)
+    public override void Register()
     {
-        base.Register(pluginEvents, context, urlsToWatch, configSection);
+        base.Register();
 
-        configSection?.Bind(_configuration);
+        ConfigSection?.Bind(_configuration);
         if (_configuration.WhenLimitExceeded == RateLimitResponseWhenLimitExceeded.Custom)
         {
-            _configuration.CustomResponseFile = Path.GetFullPath(ProxyUtils.ReplacePathTokens(_configuration.CustomResponseFile), Path.GetDirectoryName(context.Configuration?.ConfigFile ?? string.Empty) ?? string.Empty);
-            _loader = new RateLimitingCustomResponseLoader(_logger!, _configuration);
+            _configuration.CustomResponseFile = Path.GetFullPath(ProxyUtils.ReplacePathTokens(_configuration.CustomResponseFile), Path.GetDirectoryName(Context.Configuration.ConfigFile ?? string.Empty) ?? string.Empty);
+            _loader = new RateLimitingCustomResponseLoader(Logger, _configuration);
             // load the responses from the configured mocks file
             _loader.InitResponsesWatcher();
         }
 
-        pluginEvents.BeforeRequest += OnRequest;
-        pluginEvents.BeforeResponse += OnResponse;
+        PluginEvents.BeforeRequest += OnRequest;
+        PluginEvents.BeforeResponse += OnResponse;
     }
 
     // add rate limiting headers to the response from the API
     private Task OnResponse(object? sender, ProxyResponseArgs e)
     {
-        if (_urlsToWatch is null ||
-            !e.HasRequestUrlMatch(_urlsToWatch))
+        if (UrlsToWatch is null ||
+            !e.HasRequestUrlMatch(UrlsToWatch))
         {
             return Task.CompletedTask;
         }
@@ -161,8 +163,8 @@ private Task OnRequest(object? sender, ProxyRequestArgs e)
         var session = e.Session;
         var state = e.ResponseState;
         if (e.ResponseState.HasBeenSet ||
-            _urlsToWatch is null ||
-            !e.ShouldExecute(_urlsToWatch))
+            UrlsToWatch is null ||
+            !e.ShouldExecute(UrlsToWatch))
         {
             return Task.CompletedTask;
         }
@@ -191,7 +193,7 @@ _urlsToWatch is null ||
             _resourcesRemaining = 0;
             var request = e.Session.HttpClient.Request;
 
-            _logger?.LogRequest([$"Exceeded resource limit when calling {request.Url}.", "Request will be throttled"], MessageType.Failed, new LoggingContext(e.Session));
+            Logger.LogRequest([$"Exceeded resource limit when calling {request.Url}.", "Request will be throttled"], MessageType.Failed, new LoggingContext(e.Session));
             if (_configuration.WhenLimitExceeded == RateLimitResponseWhenLimitExceeded.Throttle)
             {
                 if (!e.GlobalData.ContainsKey(RetryAfterPlugin.ThrottledRequestsKey))
@@ -250,7 +252,7 @@ _urlsToWatch is null ||
                 }
                 else
                 {
-                    _logger?.LogRequest([$"Custom behavior not set. {_configuration.CustomResponseFile} not found."], MessageType.Failed, new LoggingContext(e.Session));
+                    Logger.LogRequest([$"Custom behavior not set. {_configuration.CustomResponseFile} not found."], MessageType.Failed, new LoggingContext(e.Session));
                 }
             }
         }