From c8f04923539f6136a37c9bd6e5e784636ea642a2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ivan=20Sto=C5=A1i=C4=87?= Date: Tue, 9 Feb 2021 14:54:39 +0100 Subject: [PATCH] [PT Run] Improve logs (#9518) * Improved some aspects, more work left * Fix Log being called instead of building a string * Address PR comments * Okay, spell checker --- .github/actions/spell-check/expect.txt | 1 + .../Plugins/Microsoft.Plugin.Program/Main.cs | 4 +- .../Programs/ShellLinkHelper.cs | 2 +- .../launcher/PowerLauncher/App.xaml.cs | 13 ++++--- .../PowerLauncher/Plugin/PluginManager.cs | 4 +- .../PowerLauncher/Plugin/PluginsLoader.cs | 2 +- .../Wox.Infrastructure/Image/ImageLoader.cs | 2 +- src/modules/launcher/Wox.Plugin/Logger/Log.cs | 37 ++++++++++--------- 8 files changed, 35 insertions(+), 30 deletions(-) diff --git a/.github/actions/spell-check/expect.txt b/.github/actions/spell-check/expect.txt index 20d67b27b3..32677391b9 100644 --- a/.github/actions/spell-check/expect.txt +++ b/.github/actions/spell-check/expect.txt @@ -1228,6 +1228,7 @@ LOGMSG logon LOGPIXELSX LOn +longdate lookbehind lowlevel LOWORD diff --git a/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Main.cs b/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Main.cs index 1b875a19d1..722b973f8c 100644 --- a/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Main.cs +++ b/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Main.cs @@ -52,12 +52,12 @@ namespace Microsoft.Plugin.Program var a = Task.Run(() => { - Stopwatch.Normal("|Microsoft.Plugin.Program.Main|Win32Program index cost", _win32ProgramRepository.IndexPrograms); + Stopwatch.Normal("Microsoft.Plugin.Program.Main - Win32Program index cost", _win32ProgramRepository.IndexPrograms); }); var b = Task.Run(() => { - Stopwatch.Normal("|Microsoft.Plugin.Program.Main|Package index cost", _packageRepository.IndexPrograms); + Stopwatch.Normal("Microsoft.Plugin.Program.Main - Package index cost", _packageRepository.IndexPrograms); }); Task.WaitAll(a, b); diff --git a/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Programs/ShellLinkHelper.cs b/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Programs/ShellLinkHelper.cs index ed14f477af..732b6bcb77 100644 --- a/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Programs/ShellLinkHelper.cs +++ b/src/modules/launcher/Plugins/Microsoft.Plugin.Program/Programs/ShellLinkHelper.cs @@ -169,7 +169,7 @@ namespace Microsoft.Plugin.Program.Programs } catch (Exception e) { - Log.Exception($"|Failed to fetch description for {target}, {e.Message}", e, GetType()); + Log.Exception($"Failed to fetch description for {target}, {e.Message}", e, GetType()); Description = string.Empty; } diff --git a/src/modules/launcher/PowerLauncher/App.xaml.cs b/src/modules/launcher/PowerLauncher/App.xaml.cs index 7791870156..8aa2587d3c 100644 --- a/src/modules/launcher/PowerLauncher/App.xaml.cs +++ b/src/modules/launcher/PowerLauncher/App.xaml.cs @@ -5,6 +5,7 @@ using System; using System.Diagnostics; using System.Linq; +using System.Text; using System.Windows; using ManagedCommon; using Microsoft.PowerLauncher.Telemetry; @@ -79,10 +80,11 @@ namespace PowerLauncher var bootTime = new System.Diagnostics.Stopwatch(); bootTime.Start(); - Stopwatch.Normal("|App.OnStartup|Startup cost", () => + Stopwatch.Normal("App.OnStartup - Startup cost", () => { - Log.Info("Begin PowerToys Run startup ----------------------------------------------------", GetType()); - Log.Info($"Runtime info:{ErrorReporting.RuntimeInfo()}", GetType()); + var textToLog = new StringBuilder(); + textToLog.AppendLine("Begin PowerToys Run startup ----------------------------------------------------"); + textToLog.AppendLine($"Runtime info:{ErrorReporting.RuntimeInfo()}"); RegisterAppDomainExceptions(); RegisterDispatcherUnhandledException(); @@ -117,10 +119,11 @@ namespace PowerLauncher _mainVM.MainWindowVisibility = Visibility.Visible; _mainVM.ColdStartFix(); _themeManager.ThemeChanged += OnThemeChanged; - Log.Info("End PowerToys Run startup ---------------------------------------------------- ", GetType()); + textToLog.AppendLine("End PowerToys Run startup ---------------------------------------------------- "); bootTime.Stop(); + Log.Info(textToLog.ToString(), GetType()); PowerToysTelemetry.Log.WriteEvent(new LauncherBootEvent() { BootTimeMs = bootTime.ElapsedMilliseconds }); // [Conditional("RELEASE")] @@ -175,7 +178,7 @@ namespace PowerLauncher { if (!_disposed) { - Stopwatch.Normal("|App.OnExit|Exit cost", () => + Stopwatch.Normal("App.OnExit - Exit cost", () => { Log.Info("Start PowerToys Run Exit---------------------------------------------------- ", GetType()); if (disposing) diff --git a/src/modules/launcher/PowerLauncher/Plugin/PluginManager.cs b/src/modules/launcher/PowerLauncher/Plugin/PluginManager.cs index 3359ec1041..5a75b3486d 100644 --- a/src/modules/launcher/PowerLauncher/Plugin/PluginManager.cs +++ b/src/modules/launcher/PowerLauncher/Plugin/PluginManager.cs @@ -100,7 +100,7 @@ namespace PowerLauncher.Plugin { try { - var milliseconds = Stopwatch.Debug($"|PluginManager.InitializePlugins|Init method time cost for <{pair.Metadata.Name}>", () => + var milliseconds = Stopwatch.Debug($"PluginManager.InitializePlugins - Init method time cost for <{pair.Metadata.Name}>", () => { pair.Plugin.Init(new PluginInitContext { @@ -175,7 +175,7 @@ namespace PowerLauncher.Plugin { List results = null; var metadata = pair.Metadata; - var milliseconds = Stopwatch.Debug($"|PluginManager.QueryForPlugin|Cost for {metadata.Name}", () => + var milliseconds = Stopwatch.Debug($"PluginManager.QueryForPlugin - Cost for {metadata.Name}", () => { if (delayedExecution && (pair.Plugin is IDelayedExecutionPlugin)) { diff --git a/src/modules/launcher/PowerLauncher/Plugin/PluginsLoader.cs b/src/modules/launcher/PowerLauncher/Plugin/PluginsLoader.cs index 45cb743a5e..44434135ad 100644 --- a/src/modules/launcher/PowerLauncher/Plugin/PluginsLoader.cs +++ b/src/modules/launcher/PowerLauncher/Plugin/PluginsLoader.cs @@ -31,7 +31,7 @@ namespace PowerLauncher.Plugin foreach (var metadata in metadatas) { - var milliseconds = Stopwatch.Debug($"|PluginsLoader.CSharpPlugins|Constructor init cost for {metadata.Name}", () => + var milliseconds = Stopwatch.Debug($"PluginsLoader.CSharpPlugins - Constructor init cost for {metadata.Name}", () => { #if DEBUG var assembly = AssemblyLoadContext.Default.LoadFromAssemblyPath(metadata.ExecuteFilePath); diff --git a/src/modules/launcher/Wox.Infrastructure/Image/ImageLoader.cs b/src/modules/launcher/Wox.Infrastructure/Image/ImageLoader.cs index 2e9ab1935f..ccb9d210d6 100644 --- a/src/modules/launcher/Wox.Infrastructure/Image/ImageLoader.cs +++ b/src/modules/launcher/Wox.Infrastructure/Image/ImageLoader.cs @@ -63,7 +63,7 @@ namespace Wox.Infrastructure.Image UpdateIconPath(theme); Task.Run(() => { - Stopwatch.Normal("|ImageLoader.Initialize|Preload images cost", () => + Stopwatch.Normal("ImageLoader.Initialize - Preload images cost", () => { ImageCache.Usage.AsParallel().ForAll(x => { diff --git a/src/modules/launcher/Wox.Plugin/Logger/Log.cs b/src/modules/launcher/Wox.Plugin/Logger/Log.cs index 69dd96a558..31b02a9cb0 100644 --- a/src/modules/launcher/Wox.Plugin/Logger/Log.cs +++ b/src/modules/launcher/Wox.Plugin/Logger/Log.cs @@ -5,6 +5,7 @@ using System; using System.IO.Abstractions; using System.Runtime.CompilerServices; +using System.Text; using NLog; using NLog.Config; using NLog.Targets; @@ -31,6 +32,7 @@ namespace Wox.Plugin.Logger var configuration = new LoggingConfiguration(); var target = new FileTarget(); + target.Layout = NLog.Layouts.Layout.FromString("[${longdate}] [${level:uppercase=true}]${message}\n"); configuration.AddTarget("file", target); // Adding CurrentCulture since this is user facing @@ -48,27 +50,28 @@ namespace Wox.Plugin.Logger private static void LogInternalException(string message, System.Exception e, Type fullClassName, [CallerMemberName] string methodName = "", [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0) { var logger = GetLogger(fullClassName.FullName, methodName); + var formattedOutput = new StringBuilder(); - LogInternal(LogLevel.Error, message, fullClassName, logger, methodName, sourceFilePath, sourceLineNumber); - - logger.Error("-------------------------- Begin exception --------------------------"); - logger.Error($"\n\tMessage:\n\t {message}"); + formattedOutput.AppendLine("-------------------------- Begin exception --------------------------"); + formattedOutput.AppendLine($"Message: {message}"); do { - logger.Error( - $"\n\tException full name:\n\t <{e.GetType().FullName}>" + - $"\n\tException message:\n\t <{e.Message}>" + - $"\n\tException stack trace:\n\t <{e.StackTrace}>" + - $"\n\tException source:\n\t <{e.Source}>" + - $"\n\tException target site:\n\t <{e.TargetSite}>" + - $"\n\tException HResult:\n\t <{e.HResult}>"); + formattedOutput.Append( + "\n" + + $"Exception full name : {e.GetType().FullName}\n" + + $"Exception message : {e.Message}\n" + + $"Exception stack trace:\n{e.StackTrace}\n" + + $"Exception source : {e.Source}\n" + + $"Exception target site: {e.TargetSite}\n" + + $"Exception HResult : {e.HResult}\n"); e = e.InnerException; } while (e != null); - logger.Error("-------------------------- End exception --------------------------"); + formattedOutput.AppendLine("-------------------------- End exception --------------------------"); + LogInternal(LogLevel.Error, formattedOutput.ToString(), logger, sourceFilePath, sourceLineNumber); } public static void Info(string message, Type fullClassName, [CallerMemberName] string methodName = "", [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0) @@ -125,15 +128,13 @@ namespace Wox.Plugin.Logger { var logger = GetLogger(fullClassName.FullName, methodName); - LogInternal(level, message, fullClassName, logger, methodName, sourceFilePath, sourceLineNumber); + LogInternal(level, message, logger, sourceFilePath, sourceLineNumber); } - private static void LogInternal(LogLevel level, string message, Type fullClassName, NLog.Logger logger, [CallerMemberName] string methodName = "", [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0) + private static void LogInternal(LogLevel level, string message, NLog.Logger logger, [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0) { - // System.Diagnostics.Debug.WriteLine($" {level.Name} | {message}"); - var msg = $"\n\tMessage: {message}" + - $"\n\tArea: {fullClassName}.{methodName}" + - $"\n\tSource Path: {sourceFilePath}::{sourceLineNumber}\n"; + var msg = $" [{sourceFilePath}::{sourceLineNumber}]" + + $"\n{message}"; logger.Log(level, msg); }