[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
This commit is contained in:
Ivan Stošić 2021-02-09 14:54:39 +01:00 committed by GitHub
parent 9c6dfd493c
commit c8f0492353
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 35 additions and 30 deletions

View File

@ -1228,6 +1228,7 @@ LOGMSG
logon
LOGPIXELSX
LOn
longdate
lookbehind
lowlevel
LOWORD

View File

@ -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);

View File

@ -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;
}

View File

@ -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)

View File

@ -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<Result> 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))
{

View File

@ -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);

View File

@ -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 =>
{

View File

@ -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);
}