From abecf2ffe4c42bcbad7cdddbca5d629d2a25b9f3 Mon Sep 17 00:00:00 2001 From: Kaz Wolfe Date: Sat, 30 Jul 2022 13:59:15 -0700 Subject: [PATCH] Add Per-Plugin Log Filtering Support This commit adds first-pass support for more robust plugin log filtering. No changes were made that affect PluginLog's APIs nor log format. This change works by making use of Serilog's "SourceContext" property to attach plugin information to all log messages. The in-game log UI can then be used to filter based on this property. Future expansions for this system include the ability to set different plugins to different log levels (something that already can technically be done, but requires those plugins be hard-coded through MinimumLevel.Override), creating new root loggers for each plugin (thereby giving plugin devs more control over their logging should they want to use it), plus other potential improvements in the way of adding context or rich information. - Update PluginLog to attach a "SourceContext" property to all log messages. - Tweak the SerilogEventSink to pass the original log event around. - Suppress Info/Debug/Verbose exceptions from Troubleshooting reports. - Fix the ConsoleWindow log filter to use _all_ filters, rather than just one. - Add ConsoleWindow dropdown to select plugins to filter logs by - Add support for multiple log levels to ConsoleWindow filtering --- Dalamud/EntryPoint.cs | 11 ++- .../Internal/Windows/ConsoleWindow.cs | 94 ++++++++++++++----- Dalamud/Logging/Internal/SerilogEventSink.cs | 10 +- Dalamud/Logging/PluginLog.cs | 66 ++++++++----- 4 files changed, 127 insertions(+), 54 deletions(-) diff --git a/Dalamud/EntryPoint.cs b/Dalamud/EntryPoint.cs index c28c3bbaf..f12355067 100644 --- a/Dalamud/EntryPoint.cs +++ b/Dalamud/EntryPoint.cs @@ -182,12 +182,17 @@ namespace Dalamud } } - private static void SerilogOnLogLine(object? sender, (string Line, LogEventLevel Level, DateTimeOffset TimeStamp, Exception? Exception) e) + private static void SerilogOnLogLine(object? sender, (string Line, LogEvent LogEvent) ev) { - if (e.Exception == null) + if (ev.LogEvent.Exception == null) return; - Troubleshooting.LogException(e.Exception, e.Line); + // Don't pass verbose/debug/info exceptions to the troubleshooter, as the developer is probably doing + // something intentionally (or this is known). + if (ev.LogEvent.Level < LogEventLevel.Warning) + return; + + Troubleshooting.LogException(ev.LogEvent.Exception, ev.Line); } private static void InitSymbolHandler(DalamudStartInfo info) diff --git a/Dalamud/Interface/Internal/Windows/ConsoleWindow.cs b/Dalamud/Interface/Internal/Windows/ConsoleWindow.cs index 587ddba7e..259a9e487 100644 --- a/Dalamud/Interface/Internal/Windows/ConsoleWindow.cs +++ b/Dalamud/Interface/Internal/Windows/ConsoleWindow.cs @@ -12,6 +12,7 @@ using Dalamud.Interface.Colors; using Dalamud.Interface.Components; using Dalamud.Interface.Windowing; using Dalamud.Logging.Internal; +using Dalamud.Plugin.Internal; using ImGuiNET; using Serilog; using Serilog.Events; @@ -26,7 +27,7 @@ namespace Dalamud.Interface.Internal.Windows private readonly List logText = new(); private readonly object renderLock = new(); - private readonly string[] logLevelStrings = new[] { "None", "Verbose", "Debug", "Information", "Warning", "Error", "Fatal" }; + private readonly string[] logLevelStrings = new[] { "Verbose", "Debug", "Information", "Warning", "Error", "Fatal" }; private List filteredLogText = new(); private bool autoScroll; @@ -37,7 +38,8 @@ namespace Dalamud.Interface.Internal.Windows private string commandText = string.Empty; private string textFilter = string.Empty; - private LogEventLevel? levelFilter = null; + private int levelFilter; + private List sourceFilters = new(); private bool isFiltered = false; private int historyPos; @@ -96,24 +98,23 @@ namespace Dalamud.Interface.Internal.Windows /// Add a single log line to the display. /// /// The line to add. - /// The level of the event. - /// The of the event. - public void HandleLogLine(string line, LogEventLevel level, DateTimeOffset offset) + /// The Serilog event associated with this line. + public void HandleLogLine(string line, LogEvent logEvent) { if (line.IndexOfAny(new[] { '\n', '\r' }) != -1) { var subLines = line.Split(new[] { "\r\n", "\r", "\n" }, StringSplitOptions.RemoveEmptyEntries); - this.AddAndFilter(subLines[0], level, offset, false); + this.AddAndFilter(subLines[0], logEvent, false); for (var i = 1; i < subLines.Length; i++) { - this.AddAndFilter(subLines[i], level, offset, true); + this.AddAndFilter(subLines[i], logEvent, true); } } else { - this.AddAndFilter(line, level, offset, false); + this.AddAndFilter(line, logEvent, false); } } @@ -160,11 +161,49 @@ namespace Dalamud.Interface.Internal.Windows ImGui.TextColored(ImGuiColors.DalamudGrey, "Enter to confirm."); - var filterVal = this.levelFilter.HasValue ? (int)this.levelFilter.Value + 1 : 0; - if (ImGui.Combo("Level", ref filterVal, this.logLevelStrings, 7)) + if (ImGui.BeginCombo("Levels", this.levelFilter == 0 ? "All Levels..." : "Selected Levels...")) { - this.levelFilter = (LogEventLevel)(filterVal - 1); - this.Refilter(); + for (var i = 0; i < this.logLevelStrings.Length; i++) + { + if (ImGui.Selectable(this.logLevelStrings[i], ((this.levelFilter >> i) & 1) == 1)) + { + this.levelFilter ^= 1 << i; + this.Refilter(); + } + } + + ImGui.EndCombo(); + } + + // Filter by specific plugin(s) + var pluginInternalNames = Service.Get().InstalledPlugins.Select(p => p.Manifest.InternalName).ToList(); + var sourcePreviewVal = this.sourceFilters.Count switch + { + 0 => "All plugins...", + 1 => "1 plugin...", + _ => $"{this.sourceFilters.Count} plugins...", + }; + var sourceSelectables = pluginInternalNames.Union(this.sourceFilters).ToList(); + if (ImGui.BeginCombo("Plugins", sourcePreviewVal)) + { + foreach (var selectable in sourceSelectables) + { + if (ImGui.Selectable(selectable, this.sourceFilters.Contains(selectable))) + { + if (!this.sourceFilters.Contains(selectable)) + { + this.sourceFilters.Add(selectable); + } + else + { + this.sourceFilters.Remove(selectable); + } + + this.Refilter(); + } + } + + ImGui.EndCombo(); } ImGui.EndPopup(); @@ -435,7 +474,7 @@ namespace Dalamud.Interface.Internal.Windows return 0; } - private void AddAndFilter(string line, LogEventLevel level, DateTimeOffset offset, bool isMultiline) + private void AddAndFilter(string line, LogEvent logEvent, bool isMultiline) { if (line.StartsWith("TROUBLESHOOTING:") || line.StartsWith("LASTEXCEPTION:")) return; @@ -443,11 +482,17 @@ namespace Dalamud.Interface.Internal.Windows var entry = new LogEntry { IsMultiline = isMultiline, - Level = level, + Level = logEvent.Level, Line = line, - TimeStamp = offset, + TimeStamp = logEvent.Timestamp, }; + if (logEvent.Properties.TryGetValue("SourceContext", out var sourceProp) && + sourceProp is ScalarValue { Value: string value }) + { + entry.Source = value; + } + this.logText.Add(entry); if (!this.isFiltered) @@ -459,13 +504,14 @@ namespace Dalamud.Interface.Internal.Windows private bool IsFilterApplicable(LogEntry entry) { - if (this.levelFilter.HasValue) - { - return entry.Level == this.levelFilter.Value; - } + if (this.levelFilter > 0 && ((this.levelFilter >> (int)entry.Level) & 1) == 0) + return false; - if (!string.IsNullOrEmpty(this.textFilter)) - return entry.Line.Contains(this.textFilter); + if (this.sourceFilters.Count > 0 && !this.sourceFilters.Contains(entry.Source)) + return false; + + if (!string.IsNullOrEmpty(this.textFilter) && !entry.Line.Contains(this.textFilter)) + return false; return true; } @@ -500,9 +546,9 @@ namespace Dalamud.Interface.Internal.Windows _ => throw new ArgumentOutOfRangeException(level.ToString(), "Invalid LogEventLevel"), }; - private void OnLogLine(object sender, (string Line, LogEventLevel Level, DateTimeOffset Offset, Exception? Exception) logEvent) + private void OnLogLine(object sender, (string Line, LogEvent LogEvent) logEvent) { - this.HandleLogLine(logEvent.Line, logEvent.Level, logEvent.Offset); + this.HandleLogLine(logEvent.Line, logEvent.LogEvent); } private class LogEntry @@ -514,6 +560,8 @@ namespace Dalamud.Interface.Internal.Windows public DateTimeOffset TimeStamp { get; set; } public bool IsMultiline { get; set; } + + public string? Source { get; set; } } } } diff --git a/Dalamud/Logging/Internal/SerilogEventSink.cs b/Dalamud/Logging/Internal/SerilogEventSink.cs index eb7c23d10..9327f672c 100644 --- a/Dalamud/Logging/Internal/SerilogEventSink.cs +++ b/Dalamud/Logging/Internal/SerilogEventSink.cs @@ -25,7 +25,7 @@ namespace Dalamud.Logging.Internal /// /// Event on a log line being emitted. /// - public event EventHandler<(string Line, LogEventLevel Level, DateTimeOffset TimeStamp, Exception? Exception)>? LogLine; + public event EventHandler<(string Line, LogEvent LogEvent)>? LogLine; /// /// Gets the default instance. @@ -40,12 +40,18 @@ namespace Dalamud.Logging.Internal { var message = logEvent.RenderMessage(this.formatProvider); + if (logEvent.Properties.TryGetValue("SourceContext", out var sourceProp) && + sourceProp is ScalarValue { Value: string source }) + { + message = $"[{source}] {message}"; + } + if (logEvent.Exception != null) { message += "\n" + logEvent.Exception; } - this.LogLine?.Invoke(this, (message, logEvent.Level, logEvent.Timestamp, logEvent.Exception)); + this.LogLine?.Invoke(this, (message, logEvent)); } } } diff --git a/Dalamud/Logging/PluginLog.cs b/Dalamud/Logging/PluginLog.cs index a21363854..5b1de1f64 100644 --- a/Dalamud/Logging/PluginLog.cs +++ b/Dalamud/Logging/PluginLog.cs @@ -1,6 +1,9 @@ using System; using System.Reflection; +using Serilog; +using Serilog.Events; + namespace Dalamud.Logging { /// @@ -16,7 +19,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Log(string messageTemplate, params object[] values) - => Serilog.Log.Information($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Information, messageTemplate, null, values); /// /// Log a templated message to the in-game debug log. @@ -25,7 +28,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Log(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Information(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Information, messageTemplate, exception, values); /// /// Log a templated verbose message to the in-game debug log. @@ -33,7 +36,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogVerbose(string messageTemplate, params object[] values) - => Serilog.Log.Verbose($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Verbose, messageTemplate, null, values); /// /// Log a templated verbose message to the in-game debug log. @@ -42,7 +45,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogVerbose(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Verbose(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Verbose, messageTemplate, exception, values); /// /// Log a templated debug message to the in-game debug log. @@ -50,7 +53,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogDebug(string messageTemplate, params object[] values) - => Serilog.Log.Debug($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Debug, messageTemplate, null, values); /// /// Log a templated debug message to the in-game debug log. @@ -59,7 +62,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogDebug(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Debug(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Debug, messageTemplate, exception, values); /// /// Log a templated information message to the in-game debug log. @@ -67,7 +70,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogInformation(string messageTemplate, params object[] values) - => Serilog.Log.Information($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Information, messageTemplate, null, values); /// /// Log a templated information message to the in-game debug log. @@ -76,7 +79,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogInformation(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Information(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Information, messageTemplate, exception, values); /// /// Log a templated warning message to the in-game debug log. @@ -84,7 +87,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogWarning(string messageTemplate, params object[] values) - => Serilog.Log.Warning($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Warning, messageTemplate, null, values); /// /// Log a templated warning message to the in-game debug log. @@ -93,7 +96,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogWarning(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Warning(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Warning, messageTemplate, exception, values); /// /// Log a templated error message to the in-game debug log. @@ -101,7 +104,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogError(string messageTemplate, params object[] values) - => Serilog.Log.Error($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Error, messageTemplate, null, values); /// /// Log a templated error message to the in-game debug log. @@ -110,7 +113,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogError(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Error(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Error, messageTemplate, exception, values); /// /// Log a templated fatal message to the in-game debug log. @@ -118,7 +121,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogFatal(string messageTemplate, params object[] values) - => Serilog.Log.Fatal($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Fatal, messageTemplate, null, values); /// /// Log a templated fatal message to the in-game debug log. @@ -127,7 +130,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void LogFatal(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Fatal(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Fatal, messageTemplate, exception, values); #endregion @@ -139,7 +142,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Verbose(string messageTemplate, params object[] values) - => Serilog.Log.Verbose($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Verbose, messageTemplate, null, values); /// /// Log a templated verbose message to the in-game debug log. @@ -148,7 +151,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Verbose(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Verbose(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Verbose, messageTemplate, exception, values); /// /// Log a templated debug message to the in-game debug log. @@ -156,7 +159,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Debug(string messageTemplate, params object[] values) - => Serilog.Log.Debug($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Debug, messageTemplate, null, values); /// /// Log a templated debug message to the in-game debug log. @@ -165,7 +168,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Debug(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Debug(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Debug, messageTemplate, exception, values); /// /// Log a templated information message to the in-game debug log. @@ -173,7 +176,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Information(string messageTemplate, params object[] values) - => Serilog.Log.Information($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Information, messageTemplate, null, values); /// /// Log a templated information message to the in-game debug log. @@ -182,7 +185,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Information(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Information(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Information, messageTemplate, exception, values); /// /// Log a templated warning message to the in-game debug log. @@ -190,7 +193,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Warning(string messageTemplate, params object[] values) - => Serilog.Log.Warning($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Warning, messageTemplate, null, values); /// /// Log a templated warning message to the in-game debug log. @@ -199,7 +202,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Warning(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Warning(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Warning, messageTemplate, exception, values); /// /// Log a templated error message to the in-game debug log. @@ -207,7 +210,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Error(string messageTemplate, params object[] values) - => Serilog.Log.Error($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Error, messageTemplate, null, values); /// /// Log a templated error message to the in-game debug log. @@ -216,7 +219,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Error(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Error(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Error, messageTemplate, exception, values); /// /// Log a templated fatal message to the in-game debug log. @@ -224,7 +227,7 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Fatal(string messageTemplate, params object[] values) - => Serilog.Log.Fatal($"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Fatal, messageTemplate, null, values); /// /// Log a templated fatal message to the in-game debug log. @@ -233,8 +236,19 @@ namespace Dalamud.Logging /// The message template. /// Values to log. public static void Fatal(Exception exception, string messageTemplate, params object[] values) - => Serilog.Log.Fatal(exception, $"[{Assembly.GetCallingAssembly().GetName().Name}] {messageTemplate}", values); + => WriteLog(Assembly.GetCallingAssembly().GetName().Name, LogEventLevel.Fatal, messageTemplate, exception, values); #endregion + + private static ILogger GetPluginLogger(string? pluginName) + { + return Serilog.Log.ForContext("SourceContext", pluginName ?? string.Empty); + } + + private static void WriteLog(string? pluginName, LogEventLevel level, string messageTemplate, Exception? exception = null, params object[] values) + { + var pluginLogger = GetPluginLogger(pluginName); + pluginLogger.Write(level, exception: exception, messageTemplate: messageTemplate, values); + } } }