From e784cfa96073e33f5fd581d1383d275511e47706 Mon Sep 17 00:00:00 2001 From: Chad Date: Wed, 7 Jun 2023 21:47:05 +1200 Subject: [PATCH] Improve logging performance by checking Trace/Debug log level is enabled (#12793) --- .../SqlServerDistributedLockingMechanism.cs | 23 ++++-- .../Services/SqlServerSyntaxProvider.cs | 7 +- .../SqliteDistributedLockingMechanism.cs | 23 ++++-- .../Composing/ComponentCollection.cs | 8 +- .../Composing/ComponentCollectionBuilder.cs | 4 +- src/Umbraco.Core/Composing/ComposerGraph.cs | 5 +- .../FindAssembliesWithReferencesTo.cs | 5 +- .../Composing/ReferenceResolver.cs | 5 +- src/Umbraco.Core/Composing/RuntimeHash.cs | 2 +- src/Umbraco.Core/Composing/TypeLoader.cs | 46 ++++++++--- .../Events/UserNotificationsHandler.cs | 5 +- src/Umbraco.Core/IO/FileSystems.cs | 12 ++- src/Umbraco.Core/Logging/DisposableTimer.cs | 21 ++++- src/Umbraco.Core/Logging/IProfilingLogger.cs | 7 ++ src/Umbraco.Core/Logging/LogProfiler.cs | 5 +- src/Umbraco.Core/Logging/ProfilingLogger.cs | 21 +++++ .../Routing/DefaultUrlProvider.cs | 5 +- .../Routing/UrlProviderExtensions.cs | 7 +- src/Umbraco.Core/Runtime/MainDom.cs | 16 +++- .../Services/ContentVersionService.cs | 16 +++- .../Services/NotificationService.cs | 16 +++- src/Umbraco.Core/Templates/HtmlUrlParser.cs | 7 +- .../UmbracoContentIndex.cs | 6 +- .../Examine/ContentIndexPopulator.cs | 5 +- .../Examine/ExamineIndexRebuilder.cs | 5 +- .../Examine/MediaIndexPopulator.cs | 5 +- .../HostedServices/ContentVersionCleanup.cs | 20 ++++- .../HostedServices/HealthCheckNotifier.cs | 17 +++- .../HostedServices/KeepAlive.cs | 12 ++- .../HostedServices/LogScrubber.cs | 17 +++- .../HostedServices/ReportSiteTask.cs | 5 +- .../HostedServices/ScheduledPublishing.cs | 20 ++++- .../HostedServices/TempFileCleanup.cs | 15 +++- .../Install/UnattendedInstaller.cs | 6 +- .../Install/UnattendedUpgrader.cs | 2 +- .../Mail/EmailSender.cs | 10 ++- .../DataTypes/PreValueMigratorCollection.cs | 5 +- .../AutoModelsNotificationHandler.cs | 11 ++- .../Packaging/PendingPackageMigrations.cs | 6 +- .../Repositories/Implement/UserRepository.cs | 12 ++- .../Persistence/UmbracoDatabase.cs | 15 +++- .../Persistence/UmbracoDatabaseFactory.cs | 16 +++- .../BlockGridPropertyValueConverter.cs | 2 +- .../BlockListPropertyValueConverter.cs | 4 +- .../MultiUrlPickerValueConverter.cs | 2 +- .../NestedContentManyValueConverter.cs | 2 +- .../NestedContentSingleValueConverter.cs | 2 +- .../PublishedContentTypeCache.cs | 15 +++- .../Runtime/CoreRuntime.cs | 15 ++-- .../Runtime/FileSystemMainDomLock.cs | 20 ++++- .../Runtime/RuntimeState.cs | 43 +++++++---- src/Umbraco.Infrastructure/Scoping/Scope.cs | 5 +- .../Security/MemberPasswordHasher.cs | 5 +- .../Services/CacheInstructionService.cs | 2 +- .../Sync/ServerMessengerBase.cs | 18 +++-- .../PublishedSnapshotService.cs | 42 +++++++--- .../ExamineManagementController.cs | 6 +- .../RedirectUrlManagementController.cs | 5 +- .../FileUploadCleanupFilterAttribute.cs | 6 +- .../HealthChecks/HealthCheckController.cs | 5 +- .../Install/InstallApiController.cs | 2 +- .../Controllers/RenderController.cs | 6 +- .../Macros/MacroRenderer.cs | 27 ++++--- .../Middleware/UmbracoRequestMiddleware.cs | 28 ++++--- .../InMemoryAuto/InMemoryModelFactory.cs | 77 ++++++++++++++----- .../Security/MemberSignInManager.cs | 5 +- .../Security/UmbracoSignInManager.cs | 5 +- .../ActionResults/UmbracoPageResult.cs | 2 +- .../Routing/PublicAccessRequestHandler.cs | 45 ++++++++--- 69 files changed, 648 insertions(+), 224 deletions(-) diff --git a/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerDistributedLockingMechanism.cs b/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerDistributedLockingMechanism.cs index 358eae2e38..cc2e1b5feb 100644 --- a/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerDistributedLockingMechanism.cs +++ b/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerDistributedLockingMechanism.cs @@ -70,8 +70,10 @@ public class SqlServerDistributedLockingMechanism : IDistributedLockingMechanism _timeout = timeout; LockId = lockId; LockType = lockType; - - _parent._logger.LogDebug("Requesting {lockType} for id {id}", LockType, LockId); + if (_parent._logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _parent._logger.LogDebug("Requesting {lockType} for id {id}", LockType, LockId); + } try { @@ -96,17 +98,24 @@ public class SqlServerDistributedLockingMechanism : IDistributedLockingMechanism throw new DistributedWriteLockTimeoutException(LockId); } - - _parent._logger.LogDebug("Acquired {lockType} for id {id}", LockType, LockId); + if (_parent._logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _parent._logger.LogDebug("Acquired {lockType} for id {id}", LockType, LockId); + } } public int LockId { get; } public DistributedLockType LockType { get; } - public void Dispose() => - // Mostly no op, cleaned up by completing transaction in scope. - _parent._logger.LogDebug("Dropped {lockType} for id {id}", LockType, LockId); + public void Dispose() + { + if (_parent._logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + // Mostly no op, cleaned up by completing transaction in scope. + _parent._logger.LogDebug("Dropped {lockType} for id {id}", LockType, LockId); + } + } public override string ToString() => $"SqlServerDistributedLock({LockId}, {LockType}"; diff --git a/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerSyntaxProvider.cs b/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerSyntaxProvider.cs index a1b9d2d8f0..055da32d75 100644 --- a/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerSyntaxProvider.cs +++ b/src/Umbraco.Cms.Persistence.SqlServer/Services/SqlServerSyntaxProvider.cs @@ -86,9 +86,10 @@ public class SqlServerSyntaxProvider : MicrosoftSqlSyntaxProviderBase - // Mostly no op, cleaned up by completing transaction in scope. - _parent._logger.LogDebug("Dropped {lockType} for id {id}", LockType, LockId); + public void Dispose() + { + if (_parent._logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + // Mostly no op, cleaned up by completing transaction in scope. + _parent._logger.LogDebug("Dropped {lockType} for id {id}", LockType, LockId); + } + } public override string ToString() => $"SqliteDistributedLock({LockId})"; diff --git a/src/Umbraco.Core/Composing/ComponentCollection.cs b/src/Umbraco.Core/Composing/ComponentCollection.cs index d64de626d0..506eb23134 100644 --- a/src/Umbraco.Core/Composing/ComponentCollection.cs +++ b/src/Umbraco.Core/Composing/ComponentCollection.cs @@ -23,13 +23,13 @@ public class ComponentCollection : BuilderCollectionBase public void Initialize() { - using (_profilingLogger.DebugDuration( + using (!_profilingLogger.IsEnabled(Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration( $"Initializing. (log components when >{LogThresholdMilliseconds}ms)", "Initialized.")) { foreach (IComponent component in this) { Type componentType = component.GetType(); - using (_profilingLogger.DebugDuration( + using (!_profilingLogger.IsEnabled(Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration( $"Initializing {componentType.FullName}.", $"Initialized {componentType.FullName}.", thresholdMilliseconds: LogThresholdMilliseconds)) @@ -42,14 +42,14 @@ public class ComponentCollection : BuilderCollectionBase public void Terminate() { - using (_profilingLogger.DebugDuration( + using (!_profilingLogger.IsEnabled(Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration( $"Terminating. (log components when >{LogThresholdMilliseconds}ms)", "Terminated.")) { // terminate components in reverse order foreach (IComponent component in this.Reverse()) { Type componentType = component.GetType(); - using (_profilingLogger.DebugDuration( + using (!_profilingLogger.IsEnabled(Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration( $"Terminating {componentType.FullName}.", $"Terminated {componentType.FullName}.", thresholdMilliseconds: LogThresholdMilliseconds)) diff --git a/src/Umbraco.Core/Composing/ComponentCollectionBuilder.cs b/src/Umbraco.Core/Composing/ComponentCollectionBuilder.cs index b77dfde819..04461db4fb 100644 --- a/src/Umbraco.Core/Composing/ComponentCollectionBuilder.cs +++ b/src/Umbraco.Core/Composing/ComponentCollectionBuilder.cs @@ -18,7 +18,7 @@ public class { IProfilingLogger logger = factory.GetRequiredService(); - using (logger.DebugDuration( + using (!logger.IsEnabled(Logging.LogLevel.Debug) ? null : logger.DebugDuration( $"Creating components. (log when >{LogThresholdMilliseconds}ms)", "Created.")) { return base.CreateItems(factory); @@ -29,7 +29,7 @@ public class { IProfilingLogger logger = factory.GetRequiredService(); - using (logger.DebugDuration( + using (!logger.IsEnabled(Logging.LogLevel.Debug) ? null : logger.DebugDuration( $"Creating {itemType.FullName}.", $"Created {itemType.FullName}.", thresholdMilliseconds: LogThresholdMilliseconds)) diff --git a/src/Umbraco.Core/Composing/ComposerGraph.cs b/src/Umbraco.Core/Composing/ComposerGraph.cs index 3c602b0ad9..a4e8f189f7 100644 --- a/src/Umbraco.Core/Composing/ComposerGraph.cs +++ b/src/Umbraco.Core/Composing/ComposerGraph.cs @@ -126,7 +126,10 @@ internal class ComposerGraph // bit verbose but should help for troubleshooting // var text = "Ordered Composers: " + Environment.NewLine + string.Join(Environment.NewLine, sortedComposerTypes) + Environment.NewLine; - _logger.LogDebug("Ordered Composers: {SortedComposerTypes}", sortedComposerTypes); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Ordered Composers: {SortedComposerTypes}", sortedComposerTypes); + } return sortedComposerTypes; } diff --git a/src/Umbraco.Core/Composing/FindAssembliesWithReferencesTo.cs b/src/Umbraco.Core/Composing/FindAssembliesWithReferencesTo.cs index f9e4ed6dbe..1b516636b3 100644 --- a/src/Umbraco.Core/Composing/FindAssembliesWithReferencesTo.cs +++ b/src/Umbraco.Core/Composing/FindAssembliesWithReferencesTo.cs @@ -57,7 +57,10 @@ internal class FindAssembliesWithReferencesTo catch (FileNotFoundException ex) { // occurs if we cannot load this ... for example in a test project where we aren't currently referencing Umbraco.Web, etc... - _logger.LogDebug(ex, "Could not load assembly " + target); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug(ex, "Could not load assembly " + target); + } } } } diff --git a/src/Umbraco.Core/Composing/ReferenceResolver.cs b/src/Umbraco.Core/Composing/ReferenceResolver.cs index 1924fb4b75..7ad290a192 100644 --- a/src/Umbraco.Core/Composing/ReferenceResolver.cs +++ b/src/Umbraco.Core/Composing/ReferenceResolver.cs @@ -70,7 +70,10 @@ internal class ReferenceResolver } catch (BadImageFormatException e) { - _logger.LogDebug(e, "Could not load {dll} for type scanning, skipping", dll); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug(e, "Could not load {dll} for type scanning, skipping", dll); + } } catch (SecurityException e) { diff --git a/src/Umbraco.Core/Composing/RuntimeHash.cs b/src/Umbraco.Core/Composing/RuntimeHash.cs index e66bedf79f..e7a621fe03 100644 --- a/src/Umbraco.Core/Composing/RuntimeHash.cs +++ b/src/Umbraco.Core/Composing/RuntimeHash.cs @@ -45,7 +45,7 @@ public class RuntimeHash : IRuntimeHash /// private string GetFileHash(IEnumerable<(FileSystemInfo fileOrFolder, bool scanFileContent)> filesAndFolders) { - using (_logger.DebugDuration("Determining hash of code files on disk", "Hash determined")) + using (!_logger.IsEnabled(Logging.LogLevel.Debug) ? null : _logger.DebugDuration("Determining hash of code files on disk", "Hash determined")) { // get the distinct file infos to hash var uniqInfos = new HashSet(); diff --git a/src/Umbraco.Core/Composing/TypeLoader.cs b/src/Umbraco.Core/Composing/TypeLoader.cs index 7fadd102da..9fc692f778 100644 --- a/src/Umbraco.Core/Composing/TypeLoader.cs +++ b/src/Umbraco.Core/Composing/TypeLoader.cs @@ -190,10 +190,13 @@ public sealed class TypeLoader if (!typeof(IDiscoverable).IsAssignableFrom(typeof(T))) { // warn - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Running a full, " + (cache ? string.Empty : "non-") + "cached, scan for non-discoverable type {TypeName} (slow).", typeof(T).FullName); + } return GetTypesInternal( typeof(T), @@ -214,9 +217,12 @@ public sealed class TypeLoader // warn if (!cache) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Running a non-cached, filter for discoverable type {TypeName} (slowish).", typeof(T).FullName); + } } // filter the cached discovered types (and maybe cache the result) @@ -253,11 +259,14 @@ public sealed class TypeLoader // if not IDiscoverable, directly get types if (!typeof(IDiscoverable).IsAssignableFrom(typeof(T))) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Running a full, " + (cache ? string.Empty : "non-") + "cached, scan for non-discoverable type {TypeName} / attribute {AttributeName} (slow).", typeof(T).FullName, typeof(TAttribute).FullName); + } return GetTypesInternal( typeof(T), @@ -278,10 +287,13 @@ public sealed class TypeLoader // warn if (!cache) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Running a non-cached, filter for discoverable type {TypeName} / attribute {AttributeName} (slowish).", typeof(T).FullName, typeof(TAttribute).FullName); + } } // filter the cached discovered types (and maybe cache the result) @@ -318,9 +330,12 @@ public sealed class TypeLoader if (!cache) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Running a full, non-cached, scan for types / attribute {AttributeName} (slow).", typeof(TAttribute).FullName); + } } return GetTypesInternal( @@ -376,7 +391,10 @@ public sealed class TypeLoader if (typeList != null) { // need to put some logging here to try to figure out why this is happening: http://issues.umbraco.org/issue/U4-3505 - _logger.LogDebug("Getting {TypeName}: found a cached type list.", GetName(baseType, attributeType)); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Getting {TypeName}: found a cached type list.", GetName(baseType, attributeType)); + } return typeList.Types; } @@ -384,7 +402,10 @@ public sealed class TypeLoader typeList = new TypeList(baseType, attributeType); // either we had to scan, or we could not get the types from the cache file - scan now - _logger.LogDebug("Getting {TypeName}: " + action + ".", GetName(baseType, attributeType)); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Getting {TypeName}: " + action + ".", GetName(baseType, attributeType)); + } foreach (Type t in finder()) { @@ -399,12 +420,17 @@ public sealed class TypeLoader { _types[listKey] = typeList; } - - _logger.LogDebug("Got {TypeName}, caching ({CacheType}).", GetName(baseType, attributeType), added.ToString().ToLowerInvariant()); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Got {TypeName}, caching ({CacheType}).", GetName(baseType, attributeType), added.ToString().ToLowerInvariant()); + } } else { - _logger.LogDebug("Got {TypeName}.", GetName(baseType, attributeType)); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Got {TypeName}.", GetName(baseType, attributeType)); + } } return typeList.Types; diff --git a/src/Umbraco.Core/Events/UserNotificationsHandler.cs b/src/Umbraco.Core/Events/UserNotificationsHandler.cs index 4b581788e8..6d15ec36aa 100644 --- a/src/Umbraco.Core/Events/UserNotificationsHandler.cs +++ b/src/Umbraco.Core/Events/UserNotificationsHandler.cs @@ -192,8 +192,11 @@ public sealed class UserNotificationsHandler : // if there is no current user, then use the admin if (user == null) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "There is no current Umbraco user logged in, the notifications will be sent from the administrator"); + } user = _userService.GetUserById(Constants.Security.SuperUserId); if (user == null) { diff --git a/src/Umbraco.Core/IO/FileSystems.cs b/src/Umbraco.Core/IO/FileSystems.cs index 2a5fa685df..69b66dc270 100644 --- a/src/Umbraco.Core/IO/FileSystems.cs +++ b/src/Umbraco.Core/IO/FileSystems.cs @@ -283,8 +283,10 @@ namespace Umbraco.Cms.Core.IO } _shadowCurrentId = id; - - _logger.LogDebug("Shadow '{ShadowId}'", _shadowCurrentId); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Shadow '{ShadowId}'", _shadowCurrentId); + } foreach (ShadowWrapper wrapper in _shadowWrappers) { @@ -307,8 +309,10 @@ namespace Umbraco.Cms.Core.IO { throw new InvalidOperationException("Not the current shadow."); } - - _logger.LogDebug("UnShadow '{ShadowId}' {Status}", id, completed ? "complete" : "abort"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("UnShadow '{ShadowId}' {Status}", id, completed ? "complete" : "abort"); + } var exceptions = new List(); foreach (ShadowWrapper wrapper in _shadowWrappers) diff --git a/src/Umbraco.Core/Logging/DisposableTimer.cs b/src/Umbraco.Core/Logging/DisposableTimer.cs index 6246724143..02bb52a19d 100644 --- a/src/Umbraco.Core/Logging/DisposableTimer.cs +++ b/src/Umbraco.Core/Logging/DisposableTimer.cs @@ -53,14 +53,21 @@ public class DisposableTimer : DisposableObjectSlim case LogLevel.Debug: if (startMessageArgs == null) { - logger.LogDebug("{StartMessage} [Timing {TimingId}]", startMessage, _timingId); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + logger.LogDebug("{StartMessage} [Timing {TimingId}]", startMessage, _timingId); + } } else { var args = new object[startMessageArgs.Length + 1]; startMessageArgs.CopyTo(args, 0); args[^1] = _timingId; - logger.LogDebug(startMessage + " [Timing {TimingId}]", args); + + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + logger.LogDebug(startMessage + " [Timing {TimingId}]", args); + } } break; @@ -139,11 +146,14 @@ public class DisposableTimer : DisposableObjectSlim case LogLevel.Debug: if (_endMessageArgs == null) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId); + } } else { @@ -151,7 +161,10 @@ public class DisposableTimer : DisposableObjectSlim _endMessageArgs.CopyTo(args, 0); args[^2] = Stopwatch.ElapsedMilliseconds; args[^1] = _timingId; - _logger.LogDebug(_endMessage + " ({Duration}ms) [Timing {TimingId}]", args); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug(_endMessage + " ({Duration}ms) [Timing {TimingId}]", args); + } } break; diff --git a/src/Umbraco.Core/Logging/IProfilingLogger.cs b/src/Umbraco.Core/Logging/IProfilingLogger.cs index 92c4d55f0c..77c4c869f6 100644 --- a/src/Umbraco.Core/Logging/IProfilingLogger.cs +++ b/src/Umbraco.Core/Logging/IProfilingLogger.cs @@ -62,4 +62,11 @@ public interface IProfilingLogger object[]? startMessageArgs = null, object[]? endMessageArgs = null, object[]? failMessageArgs = null); + + /// + /// Checks if the given logLevel is enabled. + /// + /// Level to be checked. + /// true if enabled. + bool IsEnabled(LogLevel logLevel) => true; } diff --git a/src/Umbraco.Core/Logging/LogProfiler.cs b/src/Umbraco.Core/Logging/LogProfiler.cs index 0504a2a1ae..84a57979bf 100644 --- a/src/Umbraco.Core/Logging/LogProfiler.cs +++ b/src/Umbraco.Core/Logging/LogProfiler.cs @@ -15,7 +15,10 @@ public class LogProfiler : IProfiler /// public IDisposable Step(string name) { - _logger.LogDebug("Begin: {ProfileName}", name); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Begin: {ProfileName}", name); + } return new LightDisposableTimer(duration => _logger.LogInformation("End {ProfileName} ({ProfileDuration}ms)", name, duration)); } diff --git a/src/Umbraco.Core/Logging/ProfilingLogger.cs b/src/Umbraco.Core/Logging/ProfilingLogger.cs index 997f139539..9c5c8bc17e 100644 --- a/src/Umbraco.Core/Logging/ProfilingLogger.cs +++ b/src/Umbraco.Core/Logging/ProfilingLogger.cs @@ -141,5 +141,26 @@ public sealed class ProfilingLogger : IProfilingLogger public void LogTrace(string messageTemplate, params object[] propertyValues) => Logger.LogTrace(messageTemplate, propertyValues); + ////> + public bool IsEnabled(LogLevel logLevel) + { + switch (logLevel) + { + case LogLevel.Verbose: + return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Trace); + case LogLevel.Debug: + return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug); + case LogLevel.Information: + return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Information); + case LogLevel.Warning: + return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Warning); + case LogLevel.Error: + return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Error); + case LogLevel.Fatal: + return Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Critical); + default: + return true; + } + } #endregion } diff --git a/src/Umbraco.Core/Routing/DefaultUrlProvider.cs b/src/Umbraco.Core/Routing/DefaultUrlProvider.cs index 173515a001..97e2f73e88 100644 --- a/src/Umbraco.Core/Routing/DefaultUrlProvider.cs +++ b/src/Umbraco.Core/Routing/DefaultUrlProvider.cs @@ -137,9 +137,12 @@ public class DefaultUrlProvider : IUrlProvider { if (string.IsNullOrWhiteSpace(route)) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Couldn't find any page with nodeId={NodeId}. This is most likely caused by the page not being published.", id); + } return null; } diff --git a/src/Umbraco.Core/Routing/UrlProviderExtensions.cs b/src/Umbraco.Core/Routing/UrlProviderExtensions.cs index 8e2a577f3a..e6441b0cf5 100644 --- a/src/Umbraco.Core/Routing/UrlProviderExtensions.cs +++ b/src/Umbraco.Core/Routing/UrlProviderExtensions.cs @@ -225,9 +225,12 @@ public static class UrlProviderExtensions if (!pcr.HasPublishedContent()) { - const string logMsg = nameof(DetectCollisionAsync) + + if (logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + const string logMsg = nameof(DetectCollisionAsync) + " did not resolve a content item for original url: {Url}, translated to {TranslatedUrl} and culture: {Culture}"; - logger.LogDebug(logMsg, url, uri, culture); + logger.LogDebug(logMsg, url, uri, culture); + } var urlInfo = UrlInfo.Message(textService.Localize("content", "routeErrorCannotRoute"), culture); return Attempt.Succeed(urlInfo); diff --git a/src/Umbraco.Core/Runtime/MainDom.cs b/src/Umbraco.Core/Runtime/MainDom.cs index 83736914a2..4d4c7ab2e8 100644 --- a/src/Umbraco.Core/Runtime/MainDom.cs +++ b/src/Umbraco.Core/Runtime/MainDom.cs @@ -108,7 +108,10 @@ namespace Umbraco.Cms.Core.Runtime lock (_locko) { - _logger.LogDebug("Signaled ({Signaled}) ({SignalSource})", _signaled ? "again" : "first", source); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Signaled ({Signaled}) ({SignalSource})", _signaled ? "again" : "first", source); + } if (_signaled) { return; @@ -136,8 +139,10 @@ namespace Umbraco.Cms.Core.Runtime continue; } } - - _logger.LogDebug("Stopped ({SignalSource})", source); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Stopped ({SignalSource})", source); + } } finally { @@ -201,7 +206,10 @@ namespace Umbraco.Cms.Core.Runtime } else { - _logger.LogDebug("Listening task completed with {TaskStatus}", _listenTask.Status); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Listening task completed with {TaskStatus}", _listenTask.Status); + } } OnSignal("signal"); diff --git a/src/Umbraco.Core/Services/ContentVersionService.cs b/src/Umbraco.Core/Services/ContentVersionService.cs index 24443a3957..f0c92db28f 100644 --- a/src/Umbraco.Core/Services/ContentVersionService.cs +++ b/src/Umbraco.Core/Services/ContentVersionService.cs @@ -129,8 +129,10 @@ internal class ContentVersionService : IContentVersionService { return Array.Empty(); } - - _logger.LogDebug("Discovered {count} candidate(s) for ContentVersion cleanup", allHistoricVersions.Count); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Discovered {count} candidate(s) for ContentVersion cleanup", allHistoricVersions.Count); + } versionsToDelete = new List(allHistoricVersions.Count); IEnumerable filteredContentVersions = @@ -143,7 +145,10 @@ internal class ContentVersionService : IContentVersionService if (scope.Notifications.PublishCancelable( new ContentDeletingVersionsNotification(version.ContentId, messages, version.VersionId))) { - _logger.LogDebug("Delete cancelled for ContentVersion [{versionId}]", version.VersionId); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Delete cancelled for ContentVersion [{versionId}]", version.VersionId); + } continue; } @@ -153,7 +158,10 @@ internal class ContentVersionService : IContentVersionService if (!versionsToDelete.Any()) { - _logger.LogDebug("No remaining ContentVersions for cleanup"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("No remaining ContentVersions for cleanup"); + } return Array.Empty(); } diff --git a/src/Umbraco.Core/Services/NotificationService.cs b/src/Umbraco.Core/Services/NotificationService.cs index ff857986b0..72d46b2fb6 100644 --- a/src/Umbraco.Core/Services/NotificationService.cs +++ b/src/Umbraco.Core/Services/NotificationService.cs @@ -568,7 +568,10 @@ public class NotificationService : INotificationService private void Process(BlockingCollection notificationRequests) => ThreadPool.QueueUserWorkItem(state => { - _logger.LogDebug("Begin processing notifications."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Begin processing notifications."); + } while (true) { // stay on for 8s @@ -578,7 +581,10 @@ public class NotificationService : INotificationService { _emailSender.SendAsync(request.Mail, Constants.Web.EmailTypes.Notification).GetAwaiter() .GetResult(); - _logger.LogDebug("Notification '{Action}' sent to {Username} ({Email})", request.Action, request.UserName, request.Email); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Notification '{Action}' sent to {Username} ({Email})", request.Action, request.UserName, request.Email); + } } catch (Exception ex) { @@ -597,8 +603,10 @@ public class NotificationService : INotificationService break; } } - - _logger.LogDebug("Done processing notifications."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Done processing notifications."); + } }); private class NotificationRequest diff --git a/src/Umbraco.Core/Templates/HtmlUrlParser.cs b/src/Umbraco.Core/Templates/HtmlUrlParser.cs index f4a817485d..16d27eb205 100644 --- a/src/Umbraco.Core/Templates/HtmlUrlParser.cs +++ b/src/Umbraco.Core/Templates/HtmlUrlParser.cs @@ -46,14 +46,17 @@ public sealed class HtmlUrlParser return text; } - using (DisposableTimer? timer = _profilingLogger.DebugDuration( + using (DisposableTimer? timer = !(_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug)) ? null : _profilingLogger.DebugDuration( typeof(IOHelper), "ResolveUrlsFromTextString starting", "ResolveUrlsFromTextString complete")) { // find all relative URLs (ie. URLs that contain ~) MatchCollection tags = ResolveUrlPattern.Matches(text); - _logger.LogDebug("After regex: {Duration} matched: {TagsCount}", timer?.Stopwatch.ElapsedMilliseconds, tags.Count); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("After regex: {Duration} matched: {TagsCount}", timer?.Stopwatch.ElapsedMilliseconds, tags.Count); + } foreach (Match tag in tags) { var url = string.Empty; diff --git a/src/Umbraco.Examine.Lucene/UmbracoContentIndex.cs b/src/Umbraco.Examine.Lucene/UmbracoContentIndex.cs index 7aa2eea5fc..3053da44cf 100644 --- a/src/Umbraco.Examine.Lucene/UmbracoContentIndex.cs +++ b/src/Umbraco.Examine.Lucene/UmbracoContentIndex.cs @@ -135,8 +135,10 @@ public class UmbracoContentIndex : UmbracoExamineIndex, IUmbracoContentIndex IBooleanOperation? filtered = c.NativeQuery(rawQuery); IOrdering? selectedFields = filtered.SelectFields(_idOnlyFieldSet); ISearchResults? results = selectedFields.Execute(); - - _logger.LogDebug("DeleteFromIndex with query: {Query} (found {TotalItems} results)", rawQuery, results.TotalItemCount); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("DeleteFromIndex with query: {Query} (found {TotalItems} results)", rawQuery, results.TotalItemCount); + } var toRemove = results.Select(x => x.Id).ToList(); // delete those descendants (ensure base. is used here so we aren't calling ourselves!) diff --git a/src/Umbraco.Infrastructure/Examine/ContentIndexPopulator.cs b/src/Umbraco.Infrastructure/Examine/ContentIndexPopulator.cs index dd02ee5754..eb9e9f135f 100644 --- a/src/Umbraco.Infrastructure/Examine/ContentIndexPopulator.cs +++ b/src/Umbraco.Infrastructure/Examine/ContentIndexPopulator.cs @@ -68,7 +68,10 @@ public class ContentIndexPopulator : IndexPopulator { if (indexes.Count == 0) { - _logger.LogDebug($"{nameof(PopulateIndexes)} called with no indexes to populate. Typically means no index is registered with this populator."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug($"{nameof(PopulateIndexes)} called with no indexes to populate. Typically means no index is registered with this populator."); + } return; } diff --git a/src/Umbraco.Infrastructure/Examine/ExamineIndexRebuilder.cs b/src/Umbraco.Infrastructure/Examine/ExamineIndexRebuilder.cs index a1c70d0ec3..5394cdc275 100644 --- a/src/Umbraco.Infrastructure/Examine/ExamineIndexRebuilder.cs +++ b/src/Umbraco.Infrastructure/Examine/ExamineIndexRebuilder.cs @@ -88,7 +88,10 @@ public class ExamineIndexRebuilder : IIndexRebuilder if (useBackgroundThread) { - _logger.LogDebug($"Queuing background job for {nameof(RebuildIndexes)}."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug($"Queuing background job for {nameof(RebuildIndexes)}."); + } _backgroundTaskQueue.QueueBackgroundWorkItem( cancellationToken => diff --git a/src/Umbraco.Infrastructure/Examine/MediaIndexPopulator.cs b/src/Umbraco.Infrastructure/Examine/MediaIndexPopulator.cs index 20df2c229e..6f4a4db4a3 100644 --- a/src/Umbraco.Infrastructure/Examine/MediaIndexPopulator.cs +++ b/src/Umbraco.Infrastructure/Examine/MediaIndexPopulator.cs @@ -38,8 +38,11 @@ public class MediaIndexPopulator : IndexPopulator { if (indexes.Count == 0) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( $"{nameof(PopulateIndexes)} called with no indexes to populate. Typically means no index is registered with this populator."); + } return; } diff --git a/src/Umbraco.Infrastructure/HostedServices/ContentVersionCleanup.cs b/src/Umbraco.Infrastructure/HostedServices/ContentVersionCleanup.cs index 1b62e8e31d..37eeb668f9 100644 --- a/src/Umbraco.Infrastructure/HostedServices/ContentVersionCleanup.cs +++ b/src/Umbraco.Infrastructure/HostedServices/ContentVersionCleanup.cs @@ -60,10 +60,16 @@ public class ContentVersionCleanup : RecurringHostedServiceBase switch (_serverRoleAccessor.CurrentServerRole) { case ServerRole.Subscriber: - _logger.LogDebug("Does not run on subscriber servers"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on subscriber servers"); + } return Task.CompletedTask; case ServerRole.Unknown: - _logger.LogDebug("Does not run on servers with unknown role"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on servers with unknown role"); + } return Task.CompletedTask; case ServerRole.Single: case ServerRole.SchedulingPublisher: @@ -74,7 +80,10 @@ public class ContentVersionCleanup : RecurringHostedServiceBase // Ensure we do not run if not main domain, but do NOT lock it if (!_mainDom.IsMainDom) { - _logger.LogDebug("Does not run if not MainDom"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run if not MainDom"); + } return Task.FromResult(false); // do NOT repeat, going down } @@ -86,7 +95,10 @@ public class ContentVersionCleanup : RecurringHostedServiceBase } else { - _logger.LogDebug("Task complete, no items were Deleted"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Task complete, no items were Deleted"); + } } return Task.FromResult(true); diff --git a/src/Umbraco.Infrastructure/HostedServices/HealthCheckNotifier.cs b/src/Umbraco.Infrastructure/HostedServices/HealthCheckNotifier.cs index 30d164276a..e1a10d9f71 100644 --- a/src/Umbraco.Infrastructure/HostedServices/HealthCheckNotifier.cs +++ b/src/Umbraco.Infrastructure/HostedServices/HealthCheckNotifier.cs @@ -93,17 +93,26 @@ public class HealthCheckNotifier : RecurringHostedServiceBase switch (_serverRegistrar.CurrentServerRole) { case ServerRole.Subscriber: - _logger.LogDebug("Does not run on subscriber servers."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on subscriber servers."); + } return; case ServerRole.Unknown: - _logger.LogDebug("Does not run on servers with unknown role."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on servers with unknown role."); + } return; } // Ensure we do not run if not main domain, but do NOT lock it if (_mainDom.IsMainDom == false) { - _logger.LogDebug("Does not run if not MainDom."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run if not MainDom."); + } return; } @@ -111,7 +120,7 @@ public class HealthCheckNotifier : RecurringHostedServiceBase // checks can be making service/database calls so we want to ensure the CallContext/Ambient scope // isn't used since that can be problematic. using (ICoreScope scope = _scopeProvider.CreateCoreScope(autoComplete: true)) - using (_profilingLogger.DebugDuration("Health checks executing", "Health checks complete")) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Health checks executing", "Health checks complete")) { // Don't notify for any checks that are disabled, nor for any disabled just for notifications. Guid[] disabledCheckIds = _healthChecksSettings.Notification.DisabledChecks diff --git a/src/Umbraco.Infrastructure/HostedServices/KeepAlive.cs b/src/Umbraco.Infrastructure/HostedServices/KeepAlive.cs index b10f56cc74..5db59ff225 100644 --- a/src/Umbraco.Infrastructure/HostedServices/KeepAlive.cs +++ b/src/Umbraco.Infrastructure/HostedServices/KeepAlive.cs @@ -69,10 +69,16 @@ public class KeepAlive : RecurringHostedServiceBase switch (_serverRegistrar.CurrentServerRole) { case ServerRole.Subscriber: - _logger.LogDebug("Does not run on subscriber servers."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on subscriber servers."); + } return; case ServerRole.Unknown: - _logger.LogDebug("Does not run on servers with unknown role."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on servers with unknown role."); + } return; } @@ -83,7 +89,7 @@ public class KeepAlive : RecurringHostedServiceBase return; } - using (_profilingLogger.DebugDuration("Keep alive executing", "Keep alive complete")) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Keep alive executing", "Keep alive complete")) { var umbracoAppUrl = _hostingEnvironment.ApplicationMainUrl?.ToString(); if (umbracoAppUrl.IsNullOrWhiteSpace()) diff --git a/src/Umbraco.Infrastructure/HostedServices/LogScrubber.cs b/src/Umbraco.Infrastructure/HostedServices/LogScrubber.cs index b69342d25b..9ae0dfe656 100644 --- a/src/Umbraco.Infrastructure/HostedServices/LogScrubber.cs +++ b/src/Umbraco.Infrastructure/HostedServices/LogScrubber.cs @@ -63,23 +63,32 @@ public class LogScrubber : RecurringHostedServiceBase switch (_serverRegistrar.CurrentServerRole) { case ServerRole.Subscriber: - _logger.LogDebug("Does not run on subscriber servers."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on subscriber servers."); + } return Task.CompletedTask; case ServerRole.Unknown: - _logger.LogDebug("Does not run on servers with unknown role."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on servers with unknown role."); + } return Task.CompletedTask; } // Ensure we do not run if not main domain, but do NOT lock it if (_mainDom.IsMainDom == false) { - _logger.LogDebug("Does not run if not MainDom."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run if not MainDom."); + } return Task.CompletedTask; } // Ensure we use an explicit scope since we are running on a background thread. using (ICoreScope scope = _scopeProvider.CreateCoreScope()) - using (_profilingLogger.DebugDuration("Log scrubbing executing", "Log scrubbing complete")) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Log scrubbing executing", "Log scrubbing complete")) { _auditService.CleanLogs((int)_settings.MaxLogAge.TotalMinutes); _ = scope.Complete(); diff --git a/src/Umbraco.Infrastructure/HostedServices/ReportSiteTask.cs b/src/Umbraco.Infrastructure/HostedServices/ReportSiteTask.cs index 95997dbbf5..7184aaf16e 100644 --- a/src/Umbraco.Infrastructure/HostedServices/ReportSiteTask.cs +++ b/src/Umbraco.Infrastructure/HostedServices/ReportSiteTask.cs @@ -91,7 +91,10 @@ public class ReportSiteTask : RecurringHostedServiceBase // Silently swallow // The user does not need the logs being polluted if our service has fallen over or is down etc // Hence only logging this at a more verbose level (which users should not be using in production) - _logger.LogDebug("There was a problem sending a request to the Umbraco telemetry service"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("There was a problem sending a request to the Umbraco telemetry service"); + } } } } diff --git a/src/Umbraco.Infrastructure/HostedServices/ScheduledPublishing.cs b/src/Umbraco.Infrastructure/HostedServices/ScheduledPublishing.cs index d593124ccb..328cf5ee5c 100644 --- a/src/Umbraco.Infrastructure/HostedServices/ScheduledPublishing.cs +++ b/src/Umbraco.Infrastructure/HostedServices/ScheduledPublishing.cs @@ -62,24 +62,36 @@ public class ScheduledPublishing : RecurringHostedServiceBase switch (_serverRegistrar.CurrentServerRole) { case ServerRole.Subscriber: - _logger.LogDebug("Does not run on subscriber servers."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on subscriber servers."); + } return Task.CompletedTask; case ServerRole.Unknown: - _logger.LogDebug("Does not run on servers with unknown role."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run on servers with unknown role."); + } return Task.CompletedTask; } // Ensure we do not run if not main domain, but do NOT lock it if (_mainDom.IsMainDom == false) { - _logger.LogDebug("Does not run if not MainDom."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run if not MainDom."); + } return Task.CompletedTask; } // Do NOT run publishing if not properly running if (_runtimeState.Level != RuntimeLevel.Run) { - _logger.LogDebug("Does not run if run level is not Run."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run if run level is not Run."); + } return Task.CompletedTask; } diff --git a/src/Umbraco.Infrastructure/HostedServices/TempFileCleanup.cs b/src/Umbraco.Infrastructure/HostedServices/TempFileCleanup.cs index 663a89b05a..cf46e38750 100644 --- a/src/Umbraco.Infrastructure/HostedServices/TempFileCleanup.cs +++ b/src/Umbraco.Infrastructure/HostedServices/TempFileCleanup.cs @@ -44,7 +44,10 @@ public class TempFileCleanup : RecurringHostedServiceBase // Ensure we do not run if not main domain if (_mainDom.IsMainDom == false) { - _logger.LogDebug("Does not run if not MainDom."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Does not run if not MainDom."); + } return Task.CompletedTask; } @@ -62,7 +65,10 @@ public class TempFileCleanup : RecurringHostedServiceBase switch (result.Status) { case CleanFolderResultStatus.FailedAsDoesNotExist: - _logger.LogDebug("The cleanup folder doesn't exist {Folder}", folder.FullName); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("The cleanup folder doesn't exist {Folder}", folder.FullName); + } break; case CleanFolderResultStatus.FailedWithException: foreach (CleanFolderResult.Error error in result.Errors!) @@ -77,7 +83,10 @@ public class TempFileCleanup : RecurringHostedServiceBase folder.Refresh(); // In case it's changed during runtime if (!folder.Exists) { - _logger.LogDebug("The cleanup folder doesn't exist {Folder}", folder.FullName); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("The cleanup folder doesn't exist {Folder}", folder.FullName); + } return; } diff --git a/src/Umbraco.Infrastructure/Install/UnattendedInstaller.cs b/src/Umbraco.Infrastructure/Install/UnattendedInstaller.cs index bf9817ca94..64cb6e8ff2 100644 --- a/src/Umbraco.Infrastructure/Install/UnattendedInstaller.cs +++ b/src/Umbraco.Infrastructure/Install/UnattendedInstaller.cs @@ -73,8 +73,10 @@ public class UnattendedInstaller : INotificationAsyncHandler( + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Verbose) ? null : _profilingLogger.TraceDuration( "Starting unattended upgrade.", "Unattended upgrade completed.")) { diff --git a/src/Umbraco.Infrastructure/Mail/EmailSender.cs b/src/Umbraco.Infrastructure/Mail/EmailSender.cs index 742075656d..03b46dbedc 100644 --- a/src/Umbraco.Infrastructure/Mail/EmailSender.cs +++ b/src/Umbraco.Infrastructure/Mail/EmailSender.cs @@ -83,18 +83,24 @@ public class EmailSender : IEmailSender // if a handler handled sending the email then don't continue. if (notification.IsHandled) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "The email sending for {Subject} was handled by a notification handler", notification.Message.Subject); + } return; } } if (!_globalSettings.IsSmtpServerConfigured && !_globalSettings.IsPickupDirectoryLocationConfigured) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Could not send email for {Subject}. It was not handled by a notification handler and there is no SMTP configured.", message.Subject); + } return; } diff --git a/src/Umbraco.Infrastructure/Migrations/Upgrade/V_8_0_0/DataTypes/PreValueMigratorCollection.cs b/src/Umbraco.Infrastructure/Migrations/Upgrade/V_8_0_0/DataTypes/PreValueMigratorCollection.cs index 422bbc1e8c..40ee54b42a 100644 --- a/src/Umbraco.Infrastructure/Migrations/Upgrade/V_8_0_0/DataTypes/PreValueMigratorCollection.cs +++ b/src/Umbraco.Infrastructure/Migrations/Upgrade/V_8_0_0/DataTypes/PreValueMigratorCollection.cs @@ -17,8 +17,11 @@ public class PreValueMigratorCollection : BuilderCollectionBase x.CanMigrate(editorAlias)); - _logger.LogDebug("Getting migrator for \"{EditorAlias}\" = {MigratorType}", editorAlias, + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Getting migrator for \"{EditorAlias}\" = {MigratorType}", editorAlias, migrator == null ? "" : migrator.GetType().Name); + } return migrator; } } diff --git a/src/Umbraco.Infrastructure/ModelsBuilder/AutoModelsNotificationHandler.cs b/src/Umbraco.Infrastructure/ModelsBuilder/AutoModelsNotificationHandler.cs index d879306226..b1d3ea48bb 100644 --- a/src/Umbraco.Infrastructure/ModelsBuilder/AutoModelsNotificationHandler.cs +++ b/src/Umbraco.Infrastructure/ModelsBuilder/AutoModelsNotificationHandler.cs @@ -118,8 +118,10 @@ public sealed class AutoModelsNotificationHandler : INotificationHandler"); + } } return pendingMigrations; diff --git a/src/Umbraco.Infrastructure/Persistence/Repositories/Implement/UserRepository.cs b/src/Umbraco.Infrastructure/Persistence/Repositories/Implement/UserRepository.cs index fbd1913a58..cf2329570e 100644 --- a/src/Umbraco.Infrastructure/Persistence/Repositories/Implement/UserRepository.cs +++ b/src/Umbraco.Infrastructure/Persistence/Repositories/Implement/UserRepository.cs @@ -265,12 +265,20 @@ SELECT 4 AS [Key], COUNT(id) AS [Value] FROM umbracoUser WHERE userDisabled = 0 if (DateTime.UtcNow - found.LastValidatedUtc > _globalSettings.TimeOut) { //timeout detected, update the record - Logger.LogDebug("ClearLoginSession for sessionId {sessionId}", sessionId);ClearLoginSession(sessionId); + if (Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + Logger.LogDebug("ClearLoginSession for sessionId {sessionId}", sessionId); + } + ClearLoginSession(sessionId); return false; } //update the validate date - Logger.LogDebug("Updating LastValidatedUtc for sessionId {sessionId}", sessionId);found.LastValidatedUtc = DateTime.UtcNow; + if (Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + Logger.LogDebug("Updating LastValidatedUtc for sessionId {sessionId}", sessionId); + } + found.LastValidatedUtc = DateTime.UtcNow; Database.Update(found); return true; } diff --git a/src/Umbraco.Infrastructure/Persistence/UmbracoDatabase.cs b/src/Umbraco.Infrastructure/Persistence/UmbracoDatabase.cs index 5be7cfdde2..4c88e7659a 100644 --- a/src/Umbraco.Infrastructure/Persistence/UmbracoDatabase.cs +++ b/src/Umbraco.Infrastructure/Persistence/UmbracoDatabase.cs @@ -271,11 +271,17 @@ public class UmbracoDatabase : Database, IUmbracoDatabase protected override void OnException(Exception ex) { _logger.LogError(ex, "Exception ({InstanceId}).", InstanceId); - _logger.LogDebug("At:\r\n{StackTrace}", Environment.StackTrace); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("At:\r\n{StackTrace}", Environment.StackTrace); + } if (EnableSqlTrace == false) { - _logger.LogDebug("Sql:\r\n{Sql}", CommandToString(LastSQL, LastArgs)); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Sql:\r\n{Sql}", CommandToString(LastSQL, LastArgs)); + } } base.OnException(ex); @@ -293,7 +299,10 @@ public class UmbracoDatabase : Database, IUmbracoDatabase if (EnableSqlTrace) { - _logger.LogDebug("SQL Trace:\r\n{Sql}", CommandToString(cmd).Replace("{", "{{").Replace("}", "}}")); // TODO: these escapes should be builtin + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("SQL Trace:\r\n{Sql}", CommandToString(cmd).Replace("{", "{{").Replace("}", "}}")); // TODO: these escapes should be builtin + } } #if DEBUG_DATABASES diff --git a/src/Umbraco.Infrastructure/Persistence/UmbracoDatabaseFactory.cs b/src/Umbraco.Infrastructure/Persistence/UmbracoDatabaseFactory.cs index 7530ab7854..d8753bfd37 100644 --- a/src/Umbraco.Infrastructure/Persistence/UmbracoDatabaseFactory.cs +++ b/src/Umbraco.Infrastructure/Persistence/UmbracoDatabaseFactory.cs @@ -84,7 +84,10 @@ public class UmbracoDatabaseFactory : DisposableObjectSlim, IUmbracoDatabaseFact ConnectionStrings umbracoConnectionString = connectionStrings.CurrentValue; if (!umbracoConnectionString.IsConnectionStringConfigured()) { - logger.LogDebug("Missing connection string, defer configuration."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + logger.LogDebug("Missing connection string, defer configuration."); + } return; // not configured } @@ -197,7 +200,10 @@ public class UmbracoDatabaseFactory : DisposableObjectSlim, IUmbracoDatabaseFact private SqlContext Initialize() { - _logger.LogDebug("Initializing."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Initializing."); + } if (ConnectionString.IsNullOrWhiteSpace()) { @@ -261,8 +267,10 @@ public class UmbracoDatabaseFactory : DisposableObjectSlim, IUmbracoDatabaseFact throw new NullReferenceException( "The call to UmbracoDatabaseFactory.Config yielded a null UmbracoDatabaseFactory instance."); } - - _logger.LogDebug("Initialized."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Initialized."); + } return new SqlContext(_sqlSyntax, _databaseType, _pocoDataFactory, _mappers); } diff --git a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockGridPropertyValueConverter.cs b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockGridPropertyValueConverter.cs index e1c5a2052c..02c12d809c 100644 --- a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockGridPropertyValueConverter.cs +++ b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockGridPropertyValueConverter.cs @@ -94,7 +94,7 @@ namespace Umbraco.Cms.Core.PropertyEditors.ValueConverters private BlockGridModel? ConvertIntermediateToBlockGridModel(IPublishedPropertyType propertyType, PropertyCacheLevel referenceCacheLevel, object? inter, bool preview) { - using (_proflog.DebugDuration($"ConvertPropertyToBlockGrid ({propertyType.DataType.Id})")) + using (!_proflog.IsEnabled(LogLevel.Debug) ? null : _proflog.DebugDuration($"ConvertPropertyToBlockGrid ({propertyType.DataType.Id})")) { // Get configuration var configuration = propertyType.DataType.ConfigurationAs(); diff --git a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockListPropertyValueConverter.cs b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockListPropertyValueConverter.cs index ae4ef24672..891e6a8e4d 100644 --- a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockListPropertyValueConverter.cs +++ b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/BlockListPropertyValueConverter.cs @@ -95,7 +95,7 @@ public class BlockListPropertyValueConverter : BlockPropertyValueConverterBase intermediate since source is always just a JSON string - using (_proflog.DebugDuration( + using (!_proflog.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _proflog.DebugDuration( $"ConvertPropertyToBlockList ({propertyType.DataType.Id})")) { BlockListModel? blockListModel = ConvertIntermediateToBlockListModel(owner, propertyType, referenceCacheLevel, inter, preview); @@ -133,7 +133,7 @@ public class BlockListPropertyValueConverter : BlockPropertyValueConverterBase intermediate since source is always just a JSON string - using (_proflog.DebugDuration( + using (!_proflog.IsEnabled(LogLevel.Debug) ? null : _proflog.DebugDuration( $"ConvertPropertyToBlockList ({propertyType.DataType.Id})")) { // Get configuration diff --git a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/MultiUrlPickerValueConverter.cs b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/MultiUrlPickerValueConverter.cs index 821ece9b33..a40571637e 100644 --- a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/MultiUrlPickerValueConverter.cs +++ b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/MultiUrlPickerValueConverter.cs @@ -84,7 +84,7 @@ public class MultiUrlPickerValueConverter : PropertyValueConverterBase, IDeliver public override object? ConvertIntermediateToObject(IPublishedElement owner, IPublishedPropertyType propertyType, PropertyCacheLevel referenceCacheLevel, object? inter, bool preview) { - using (_proflog.DebugDuration( + using (!_proflog.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _proflog.DebugDuration( $"ConvertPropertyToLinks ({propertyType.DataType.Id})")) { var maxNumber = propertyType.DataType.ConfigurationAs()!.MaxNumber; diff --git a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentManyValueConverter.cs b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentManyValueConverter.cs index c2a3d8330e..cc0a04a9f4 100644 --- a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentManyValueConverter.cs +++ b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentManyValueConverter.cs @@ -80,7 +80,7 @@ public class NestedContentManyValueConverter : NestedContentValueConverterBase, /// public override object ConvertIntermediateToObject(IPublishedElement owner, IPublishedPropertyType propertyType, PropertyCacheLevel referenceCacheLevel, object? inter, bool preview) { - using (_proflog.DebugDuration( + using (!_proflog.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _proflog.DebugDuration( $"ConvertPropertyToNestedContent ({propertyType.DataType.Id})")) { NestedContentConfiguration? configuration = diff --git a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentSingleValueConverter.cs b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentSingleValueConverter.cs index 7110d448ee..4beefb3318 100644 --- a/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentSingleValueConverter.cs +++ b/src/Umbraco.Infrastructure/PropertyEditors/ValueConverters/NestedContentSingleValueConverter.cs @@ -79,7 +79,7 @@ public class NestedContentSingleValueConverter : NestedContentValueConverterBase /// public override object? ConvertIntermediateToObject(IPublishedElement owner, IPublishedPropertyType propertyType, PropertyCacheLevel referenceCacheLevel, object? inter, bool preview) { - using (_proflog.DebugDuration( + using (!_proflog.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _proflog.DebugDuration( $"ConvertPropertyToNestedContent ({propertyType.DataType.Id})")) { var value = (string?)inter; diff --git a/src/Umbraco.Infrastructure/PublishedCache/PublishedContentTypeCache.cs b/src/Umbraco.Infrastructure/PublishedCache/PublishedContentTypeCache.cs index b8d93631d0..f21635d2df 100644 --- a/src/Umbraco.Infrastructure/PublishedCache/PublishedContentTypeCache.cs +++ b/src/Umbraco.Infrastructure/PublishedCache/PublishedContentTypeCache.cs @@ -60,7 +60,10 @@ public class PublishedContentTypeCache : IDisposable /// public void ClearAll() { - _logger.LogDebug("Clear all."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Clear all."); + } try { @@ -84,7 +87,10 @@ public class PublishedContentTypeCache : IDisposable /// An identifier. public void ClearContentType(int id) { - _logger.LogDebug("Clear content type w/id {ContentTypeId}", id); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Clear content type w/id {ContentTypeId}", id); + } try { @@ -125,7 +131,10 @@ public class PublishedContentTypeCache : IDisposable /// A data type identifier. public void ClearDataType(int id) { - _logger.LogDebug("Clear data type w/id {DataTypeId}.", id); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Clear data type w/id {DataTypeId}.", id); + } // there is no recursion to handle here because a PublishedContentType contains *all* its // properties ie both its own properties and those that were inherited (it's based upon an diff --git a/src/Umbraco.Infrastructure/Runtime/CoreRuntime.cs b/src/Umbraco.Infrastructure/Runtime/CoreRuntime.cs index 5bc005fc6d..19c947481d 100644 --- a/src/Umbraco.Infrastructure/Runtime/CoreRuntime.cs +++ b/src/Umbraco.Infrastructure/Runtime/CoreRuntime.cs @@ -236,7 +236,7 @@ public class CoreRuntime : IRuntime private void AcquireMainDom() { - using DisposableTimer? timer = _profilingLogger.DebugDuration("Acquiring MainDom.", "Acquired."); + using DisposableTimer? timer = !_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Acquiring MainDom.", "Acquired."); try { @@ -257,18 +257,23 @@ public class CoreRuntime : IRuntime return; } - using DisposableTimer? timer = + using DisposableTimer? timer = !_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Determining runtime level.", "Determined."); try { State.DetermineRuntimeLevel(); - - _logger.LogDebug("Runtime level: {RuntimeLevel} - {RuntimeLevelReason}", State.Level, State.Reason); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Runtime level: {RuntimeLevel} - {RuntimeLevelReason}", State.Level, State.Reason); + } if (State.Level == RuntimeLevel.Upgrade) { - _logger.LogDebug("Configure database factory for upgrades."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Configure database factory for upgrades."); + } _databaseFactory.ConfigureForUpgrade(); } } diff --git a/src/Umbraco.Infrastructure/Runtime/FileSystemMainDomLock.cs b/src/Umbraco.Infrastructure/Runtime/FileSystemMainDomLock.cs index 26b8d55f96..6dcd3ef9b0 100644 --- a/src/Umbraco.Infrastructure/Runtime/FileSystemMainDomLock.cs +++ b/src/Umbraco.Infrastructure/Runtime/FileSystemMainDomLock.cs @@ -44,16 +44,22 @@ internal class FileSystemMainDomLock : IMainDomLock try { Directory.CreateDirectory(_hostingEnvironment.LocalTempPath); - _logger.LogDebug("Attempting to obtain MainDom lock file handle {lockFilePath}", _lockFilePath); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Attempting to obtain MainDom lock file handle {lockFilePath}", _lockFilePath); + } _lockFileStream = File.Open(_lockFilePath, FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.None); DeleteLockReleaseSignalFile(); return Task.FromResult(true); } catch (IOException) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Couldn't obtain MainDom lock file handle, signalling for release of {lockFilePath}", _lockFilePath); + } CreateLockReleaseSignalFile(); } catch (Exception ex) @@ -107,13 +113,19 @@ internal class FileSystemMainDomLock : IMainDomLock { if (_cancellationTokenSource.IsCancellationRequested) { - _logger.LogDebug("ListenAsync Task canceled, exiting loop"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("ListenAsync Task canceled, exiting loop"); + } return; } if (File.Exists(_releaseSignalFilePath)) { - _logger.LogDebug("Found lock release signal file, releasing lock on {lockFilePath}", _lockFilePath); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Found lock release signal file, releasing lock on {lockFilePath}", _lockFilePath); + } _lockFileStream?.Close(); _lockFileStream = null; break; diff --git a/src/Umbraco.Infrastructure/Runtime/RuntimeState.cs b/src/Umbraco.Infrastructure/Runtime/RuntimeState.cs index 6597fadf61..37c99c64f2 100644 --- a/src/Umbraco.Infrastructure/Runtime/RuntimeState.cs +++ b/src/Umbraco.Infrastructure/Runtime/RuntimeState.cs @@ -168,7 +168,10 @@ public class RuntimeState : IRuntimeState { // local version *does* match code version, but the database is not configured // install - may happen with Deploy/Cloud/etc - _logger.LogDebug("Database is not configured, need to install Umbraco."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Database is not configured, need to install Umbraco."); + } Level = RuntimeLevel.Install; Reason = RuntimeLevelReason.InstallNoDatabase; @@ -206,8 +209,11 @@ public class RuntimeState : IRuntimeState { case UmbracoDatabaseState.CannotConnect: { - // cannot connect to configured database, this is bad, fail - _logger.LogDebug("Could not connect to database."); + // cannot connect to configured database, this is bad, fail + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Could not connect to database."); + } if (_globalSettings.Value.InstallMissingDatabase || _databaseProviderMetadata.CanForceCreateDatabase(_databaseFactory)) { @@ -231,12 +237,15 @@ public class RuntimeState : IRuntimeState } case UmbracoDatabaseState.NeedsUpgrade: { - // the db version does not match... but we do have a migration table - // so, at least one valid table, so we quite probably are installed & need to upgrade + // the db version does not match... but we do have a migration table + // so, at least one valid table, so we quite probably are installed & need to upgrade - // although the files version matches the code version, the database version does not - // which means the local files have been upgraded but not the database - need to upgrade - _logger.LogDebug("Has not reached the final upgrade step, need to upgrade Umbraco."); + // although the files version matches the code version, the database version does not + // which means the local files have been upgraded but not the database - need to upgrade + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Has not reached the final upgrade step, need to upgrade Umbraco."); + } Level = _unattendedSettings.Value.UpgradeUnattended ? RuntimeLevel.Run : RuntimeLevel.Upgrade; Reason = RuntimeLevelReason.UpgradeMigrations; } @@ -249,7 +258,10 @@ public class RuntimeState : IRuntimeState if (_unattendedSettings.Value.PackageMigrationsUnattended) { - _logger.LogDebug("Package migrations need to execute."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Package migrations need to execute."); + } Reason = RuntimeLevelReason.UpgradePackageMigrations; } else @@ -354,9 +366,10 @@ public class RuntimeState : IRuntimeState } FinalMigrationState = upgrader.Plan.FinalState; - - _logger.LogDebug("Final upgrade state is {FinalMigrationState}, database contains {DatabaseState}", FinalMigrationState, CurrentMigrationState ?? ""); - + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Final upgrade state is {FinalMigrationState}, database contains {DatabaseState}", FinalMigrationState, CurrentMigrationState ?? ""); + } return CurrentMigrationState != FinalMigrationState; } @@ -373,8 +386,10 @@ public class RuntimeState : IRuntimeState { break; } - - _logger.LogDebug("Could not immediately connect to database, trying again."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Could not immediately connect to database, trying again."); + } Thread.Sleep(1000); } diff --git a/src/Umbraco.Infrastructure/Scoping/Scope.cs b/src/Umbraco.Infrastructure/Scoping/Scope.cs index 0ff1fa5d30..295c92a6d6 100644 --- a/src/Umbraco.Infrastructure/Scoping/Scope.cs +++ b/src/Umbraco.Infrastructure/Scoping/Scope.cs @@ -75,7 +75,10 @@ namespace Umbraco.Cms.Infrastructure.Scoping #if DEBUG_SCOPES _scopeProvider.RegisterScope(this); #endif - logger.LogTrace("Create {InstanceId} on thread {ThreadId}", InstanceId.ToString("N").Substring(0, 8), Thread.CurrentThread.ManagedThreadId); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Trace)) + { + logger.LogTrace("Create {InstanceId} on thread {ThreadId}", InstanceId.ToString("N").Substring(0, 8), Thread.CurrentThread.ManagedThreadId); + } if (detachable) { diff --git a/src/Umbraco.Infrastructure/Security/MemberPasswordHasher.cs b/src/Umbraco.Infrastructure/Security/MemberPasswordHasher.cs index 034014663d..3c7e4eabee 100644 --- a/src/Umbraco.Infrastructure/Security/MemberPasswordHasher.cs +++ b/src/Umbraco.Infrastructure/Security/MemberPasswordHasher.cs @@ -107,8 +107,11 @@ public class MemberPasswordHasher : UmbracoPasswordHasher } else { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Unable to determine member password hashing algorithm, but this can happen when member enters a wrong password, before it has be rehashed"); + } } return PasswordVerificationResult.Failed; diff --git a/src/Umbraco.Infrastructure/Services/CacheInstructionService.cs b/src/Umbraco.Infrastructure/Services/CacheInstructionService.cs index 53be47e155..f47210fa49 100644 --- a/src/Umbraco.Infrastructure/Services/CacheInstructionService.cs +++ b/src/Umbraco.Infrastructure/Services/CacheInstructionService.cs @@ -154,7 +154,7 @@ namespace Umbraco.Cms DateTime lastPruned, int lastId) { - using (_profilingLogger.DebugDuration("Syncing from database...")) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Syncing from database...")) using (ICoreScope scope = ScopeProvider.CreateCoreScope()) { var numberOfInstructionsProcessed = ProcessDatabaseInstructions(cacheRefreshers, cancellationToken, localIdentity, ref lastId); diff --git a/src/Umbraco.Infrastructure/Sync/ServerMessengerBase.cs b/src/Umbraco.Infrastructure/Sync/ServerMessengerBase.cs index 20d251696b..1f158fcdf8 100644 --- a/src/Umbraco.Infrastructure/Sync/ServerMessengerBase.cs +++ b/src/Umbraco.Infrastructure/Sync/ServerMessengerBase.cs @@ -228,10 +228,12 @@ public abstract class ServerMessengerBase : IServerMessenger { throw new ArgumentNullException(nameof(refresher)); } - - StaticApplicationLogging.Logger.LogDebug( + if (StaticApplicationLogging.Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + StaticApplicationLogging.Logger.LogDebug( "Invoking refresher {RefresherType} on local server for message type RefreshByPayload", refresher.GetType()); + } var payloadRefresher = refresher as IPayloadCacheRefresher; if (payloadRefresher == null) @@ -260,9 +262,11 @@ public abstract class ServerMessengerBase : IServerMessenger { throw new ArgumentNullException(nameof(refresher)); } - - StaticApplicationLogging.Logger.LogDebug( + if (StaticApplicationLogging.Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + StaticApplicationLogging.Logger.LogDebug( "Invoking refresher {RefresherType} on local server for message type {MessageType}", refresher.GetType(), messageType); + } switch (messageType) { @@ -350,9 +354,11 @@ public abstract class ServerMessengerBase : IServerMessenger { throw new ArgumentNullException(nameof(refresher)); } - - StaticApplicationLogging.Logger.LogDebug( + if (StaticApplicationLogging.Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + StaticApplicationLogging.Logger.LogDebug( "Invoking refresher {RefresherType} on local server for message type {MessageType}", refresher.GetType(), messageType); + } var typedRefresher = refresher as ICacheRefresher; diff --git a/src/Umbraco.PublishedCache.NuCache/PublishedSnapshotService.cs b/src/Umbraco.PublishedCache.NuCache/PublishedSnapshotService.cs index fe3c2836c5..68b50cfd91 100644 --- a/src/Umbraco.PublishedCache.NuCache/PublishedSnapshotService.cs +++ b/src/Umbraco.PublishedCache.NuCache/PublishedSnapshotService.cs @@ -181,7 +181,10 @@ internal class PublishedSnapshotService : IPublishedSnapshotService foreach (ContentTypeCacheRefresher.JsonPayload payload in payloads) { - _logger.LogDebug("Notified {ChangeTypes} for {ItemType} {ItemId}", payload.ChangeTypes, payload.ItemType, payload.Id); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Notified {ChangeTypes} for {ItemType} {ItemId}", payload.ChangeTypes, payload.ItemType, payload.Id); + } } Notify(_contentStore, payloads, RefreshContentTypesLocked); @@ -230,10 +233,13 @@ internal class PublishedSnapshotService : IPublishedSnapshotService foreach (DataTypeCacheRefresher.JsonPayload payload in payloads) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Notified {RemovedStatus} for data type {DataTypeId}", payload.Removed ? "Removed" : "Refreshed", payload.Id); + } } using (_contentStore.GetScopedWriteLock(_scopeProvider)) @@ -622,15 +628,23 @@ internal class PublishedSnapshotService : IPublishedSnapshotService /// private void MainDomRelease() { - _logger.LogDebug("Releasing from MainDom..."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Releasing from MainDom..."); + } lock (_storesLock) { - _logger.LogDebug("Releasing content store..."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Releasing content store..."); + } _contentStore?.ReleaseLocalDb(); // null check because we could shut down before being assigned _localContentDb = null; - - _logger.LogDebug("Releasing media store..."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Releasing media store..."); + } _mediaStore?.ReleaseLocalDb(); // null check because we could shut down before being assigned _localMediaDb = null; @@ -742,8 +756,10 @@ internal class PublishedSnapshotService : IPublishedSnapshotService // beware! at that point the cache is inconsistent, // assuming we are going to SetAll content items! _localMediaDb?.Clear(); - - _logger.LogDebug("Loading media from database..."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Loading media from database..."); + } // IMPORTANT GetAllMediaSources sorts kits by level + parentId + sortOrder try @@ -852,7 +868,10 @@ internal class PublishedSnapshotService : IPublishedSnapshotService // contentStore is write-locked during changes - see note above, calls to this method are wrapped in contentStore.GetScopedWriteLock foreach (ContentCacheRefresher.JsonPayload payload in payloads) { - _logger.LogDebug("Notified {ChangeTypes} for content {ContentId}", payload.ChangeTypes, payload.Id); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Notified {ChangeTypes} for content {ContentId}", payload.ChangeTypes, payload.Id); + } if (payload.ChangeTypes.HasType(TreeChangeTypes.RefreshAll)) { @@ -926,7 +945,10 @@ internal class PublishedSnapshotService : IPublishedSnapshotService // see notes for content cache refresher foreach (MediaCacheRefresher.JsonPayload payload in payloads) { - _logger.LogDebug("Notified {ChangeTypes} for media {MediaId}", payload.ChangeTypes, payload.Id); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Notified {ChangeTypes} for media {MediaId}", payload.ChangeTypes, payload.Id); + } if (payload.ChangeTypes.HasType(TreeChangeTypes.RefreshAll)) { diff --git a/src/Umbraco.Web.BackOffice/Controllers/ExamineManagementController.cs b/src/Umbraco.Web.BackOffice/Controllers/ExamineManagementController.cs index 0fac0e482e..e59d3166bb 100644 --- a/src/Umbraco.Web.BackOffice/Controllers/ExamineManagementController.cs +++ b/src/Umbraco.Web.BackOffice/Controllers/ExamineManagementController.cs @@ -266,8 +266,10 @@ public class ExamineManagementController : UmbracoAuthorizedJsonController private void Indexer_IndexOperationComplete(object? sender, EventArgs e) { var indexer = (IIndex?)sender; - - _logger.LogDebug("Logging operation completed for index {IndexName}", indexer?.Name); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Logging operation completed for index {IndexName}", indexer?.Name); + } if (indexer is not null) { diff --git a/src/Umbraco.Web.BackOffice/Controllers/RedirectUrlManagementController.cs b/src/Umbraco.Web.BackOffice/Controllers/RedirectUrlManagementController.cs index c4d7d47d87..d87398d574 100644 --- a/src/Umbraco.Web.BackOffice/Controllers/RedirectUrlManagementController.cs +++ b/src/Umbraco.Web.BackOffice/Controllers/RedirectUrlManagementController.cs @@ -116,7 +116,10 @@ public class RedirectUrlManagementController : UmbracoAuthorizedApiController { var errorMessage = "User is not a member of the administrators group and so is not allowed to toggle the URL tracker"; - _logger.LogDebug(errorMessage); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug(errorMessage); + } throw new SecurityException(errorMessage); } diff --git a/src/Umbraco.Web.BackOffice/Filters/FileUploadCleanupFilterAttribute.cs b/src/Umbraco.Web.BackOffice/Filters/FileUploadCleanupFilterAttribute.cs index 474b1ef581..60f70c021a 100644 --- a/src/Umbraco.Web.BackOffice/Filters/FileUploadCleanupFilterAttribute.cs +++ b/src/Umbraco.Web.BackOffice/Filters/FileUploadCleanupFilterAttribute.cs @@ -104,8 +104,10 @@ public sealed class FileUploadCleanupFilterAttribute : TypeFilterAttribute { tempFolders.Add(dir); } - - _logger.LogDebug("Removing temp file {FileName}", f.TempFilePath); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Removing temp file {FileName}", f.TempFilePath); + } try { diff --git a/src/Umbraco.Web.BackOffice/HealthChecks/HealthCheckController.cs b/src/Umbraco.Web.BackOffice/HealthChecks/HealthCheckController.cs index 34adf15a94..9744ed8c5f 100644 --- a/src/Umbraco.Web.BackOffice/HealthChecks/HealthCheckController.cs +++ b/src/Umbraco.Web.BackOffice/HealthChecks/HealthCheckController.cs @@ -76,7 +76,10 @@ public class HealthCheckController : UmbracoAuthorizedJsonController try { - _logger.LogDebug("Running health check: " + check.Name); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Running health check: " + check.Name); + } return await check.GetStatus(); } catch (Exception ex) diff --git a/src/Umbraco.Web.BackOffice/Install/InstallApiController.cs b/src/Umbraco.Web.BackOffice/Install/InstallApiController.cs index 52068c6f8d..5708b3c4fd 100644 --- a/src/Umbraco.Web.BackOffice/Install/InstallApiController.cs +++ b/src/Umbraco.Web.BackOffice/Install/InstallApiController.cs @@ -278,7 +278,7 @@ public class InstallApiController : ControllerBase // executes the step internal async Task ExecuteStepAsync(InstallSetupStep step, object? instruction) { - using (_proflog.TraceDuration($"Executing installation step: '{step.Name}'.", "Step completed")) + using (!_proflog.IsEnabled(Core.Logging.LogLevel.Verbose) ? null : _proflog.TraceDuration($"Executing installation step: '{step.Name}'.", "Step completed")) { Attempt modelAttempt = instruction.TryConvertTo(step.StepType); if (!modelAttempt.Success) diff --git a/src/Umbraco.Web.Common/Controllers/RenderController.cs b/src/Umbraco.Web.Common/Controllers/RenderController.cs index dad8d8a84b..4b9ab5d98d 100644 --- a/src/Umbraco.Web.Common/Controllers/RenderController.cs +++ b/src/Umbraco.Web.Common/Controllers/RenderController.cs @@ -55,12 +55,14 @@ public class RenderController : UmbracoPageController, IRenderController public override async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next) { IPublishedRequest pcr = UmbracoRouteValues.PublishedRequest; - - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "Response status: Content={Content}, StatusCode={ResponseStatusCode}, Culture={Culture}", pcr.PublishedContent?.Id ?? -1, pcr.ResponseStatusCode, pcr.Culture); + } UmbracoRouteResult routeStatus = pcr.GetRouteResult(); switch (routeStatus) diff --git a/src/Umbraco.Web.Common/Macros/MacroRenderer.cs b/src/Umbraco.Web.Common/Macros/MacroRenderer.cs index 9ff69bcb7a..1bc46f0db0 100644 --- a/src/Umbraco.Web.Common/Macros/MacroRenderer.cs +++ b/src/Umbraco.Web.Common/Macros/MacroRenderer.cs @@ -249,9 +249,10 @@ public class MacroRenderer : IMacroRenderer { return null; } - - _logger.LogDebug("Macro content loaded from cache '{MacroCacheId}'", model.CacheIdentifier); - + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Macro content loaded from cache '{MacroCacheId}'", model.CacheIdentifier); + } // ensure that the source has not changed // note: does not handle dependencies, and never has FileInfo? macroSource = GetMacroFile(model); // null if macro is not file-based @@ -259,13 +260,19 @@ public class MacroRenderer : IMacroRenderer { if (macroSource.Exists == false) { - _logger.LogDebug("Macro source does not exist anymore, ignore cache."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Macro source does not exist anymore, ignore cache."); + } return null; } if (macroContent.Date < macroSource.LastWriteTime) { - _logger.LogDebug("Macro source has changed, ignore cache."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Macro source has changed, ignore cache."); + } return null; } } @@ -304,8 +311,10 @@ public class MacroRenderer : IMacroRenderer CacheKeys.MacroContentCacheKey + model.CacheIdentifier, () => macroContent, new TimeSpan(0, 0, model.CacheDuration)); - - _logger.LogDebug("Macro content saved to cache '{MacroCacheId}'", model.CacheIdentifier); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Macro content saved to cache '{MacroCacheId}'", model.CacheIdentifier); + } } // gets the macro source file name @@ -372,7 +381,7 @@ public class MacroRenderer : IMacroRenderer } var macroInfo = $"Render Macro: {macro.Name}, cache: {macro.CacheDuration}"; - using (_profilingLogger.DebugDuration(macroInfo, "Rendered Macro.")) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration(macroInfo, "Rendered Macro.")) { // parse macro parameters ie replace the special [#key], [$key], etc. syntaxes foreach (MacroPropertyModel prop in macro.Properties) @@ -424,7 +433,7 @@ public class MacroRenderer : IMacroRenderer /// private Attempt ExecuteMacroWithErrorWrapper(MacroModel macro, string msgIn, string msgOut, Func getMacroContent, Func msgErr) { - using (_profilingLogger.DebugDuration(msgIn, msgOut)) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration(msgIn, msgOut)) { return ExecuteProfileMacroWithErrorWrapper(macro, msgIn, getMacroContent, msgErr); } diff --git a/src/Umbraco.Web.Common/Middleware/UmbracoRequestMiddleware.cs b/src/Umbraco.Web.Common/Middleware/UmbracoRequestMiddleware.cs index 9b93ad890c..f5b4f06a69 100644 --- a/src/Umbraco.Web.Common/Middleware/UmbracoRequestMiddleware.cs +++ b/src/Umbraco.Web.Common/Middleware/UmbracoRequestMiddleware.cs @@ -114,9 +114,12 @@ public class UmbracoRequestMiddleware : IMiddleware try { - // Verbose log start of every request - LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache); - _logger.LogTrace("Begin request [{HttpRequestId}]: {RequestUrl}", httpRequestId, pathAndQuery); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Trace)) + { + // Verbose log start of every request + LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache); + _logger.LogTrace("Begin request [{HttpRequestId}]: {RequestUrl}", httpRequestId, pathAndQuery); + } try { @@ -144,14 +147,17 @@ public class UmbracoRequestMiddleware : IMiddleware } finally { - // Verbose log end of every request (in v8 we didn't log the end request of ALL requests, only the front-end which was - // strange since we always logged the beginning, so now we just log start/end of all requests) - LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache); - _logger.LogTrace( - "End Request [{HttpRequestId}]: {RequestUrl} ({RequestDuration}ms)", - httpRequestId, - pathAndQuery, - DateTime.Now.Subtract(umbracoContextReference.UmbracoContext.ObjectCreated).TotalMilliseconds); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Trace)) + { + // Verbose log end of every request (in v8 we didn't log the end request of ALL requests, only the front-end which was + // strange since we always logged the beginning, so now we just log start/end of all requests) + LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache); + _logger.LogTrace( + "End Request [{HttpRequestId}]: {RequestUrl} ({RequestDuration}ms)", + httpRequestId, + pathAndQuery, + DateTime.Now.Subtract(umbracoContextReference.UmbracoContext.ObjectCreated).TotalMilliseconds); + } try { diff --git a/src/Umbraco.Web.Common/ModelsBuilder/InMemoryAuto/InMemoryModelFactory.cs b/src/Umbraco.Web.Common/ModelsBuilder/InMemoryAuto/InMemoryModelFactory.cs index 12846f6bdd..55d4cf121d 100644 --- a/src/Umbraco.Web.Common/ModelsBuilder/InMemoryAuto/InMemoryModelFactory.cs +++ b/src/Umbraco.Web.Common/ModelsBuilder/InMemoryAuto/InMemoryModelFactory.cs @@ -215,7 +215,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto // tells the factory that it should build a new generation of models private void ResetModels() { - _logger.LogDebug("Resetting models."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Resetting models."); + } try { @@ -257,7 +260,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto { if (_debugLevel > 0) { - _logger.LogDebug("Ensuring models."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Ensuring models."); + } } // don't use an upgradeable lock here because only 1 thread at a time could enter it @@ -291,7 +297,7 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto // we don't have models, // either they haven't been loaded from the cache yet // or they have been reseted and are pending a rebuild - using (_profilingLogger.DebugDuration("Get models.", "Got models.")) + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration("Get models.", "Got models.")) { try { @@ -396,13 +402,19 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto // currentHash hashes both the types & the user's partials if (!forceRebuild) { - _logger.LogDebug("Looking for cached models."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Looking for cached models."); + } if (File.Exists(modelsHashFile) && File.Exists(projFile)) { var cachedHash = File.ReadAllText(modelsHashFile); if (currentHash != cachedHash) { - _logger.LogDebug("Found obsolete cached models."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Found obsolete cached models."); + } forceRebuild = true; } @@ -426,8 +438,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto if (File.Exists(dllPathFile)) { var dllPath = File.ReadAllText(dllPathFile); - - _logger.LogDebug($"Cached models dll at {dllPath}."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Cached models dll at {dllPath}.",dllPath); + } if (File.Exists(dllPath) && !File.Exists(dllPath + ".delete")) { @@ -441,24 +455,37 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto // ver 1, but we remember we want to skip that one - so we never end up // with the "same but different" version of the assembly in memory _skipver = assembly.GetName().Version?.Revision; - - _logger.LogDebug("Loading cached models (dll)."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Loading cached models (dll)."); + } return assembly; } - - _logger.LogDebug("Cached models dll cannot be loaded (invalid assembly)."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Cached models dll cannot be loaded (invalid assembly)."); + } } else if (!File.Exists(dllPath)) { - _logger.LogDebug("Cached models dll does not exist."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Cached models dll does not exist."); + } } else if (File.Exists(dllPath + ".delete")) { - _logger.LogDebug("Cached models dll is marked for deletion."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Cached models dll is marked for deletion."); + } } else { - _logger.LogDebug("Cached models dll cannot be loaded (why?)."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Cached models dll cannot be loaded (why?)."); + } } } @@ -487,13 +514,18 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto ClearOnFailingToCompile(dllPathFile, modelsHashFile, projFile); throw; } - - _logger.LogDebug("Loading cached models (source)."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Loading cached models (source)."); + } return assembly; } // need to rebuild - _logger.LogDebug("Rebuilding models."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Rebuilding models."); + } // generate code, save var code = GenerateModelsCode(typeModels); @@ -531,8 +563,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto ClearOnFailingToCompile(dllPathFile, modelsHashFile, projFile); throw; } - - _logger.LogDebug("Done rebuilding."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Done rebuilding."); + } return assembly; } @@ -577,7 +611,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto private void ClearOnFailingToCompile(string dllPathFile, string modelsHashFile, string projFile) { - _logger.LogDebug("Failed to compile."); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Failed to compile."); + } // the dll file reference still points to the previous dll, which is obsolete // now and will be deleted by ASP.NET eventually, so better clear that reference. diff --git a/src/Umbraco.Web.Common/Security/MemberSignInManager.cs b/src/Umbraco.Web.Common/Security/MemberSignInManager.cs index 6b392c42fd..d402e5f843 100644 --- a/src/Umbraco.Web.Common/Security/MemberSignInManager.cs +++ b/src/Umbraco.Web.Common/Security/MemberSignInManager.cs @@ -79,10 +79,13 @@ public class MemberSignInManager : UmbracoSignInManager, IMe IDictionary? items = auth.Properties?.Items; if (auth.Principal == null || items == null) { - Logger.LogDebug( + if (Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + Logger.LogDebug( auth.Failure ?? new NullReferenceException("Context.AuthenticateAsync(ExternalAuthenticationType) is null"), "The external login authentication failed. No user Principal or authentication items was resolved."); + } return null; } diff --git a/src/Umbraco.Web.Common/Security/UmbracoSignInManager.cs b/src/Umbraco.Web.Common/Security/UmbracoSignInManager.cs index 052a3ae631..7f16042988 100644 --- a/src/Umbraco.Web.Common/Security/UmbracoSignInManager.cs +++ b/src/Umbraco.Web.Common/Security/UmbracoSignInManager.cs @@ -59,8 +59,11 @@ public abstract class UmbracoSignInManager : SignInManager IDictionary? items = auth.Properties?.Items; if (auth.Principal == null || items == null) { - Logger.LogDebug( + if (Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + Logger.LogDebug( "The external login authentication failed. No user Principal or authentication items was resolved."); + } return null; } diff --git a/src/Umbraco.Web.Website/ActionResults/UmbracoPageResult.cs b/src/Umbraco.Web.Website/ActionResults/UmbracoPageResult.cs index 897aca28bb..46a4bd20bd 100644 --- a/src/Umbraco.Web.Website/ActionResults/UmbracoPageResult.cs +++ b/src/Umbraco.Web.Website/ActionResults/UmbracoPageResult.cs @@ -60,7 +60,7 @@ public class UmbracoPageResult : IActionResult /// private async Task ExecuteControllerAction(IActionInvoker? actionInvoker) { - using (_profilingLogger.TraceDuration( + using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Verbose) ? null : _profilingLogger.TraceDuration( "Executing Umbraco RouteDefinition controller", "Finished")) { diff --git a/src/Umbraco.Web.Website/Routing/PublicAccessRequestHandler.cs b/src/Umbraco.Web.Website/Routing/PublicAccessRequestHandler.cs index a33ac7bca2..b7c751d28c 100644 --- a/src/Umbraco.Web.Website/Routing/PublicAccessRequestHandler.cs +++ b/src/Umbraco.Web.Website/Routing/PublicAccessRequestHandler.cs @@ -50,7 +50,10 @@ public class PublicAccessRequestHandler : IPublicAccessRequestHandler PublicAccessStatus publicAccessStatus; do { - _logger.LogDebug(nameof(RewriteForPublishedContentAccessAsync) + ": Loop {LoopCounter}", i); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug(nameof(RewriteForPublishedContentAccessAsync) + ": Loop {LoopCounter}", i); + } IPublishedContent? publishedContent = routeValues.PublishedRequest?.PublishedContent; if (publishedContent == null) @@ -64,7 +67,10 @@ public class PublicAccessRequestHandler : IPublicAccessRequestHandler if (publicAccessAttempt.Success) { - _logger.LogDebug("EnsurePublishedContentAccess: Page is protected, check for access"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("EnsurePublishedContentAccess: Page is protected, check for access"); + } // manually authenticate the request AuthenticateResult authResult = @@ -87,7 +93,10 @@ public class PublicAccessRequestHandler : IPublicAccessRequestHandler // redirect if this is not the login page if (publicAccessAttempt.Result!.LoginNodeId != publishedContent.Id) { - _logger.LogDebug("EnsurePublishedContentAccess: Not logged in, redirect to login page"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("EnsurePublishedContentAccess: Not logged in, redirect to login page"); + } routeValues = await SetPublishedContentAsOtherPageAsync( httpContext, routeValues.PublishedRequest, publicAccessAttempt.Result!.LoginNodeId); } @@ -97,32 +106,47 @@ public class PublicAccessRequestHandler : IPublicAccessRequestHandler // Redirect if this is not the access denied page if (publicAccessAttempt.Result!.NoAccessNodeId != publishedContent.Id) { - _logger.LogDebug( + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug( "EnsurePublishedContentAccess: Current member has not access, redirect to error page"); + } routeValues = await SetPublishedContentAsOtherPageAsync( httpContext, routeValues.PublishedRequest, publicAccessAttempt.Result!.NoAccessNodeId); } break; case PublicAccessStatus.LockedOut: - _logger.LogDebug("Current member is locked out, redirect to error page"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Current member is locked out, redirect to error page"); + } routeValues = await SetPublishedContentAsOtherPageAsync( httpContext, routeValues.PublishedRequest, publicAccessAttempt.Result!.NoAccessNodeId); break; case PublicAccessStatus.NotApproved: - _logger.LogDebug("Current member is unapproved, redirect to error page"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Current member is unapproved, redirect to error page"); + } routeValues = await SetPublishedContentAsOtherPageAsync( httpContext, routeValues.PublishedRequest, publicAccessAttempt.Result!.NoAccessNodeId); break; case PublicAccessStatus.AccessAccepted: - _logger.LogDebug("Current member has access"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("Current member has access"); + } break; } } else { publicAccessStatus = PublicAccessStatus.AccessAccepted; - _logger.LogDebug("EnsurePublishedContentAccess: Page is not protected"); + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug("EnsurePublishedContentAccess: Page is not protected"); + } } // loop until we have access or reached max loops @@ -130,8 +154,11 @@ public class PublicAccessRequestHandler : IPublicAccessRequestHandler if (i == maxLoop) { - _logger.LogDebug(nameof(RewriteForPublishedContentAccessAsync) + + if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug)) + { + _logger.LogDebug(nameof(RewriteForPublishedContentAccessAsync) + ": Looks like we are running into an infinite loop, abort"); + } } return routeValues;