diff --git a/src/Umbraco.Core/Logging/DisposableTimer.cs b/src/Umbraco.Core/Logging/DisposableTimer.cs index 50bfd537cd..58e951ab3b 100644 --- a/src/Umbraco.Core/Logging/DisposableTimer.cs +++ b/src/Umbraco.Core/Logging/DisposableTimer.cs @@ -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(); + } } } } diff --git a/src/Umbraco.Core/Logging/IProfilingLogger.cs b/src/Umbraco.Core/Logging/IProfilingLogger.cs index fd51bd2da3..4a0714fd0c 100644 --- a/src/Umbraco.Core/Logging/IProfilingLogger.cs +++ b/src/Umbraco.Core/Logging/IProfilingLogger.cs @@ -1,4 +1,4 @@ -using System; +using System; namespace Umbraco.Cms.Core.Logging { @@ -10,31 +10,31 @@ namespace Umbraco.Cms.Core.Logging /// /// Profiles an action and log as information messages. /// - DisposableTimer TraceDuration(string startMessage); + DisposableTimer TraceDuration(string startMessage, object[] startMessageArgs = null); /// /// Profiles an action and log as information messages. /// - DisposableTimer TraceDuration(string startMessage, string completeMessage, string failMessage = null); + DisposableTimer TraceDuration(string startMessage, string completeMessage, string failMessage = null, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null); /// /// Profiles an action and log as information messages. /// - 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); /// /// Profiles an action and log as debug messages. /// - DisposableTimer DebugDuration(string startMessage); + DisposableTimer DebugDuration(string startMessage, object[] startMessageArgs = null); /// /// Profiles an action and log as debug messages. /// - DisposableTimer DebugDuration(string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0); + DisposableTimer DebugDuration(string startMessage, string completeMessage, string failMessage = null, int thresholdMilliseconds = 0, object[] startMessageArgs = null, object[] endMessageArgs = null, object[] failMessageArgs = null); /// /// Profiles an action and log as debug messages. /// - 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); } } diff --git a/src/Umbraco.Core/Logging/ProfilingLogger.cs b/src/Umbraco.Core/Logging/ProfilingLogger.cs index 6a6bcfd850..9c66c95d24 100644 --- a/src/Umbraco.Core/Logging/ProfilingLogger.cs +++ b/src/Umbraco.Core/Logging/ProfilingLogger.cs @@ -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(string startMessage) - { - return TraceDuration(startMessage, "Completed."); - } + public DisposableTimer TraceDuration(string startMessage, object[] startMessageArgs = null) + => TraceDuration(startMessage, "Completed.", startMessageArgs: startMessageArgs); - public DisposableTimer TraceDuration(string startMessage, string completeMessage, string failMessage = null) - { - return new DisposableTimer(Logger, LogLevel.Information, Profiler, typeof(T), startMessage, completeMessage, failMessage); - } + public DisposableTimer TraceDuration(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(string startMessage) - { - return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug) - ? DebugDuration(startMessage, "Completed.") + public DisposableTimer DebugDuration(string startMessage, object[] startMessageArgs = null) + => Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug) + ? DebugDuration(startMessage, "Completed.", startMessageArgs: startMessageArgs) : null; - } - public DisposableTimer DebugDuration(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(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