yv01p/Umbraco-CMS
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Allows for structured logging with the IProfilingLogger (#9958)

Browse Source 
* Allows for structured logging with the IProfilingLogger

* Review fixes

Co-authored-by: Bjarke Berg <mail@bergmania.dk>
This commit is contained in:
Shannon Deminick
2021-04-27 17:10:30 +10:00
committed by GitHub
parent 51a720b16c
commit eaa46fe190
3 changed files with 107 additions and 50 deletions
Download Patch File Download Diff File Expand all files Collapse all files

99
src/Umbraco.Core/Logging/DisposableTimer.cs
View File

@@ -16,13 +16,24 @@ namespace Umbraco.Cms.Core.Logging
private readonly IDisposable _profilerStep;
private readonly string _endMessage;
private string _failMessage;
private readonly object[] _endMessageArgs;
private readonly object[] _failMessageArgs;
private Exception _failException;
private bool _failed;
private readonly string _timingId;
// internal - created by profiling logger
internal DisposableTimer(ILogger logger, LogLevel level, IProfiler profiler, Type loggerType,
string startMessage, string endMessage, string failMessage = null,
internal DisposableTimer(
ILogger logger,
LogLevel level,
IProfiler profiler,
Type loggerType,
string startMessage,
string endMessage,
string failMessage = null,
object[] startMessageArgs = null,
object[] endMessageArgs = null,
object[] failMessageArgs = null,
int thresholdMilliseconds = 0)
{
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
@@ -30,6 +41,8 @@ namespace Umbraco.Cms.Core.Logging
_loggerType = loggerType ?? throw new ArgumentNullException(nameof(loggerType));
_endMessage = endMessage;
_failMessage = failMessage;
_endMessageArgs = endMessageArgs;
_failMessageArgs = failMessageArgs;
_thresholdMilliseconds = thresholdMilliseconds < 0 ? 0 : thresholdMilliseconds;
_timingId = Guid.NewGuid().ToString("N").Substring(0, 7); // keep it short-ish
@@ -38,10 +51,30 @@ namespace Umbraco.Cms.Core.Logging
switch (_level)
{
case LogLevel.Debug:
logger.LogDebug("{StartMessage} [Timing {TimingId}]", startMessage, _timingId);
if (startMessageArgs == null)
{
logger.LogDebug("{StartMessage} [Timing {TimingId}]", startMessage, _timingId);
}
else
{
var args = new object[startMessageArgs.Length + 1];
startMessageArgs.CopyTo(args, 0);
args[startMessageArgs.Length] = _timingId;
logger.LogDebug(startMessage + " [Timing {TimingId}]", args);
}
break;
case LogLevel.Information:
logger.LogInformation("{StartMessage} [Timing {TimingId}]", startMessage, _timingId);
if (startMessageArgs == null)
{
logger.LogInformation("{StartMessage} [Timing {TimingId}]", startMessage, _timingId);
}
else
{
var args = new object[startMessageArgs.Length + 1];
startMessageArgs.CopyTo(args, 0);
args[startMessageArgs.Length] = _timingId;
logger.LogDebug(startMessage + " [Timing {TimingId}]", args);
}
break;
default:
throw new ArgumentOutOfRangeException(nameof(level));
@@ -85,19 +118,55 @@ namespace Umbraco.Cms.Core.Logging
{
if (_failed)
{
_logger.LogError(_failException, "{FailMessage} ({Duration}ms) [Timing {TimingId}]", _failMessage, Stopwatch.ElapsedMilliseconds, _timingId);
if (_failMessageArgs is null)
{
_logger.LogError(_failException, "{FailMessage} ({Duration}ms) [Timing {TimingId}]", _failMessage, Stopwatch.ElapsedMilliseconds, _timingId);
}
else
{
var args = new object[_failMessageArgs.Length + 2];
_failMessageArgs.CopyTo(args, 0);
args[_failMessageArgs.Length - 1] = Stopwatch.ElapsedMilliseconds;
args[_failMessageArgs.Length] = _timingId;
_logger.LogError(_failException, _failMessage + " ({Duration}ms) [Timing {TimingId}]", args);
}
}
else switch (_level)
else
{
case LogLevel.Debug:
_logger.LogDebug("{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId);
break;
case LogLevel.Information:
_logger.LogInformation("{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId);
break;
// filtered in the ctor
//default:
// throw new Exception();
switch (_level)
{
case LogLevel.Debug:
if (_endMessageArgs == null)
{
_logger.LogDebug("{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId);
}
else
{
var args = new object[_endMessageArgs.Length + 2];
_endMessageArgs.CopyTo(args, 0);
args[args.Length - 1] = Stopwatch.ElapsedMilliseconds;
args[args.Length] = _timingId;
_logger.LogDebug(_endMessage + " ({Duration}ms) [Timing {TimingId}]", args);
}
break;
case LogLevel.Information:
if (_endMessageArgs == null)
{
_logger.LogInformation("{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId);
}
else
{
var args = new object[_endMessageArgs.Length + 2];
_endMessageArgs.CopyTo(args, 0);
args[_endMessageArgs.Length - 1] = Stopwatch.ElapsedMilliseconds;
args[_endMessageArgs.Length] = _timingId;
_logger.LogInformation(_endMessage + " ({Duration}ms) [Timing {TimingId}]", args);
}
break;
// filtered in the ctor
//default:
// throw new Exception();
}
}
}
}

14
src/Umbraco.Core/Logging/IProfilingLogger.cs
View File

@@ -1,4 +1,4 @@
using System;
using System;
namespace Umbraco.Cms.Core.Logging
{
@@ -10,31 +10,31 @@ namespace Umbraco.Cms.Core.Logging
/// <summary>
/// Profiles an action and log as information messages.
/// </summary>
DisposableTimer TraceDuration<T>(string startMessage);
DisposableTimer TraceDuration<T>(string startMessage, object[] startMessageArgs = null);
/// <summary>
/// Profiles an action and log as information messages.
/// </summary>
DisposableTimer TraceDuration<T>(string startMessage, string completeMessage, string failMessage = null);
DisposableTimer TraceDuration<T>(string startMessage, string completeMessage, string failMessage = null, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null);
/// <summary>
/// Profiles an action and log as information messages.
/// </summary>
DisposableTimer TraceDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null);
DisposableTimer TraceDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null);
/// <summary>
/// Profiles an action and log as debug messages.
/// </summary>
DisposableTimer DebugDuration<T>(string startMessage);
DisposableTimer DebugDuration<T>(string startMessage, object[] startMessageArgs = null);
/// <summary>
/// Profiles an action and log as debug messages.
/// </summary>
DisposableTimer DebugDuration<T>(string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0);
DisposableTimer DebugDuration<T>(string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null);
/// <summary>
/// Profiles an action and log as debug messages.
/// </summary>
DisposableTimer DebugDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0);
DisposableTimer DebugDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null);
}
}

44
src/Umbraco.Core/Logging/ProfilingLogger.cs
View File

@@ -1,4 +1,4 @@
using System;
using System;
using Microsoft.Extensions.Logging;
namespace Umbraco.Cms.Core.Logging
@@ -27,41 +27,29 @@ namespace Umbraco.Cms.Core.Logging
Profiler = profiler ?? throw new ArgumentNullException(nameof(profiler));
}
public DisposableTimer TraceDuration<T>(string startMessage)
{
return TraceDuration<T>(startMessage, "Completed.");
}
public DisposableTimer TraceDuration<T>(string startMessage, object[] startMessageArgs = null)
=> TraceDuration<T>(startMessage, "Completed.", startMessageArgs: startMessageArgs);
public DisposableTimer TraceDuration<T>(string startMessage, string completeMessage, string failMessage = null)
{
return new DisposableTimer(Logger, LogLevel.Information, Profiler, typeof(T), startMessage, completeMessage, failMessage);
}
public DisposableTimer TraceDuration<T>(string startMessage, string completeMessage, string failMessage = null, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null)
=> new DisposableTimer(Logger, LogLevel.Information, Profiler, typeof(T), startMessage, completeMessage, failMessage);
public DisposableTimer TraceDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null)
{
return new DisposableTimer(Logger, LogLevel.Information, Profiler, loggerType, startMessage, completeMessage, failMessage);
}
public DisposableTimer TraceDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null)
=> new DisposableTimer(Logger, LogLevel.Information, Profiler, loggerType, startMessage, completeMessage, failMessage);
public DisposableTimer DebugDuration<T>(string startMessage)
{
return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)
? DebugDuration<T>(startMessage, "Completed.")
public DisposableTimer DebugDuration<T>(string startMessage, object[] startMessageArgs = null)
=> Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)
? DebugDuration<T>(startMessage, "Completed.", startMessageArgs: startMessageArgs)
: null;
}
public DisposableTimer DebugDuration<T>(string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0)
{
return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)
? new DisposableTimer(Logger, LogLevel.Debug, Profiler, typeof(T), startMessage, completeMessage, failMessage, thresholdMilliseconds)
public DisposableTimer DebugDuration<T>(string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null)
=> Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)
? new DisposableTimer(Logger, LogLevel.Debug, Profiler, typeof(T), startMessage, completeMessage, failMessage, startMessageArgs, endMessageArgs, failMessageArgs, thresholdMilliseconds)
: null;
}
public DisposableTimer DebugDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0)
{
return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)
? new DisposableTimer(Logger, LogLevel.Debug, Profiler, loggerType, startMessage, completeMessage, failMessage, thresholdMilliseconds)
public DisposableTimer DebugDuration(Type loggerType, string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null)
=> Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)
? new DisposableTimer(Logger, LogLevel.Debug, Profiler, loggerType, startMessage, completeMessage, failMessage, startMessageArgs, endMessageArgs, failMessageArgs, thresholdMilliseconds)
: null;
}
#region ILogger