From 97188c4dacc9b113e2b464544f2da4566ed08727 Mon Sep 17 00:00:00 2001 From: Waldek Mastykarz Date: Mon, 26 May 2025 19:33:59 +0200 Subject: [PATCH] Fixes printing log messages outside of the request scope. Closes #1205 --- dev-proxy/Logging/LogEntry.cs | 28 ++ dev-proxy/Logging/ProxyConsoleFormatter.cs | 366 ++++++++++++--------- 2 files changed, 235 insertions(+), 159 deletions(-) create mode 100644 dev-proxy/Logging/LogEntry.cs diff --git a/dev-proxy/Logging/LogEntry.cs b/dev-proxy/Logging/LogEntry.cs new file mode 100644 index 00000000..64e8c7ee --- /dev/null +++ b/dev-proxy/Logging/LogEntry.cs @@ -0,0 +1,28 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using Microsoft.Extensions.Logging.Abstractions; + +namespace DevProxy.Logging; + +readonly struct LogEntry +{ + public LogLevel LogLevel { get; init; } + public string Category { get; init; } + public EventId EventId { get; init; } + public string? Message { get; init; } + public Exception? Exception { get; init; } + + public static LogEntry FromLogEntry(LogEntry logEntry) + { + return new() + { + LogLevel = logEntry.LogLevel, + Category = logEntry.Category, + EventId = logEntry.EventId, + Message = logEntry.Formatter(logEntry.State, logEntry.Exception), + Exception = logEntry.Exception + }; + } +} \ No newline at end of file diff --git a/dev-proxy/Logging/ProxyConsoleFormatter.cs b/dev-proxy/Logging/ProxyConsoleFormatter.cs index 4fc2a711..a549d83f 100644 --- a/dev-proxy/Logging/ProxyConsoleFormatter.cs +++ b/dev-proxy/Logging/ProxyConsoleFormatter.cs @@ -2,34 +2,90 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. -using System.Collections.Concurrent; -using System.Text; using DevProxy.Abstractions; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Logging.Console; using Microsoft.Extensions.Options; +using System.Collections.Concurrent; +using System.Text; namespace DevProxy.Logging; -public class ProxyConsoleFormatter : ConsoleFormatter +sealed class ProxyConsoleFormatter : ConsoleFormatter { + public const string DefaultCategoryName = "devproxy"; + private const string _boxTopLeft = "\u256d "; private const string _boxLeft = "\u2502 "; private const string _boxBottomLeft = "\u2570 "; - // used to align single-line messages private const string _boxSpacing = " "; - private readonly ConcurrentDictionary> _requestLogs = []; + private const string _labelSpacing = " "; + + // Cached lookup tables for better performance + private static readonly Dictionary _logLevelStrings = new() + { + [LogLevel.Trace] = "trce", + [LogLevel.Debug] = "dbug", + [LogLevel.Information] = "info", + [LogLevel.Warning] = "warn", + [LogLevel.Error] = "fail", + [LogLevel.Critical] = "crit" + }; + private static readonly Dictionary _logLevelColors = new() + { + [LogLevel.Information] = (Console.BackgroundColor, ConsoleColor.Blue), + [LogLevel.Warning] = (ConsoleColor.DarkYellow, Console.ForegroundColor), + [LogLevel.Error] = (ConsoleColor.DarkRed, Console.ForegroundColor), + [LogLevel.Debug] = (Console.BackgroundColor, ConsoleColor.Gray), + [LogLevel.Trace] = (Console.BackgroundColor, ConsoleColor.Gray) + }; + private static readonly Dictionary _messageTypeStrings = new() + { + [MessageType.InterceptedRequest] = "req", + [MessageType.InterceptedResponse] = "res", + [MessageType.PassedThrough] = "pass", + [MessageType.Chaos] = "oops", + [MessageType.Warning] = "warn", + [MessageType.Mocked] = "mock", + [MessageType.Failed] = "fail", + [MessageType.Tip] = "tip", + [MessageType.Skipped] = "skip", + [MessageType.Processed] = "proc", + [MessageType.Timestamp] = "time", + [MessageType.FinishedProcessingRequest] = " " + }; + private static readonly Dictionary _messageTypeColors = new() + { + [MessageType.InterceptedRequest] = (Console.BackgroundColor, ConsoleColor.Gray), + [MessageType.PassedThrough] = (ConsoleColor.Gray, Console.ForegroundColor), + [MessageType.Skipped] = (Console.BackgroundColor, ConsoleColor.Gray), + [MessageType.Processed] = (ConsoleColor.DarkGreen, Console.ForegroundColor), + [MessageType.Chaos] = (ConsoleColor.DarkRed, Console.ForegroundColor), + [MessageType.Warning] = (ConsoleColor.DarkYellow, Console.ForegroundColor), + [MessageType.Mocked] = (ConsoleColor.DarkMagenta, Console.ForegroundColor), + [MessageType.Failed] = (ConsoleColor.DarkRed, Console.ForegroundColor), + [MessageType.Tip] = (ConsoleColor.DarkBlue, Console.ForegroundColor), + [MessageType.Timestamp] = (Console.BackgroundColor, ConsoleColor.Gray) + }; + + private readonly ConcurrentDictionary> _messages = []; private readonly ProxyConsoleFormatterOptions _options; - const string labelSpacing = " "; - // label length + 2 - private readonly static string noLabelSpacing = new(' ', 4 + 2); - public static readonly string DefaultCategoryName = "devproxy"; + private readonly HashSet _filteredMessageTypes; public ProxyConsoleFormatter(IOptions options) : base(DefaultCategoryName) { - // needed to properly required rounded corners in the box Console.OutputEncoding = Encoding.UTF8; _options = options.Value; + + _filteredMessageTypes = [MessageType.InterceptedResponse]; + if (!_options.ShowSkipMessages) + { + _ = _filteredMessageTypes.Add(MessageType.Skipped); + } + if (!_options.ShowTimestamps) + { + _ = _filteredMessageTypes.Add(MessageType.Timestamp); + } } public override void Write(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) @@ -40,7 +96,7 @@ public override void Write(in LogEntry logEntry, IExternalScopeP } else { - LogMessage(logEntry, scopeProvider, textWriter); + LogRegularLogMessage(logEntry, scopeProvider, textWriter); } } @@ -48,77 +104,89 @@ private void LogRequest(RequestLog requestLog, string category, IExternalScopePr { var messageType = requestLog.MessageType; - // don't log intercepted response to console - if (messageType == MessageType.InterceptedResponse || - (messageType == MessageType.Skipped && !_options.ShowSkipMessages) || - (messageType == MessageType.Timestamp && !_options.ShowTimestamps) - ) + if (_filteredMessageTypes.Contains(messageType)) { return; } var requestId = GetRequestIdScope(scopeProvider); + if (requestId is null) + { + return; + } - if (requestId is not null) + if (messageType == MessageType.FinishedProcessingRequest) { - if (messageType == MessageType.FinishedProcessingRequest) - { - // log all request logs for the request - var currentRequestLogs = _requestLogs[requestId.Value]; - var lastIndex = currentRequestLogs.Count - 1; - for (var i = 0; i < currentRequestLogs.Count; ++i) - { - var log = currentRequestLogs[i]; - WriteLogMessageBoxedWithInvertedLabels(log, scopeProvider, textWriter, i == lastIndex); - } - _requestLogs.Remove(requestId.Value, out _); - } - else - { - // buffer request logs until the request is finished processing - requestLog.PluginName = category == DefaultCategoryName ? null : category; - var value = _requestLogs.GetOrAdd(requestId.Value, []); - value.Add(requestLog); - } + FlushLogsForRequest(requestId.Value, textWriter); + } + else + { + BufferRequestLog(requestLog, category, requestId.Value); } } - private static int? GetRequestIdScope(IExternalScopeProvider? scopeProvider) + private void FlushLogsForRequest(int requestId, TextWriter textWriter) { - int? requestId = null; + if (!_messages.TryGetValue(requestId, out var messages)) + { + return; + } - scopeProvider?.ForEachScope((scope, state) => + var lastIndex = messages.Count - 1; + for (var i = 0; i < messages.Count; i++) { - if (scope is Dictionary dictionary) + var isLast = i == lastIndex; + switch (messages[i]) { - if (dictionary.TryGetValue(nameof(requestId), out var req)) - { - requestId = (int)req; - } + case RequestLog log: + WriteRequestLogMessage(log, textWriter, isLast); + break; + case LogEntry logEntry: + WriteRegularLogMessage(logEntry, textWriter, isLast); + break; + default: + // noop + break; } - }, ""); + } + _ = _messages.TryRemove(requestId, out _); + } - return requestId; + private void BufferRequestLog(RequestLog requestLog, string category, int requestId) + { + requestLog.PluginName = category == DefaultCategoryName ? null : category; + var messages = _messages.GetOrAdd(requestId, _ => []); + messages.Add(requestLog); } - private void LogMessage(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) + private void LogRegularLogMessage(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) { - // regular messages - var logLevel = logEntry.LogLevel; - var message = logEntry.Formatter(logEntry.State, logEntry.Exception); - var category = logEntry.Category == DefaultCategoryName ? null : logEntry.Category; + var requestId = GetRequestIdScope(scopeProvider); + if (requestId is null) + { + WriteRegularLogMessage(logEntry, scopeProvider, textWriter); + } + else + { + var message = LogEntry.FromLogEntry(logEntry); + var messages = _messages.GetOrAdd(requestId.Value, _ => []); + messages.Add(message); + } + } - WriteMessageBoxedWithInvertedLabels(message, logLevel, category, scopeProvider, textWriter); + private void WriteRegularLogMessage(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) + { + var message = logEntry.Formatter(logEntry.State, logEntry.Exception); + WriteMessageWithLabel(message, logEntry.LogLevel, scopeProvider, textWriter); if (logEntry.Exception is not null) { textWriter.Write($" Exception Details: {logEntry.Exception}"); } - textWriter.WriteLine(); } - private void WriteMessageBoxedWithInvertedLabels(string? message, LogLevel logLevel, string? category, IExternalScopeProvider? scopeProvider, TextWriter textWriter) + private void WriteMessageWithLabel(string? message, LogLevel logLevel, IExternalScopeProvider? scopeProvider, TextWriter textWriter) { if (message is null) { @@ -128,140 +196,120 @@ private void WriteMessageBoxedWithInvertedLabels(string? message, LogLevel logLe var label = GetLogLevelString(logLevel); var (bgColor, fgColor) = GetLogLevelColor(logLevel); - textWriter.WriteColoredMessage($" {label} ", bgColor, fgColor); - textWriter.Write($"{labelSpacing}{_boxSpacing}{(logLevel == LogLevel.Debug ? $"[{DateTime.Now:T}] " : "")}"); + WriteLabel(textWriter, label, bgColor, fgColor); + textWriter.Write($"{_labelSpacing}{_boxSpacing}"); - if (_options.IncludeScopes && scopeProvider is not null) + if (logLevel == LogLevel.Debug) { - scopeProvider.ForEachScope((scope, state) => - { - if (scope is null) - { - return; - } - - if (scope is string scopeString) - { - textWriter.Write(scopeString); - textWriter.Write(": "); - } - else if (scope.GetType().Name == "FormattedLogValues") - { - textWriter.Write(scope.ToString()); - textWriter.Write(": "); - } - }, textWriter); - } - - if (!string.IsNullOrEmpty(category)) - { - textWriter.Write($"{category}: "); + textWriter.Write($"[{DateTime.Now:T}] "); } + WriteScopes(scopeProvider, textWriter); textWriter.Write(message); } - private void WriteLogMessageBoxedWithInvertedLabels(RequestLog log, IExternalScopeProvider? scopeProvider, TextWriter textWriter, bool lastMessage = false) + private void WriteRequestLogMessage(RequestLog log, TextWriter textWriter, bool isLast) { var label = GetMessageTypeString(log.MessageType); var (bgColor, fgColor) = GetMessageTypeColor(log.MessageType); + var boxChar = GetBoxCharacter(log.MessageType, isLast); - void writePluginName() + if (log.MessageType == MessageType.InterceptedRequest) { - if (_options.IncludeScopes && log.PluginName is not null) - { - textWriter.Write($"{log.PluginName}: "); - } + textWriter.WriteLine(); } - switch (log.MessageType) - { - case MessageType.InterceptedRequest: - // always one line (method + URL) - // print label and top of the box - textWriter.WriteLine(); - textWriter.WriteColoredMessage($" {label} ", bgColor, fgColor); - textWriter.Write($"{(label.Length < 4 ? " " : "")}{labelSpacing}{_boxTopLeft}"); - writePluginName(); - textWriter.WriteLine(log.Message); - break; - default: - textWriter.WriteColoredMessage($" {label} ", bgColor, fgColor); - textWriter.Write($"{(label.Length < 4 ? " " : "")}{labelSpacing}{(lastMessage ? _boxBottomLeft : _boxLeft)}"); - writePluginName(); - textWriter.WriteLine(log.Message); - break; - } + WriteLabel(textWriter, label, bgColor, fgColor); + textWriter.Write($"{GetLabelPadding(label)}{_labelSpacing}{boxChar}"); + WritePluginName(textWriter, log.PluginName); + textWriter.WriteLine(log.Message); } - // from https://github.com/dotnet/runtime/blob/198a2596229f69b8e02902bfb4ffc2a30be3b339/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs#L154 - private static string GetLogLevelString(LogLevel logLevel) + private void WriteRegularLogMessage(LogEntry log, TextWriter textWriter, bool isLast) { - return logLevel switch - { - LogLevel.Trace => "trce", - LogLevel.Debug => "dbug", - LogLevel.Information => "info", - LogLevel.Warning => "warn", - LogLevel.Error => "fail", - LogLevel.Critical => "crit", - _ => throw new ArgumentOutOfRangeException(nameof(logLevel)) - }; + var label = GetLogLevelString(log.LogLevel); + var (bgColor, fgColor) = GetLogLevelColor(log.LogLevel); + var boxChar = isLast ? _boxBottomLeft : _boxLeft; + + WriteLabel(textWriter, label, bgColor, fgColor); + textWriter.Write($"{GetLabelPadding(label)}{_labelSpacing}{boxChar}"); + WritePluginName(textWriter, log.Category); + textWriter.WriteLine(log.Message); } - private static (ConsoleColor bg, ConsoleColor fg) GetLogLevelColor(LogLevel logLevel) + private void WritePluginName(TextWriter textWriter, string? categoryOrPluginName) { - var fgColor = Console.ForegroundColor; - var bgColor = Console.BackgroundColor; + if (!_options.IncludeScopes || categoryOrPluginName is null) + { + return; + } - return logLevel switch + var pluginName = categoryOrPluginName[(categoryOrPluginName.LastIndexOf('.') + 1)..]; + if (pluginName != nameof(ProxyEngine)) { - LogLevel.Information => (bgColor, ConsoleColor.Blue), - LogLevel.Warning => (ConsoleColor.DarkYellow, fgColor), - LogLevel.Error => (ConsoleColor.DarkRed, fgColor), - LogLevel.Debug => (bgColor, ConsoleColor.Gray), - LogLevel.Trace => (bgColor, ConsoleColor.Gray), - _ => (bgColor, fgColor) - }; + textWriter.Write($"{pluginName}: "); + } } - private static string GetMessageTypeString(MessageType messageType) + private void WriteScopes(IExternalScopeProvider? scopeProvider, TextWriter textWriter) { - return messageType switch + if (!_options.IncludeScopes || scopeProvider is null) { - MessageType.InterceptedRequest => "req", - MessageType.InterceptedResponse => "res", - MessageType.PassedThrough => "pass", - MessageType.Chaos => "oops", - MessageType.Warning => "warn", - MessageType.Mocked => "mock", - MessageType.Failed => "fail", - MessageType.Tip => "tip", - MessageType.Skipped => "skip", - MessageType.Processed => "proc", - MessageType.Timestamp => "time", - _ => " " - }; + return; + } + + scopeProvider.ForEachScope((scope, state) => + { + if (scope is null) + { + return; + } + + var scopeText = scope is string scopeString ? scopeString : + scope.GetType().Name == "FormattedLogValues" ? scope.ToString() : null; + + if (scopeText is not null) + { + textWriter.Write($"{scopeText}: "); + } + }, textWriter); } - private static (ConsoleColor bg, ConsoleColor fg) GetMessageTypeColor(MessageType messageType) - { - var fgColor = Console.ForegroundColor; - var bgColor = Console.BackgroundColor; + private static string GetLogLevelString(LogLevel logLevel) => + _logLevelStrings.TryGetValue(logLevel, out var str) ? str : throw new ArgumentOutOfRangeException(nameof(logLevel)); + + private static (ConsoleColor bg, ConsoleColor fg) GetLogLevelColor(LogLevel logLevel) => + _logLevelColors.TryGetValue(logLevel, out var color) ? color : (Console.BackgroundColor, Console.ForegroundColor); - return messageType switch + private static string GetMessageTypeString(MessageType messageType) => + _messageTypeStrings.TryGetValue(messageType, out var str) ? str : " "; + + private static (ConsoleColor bg, ConsoleColor fg) GetMessageTypeColor(MessageType messageType) => + _messageTypeColors.TryGetValue(messageType, out var color) ? color : (Console.BackgroundColor, Console.ForegroundColor); + + private static int? GetRequestIdScope(IExternalScopeProvider? scopeProvider) + { + int? requestId = null; + scopeProvider?.ForEachScope((scope, _) => { - MessageType.InterceptedRequest => (bgColor, ConsoleColor.Gray), - MessageType.PassedThrough => (ConsoleColor.Gray, fgColor), - MessageType.Skipped => (bgColor, ConsoleColor.Gray), - MessageType.Processed => (ConsoleColor.DarkGreen, fgColor), - MessageType.Chaos => (ConsoleColor.DarkRed, fgColor), - MessageType.Warning => (ConsoleColor.DarkYellow, fgColor), - MessageType.Mocked => (ConsoleColor.DarkMagenta, fgColor), - MessageType.Failed => (ConsoleColor.DarkRed, fgColor), - MessageType.Tip => (ConsoleColor.DarkBlue, fgColor), - MessageType.Timestamp => (bgColor, ConsoleColor.Gray), - _ => (bgColor, fgColor) - }; + if (scope is Dictionary dictionary && + dictionary.TryGetValue(nameof(requestId), out var req)) + { + requestId = (int)req; + } + }, ""); + return requestId; + } + + private static void WriteLabel(TextWriter textWriter, string label, ConsoleColor bgColor, ConsoleColor fgColor) + { + textWriter.WriteColoredMessage($" {label} ", bgColor, fgColor); } + + private static string GetLabelPadding(string label) => + label.Length < 4 ? " " : ""; + + private static string GetBoxCharacter(MessageType messageType, bool isLast) => + messageType == MessageType.InterceptedRequest ? _boxTopLeft : + isLast ? _boxBottomLeft : _boxLeft; } \ No newline at end of file