diff --git a/uSync.AutoTemplates/TemplateWatcher.cs b/uSync.AutoTemplates/TemplateWatcher.cs index b7f647273..1bfac2f44 100644 --- a/uSync.AutoTemplates/TemplateWatcher.cs +++ b/uSync.AutoTemplates/TemplateWatcher.cs @@ -165,7 +165,8 @@ private void CheckFile(string filename) { if (_templateFileSystem?.FileExists(filename) is false) return; - _logger.LogInformation("Checking {filename} template", filename); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("Checking {filename} template", filename); var fileAlias = GetAliasFromFileName(filename); diff --git a/uSync.BackOffice/Boot/FirstBootMigration.cs b/uSync.BackOffice/Boot/FirstBootMigration.cs index a92097329..0377a4405 100644 --- a/uSync.BackOffice/Boot/FirstBootMigration.cs +++ b/uSync.BackOffice/Boot/FirstBootMigration.cs @@ -67,15 +67,17 @@ protected override async Task MigrateAsync() if (_serverRoleAccessor.CurrentServerRole == ServerRole.Subscriber) { - _logger.LogInformation("This is a Subscriber server in a load balanced setup - uSync only runs on single or schedulingPublisher (main) servers"); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("This is a Subscriber server in a load balanced setup - uSync only runs on single or schedulingPublisher (main) servers"); + return; } var sw = Stopwatch.StartNew(); var changes = 0; - _logger.LogInformation("Import on First-boot Set - will import {group} handler groups", - _uSyncConfig.Settings.FirstBootGroup); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("Import on First-boot Set - will import {group} handler groups", _uSyncConfig.Settings.FirstBootGroup); // if config service is set to import on first boot then this // will let uSync do a first boot import @@ -95,8 +97,9 @@ protected override async Task MigrateAsync() }; sw.Stop(); - _logger.LogInformation("uSync First boot complete {changes} changes in ({time}ms)", - changes, sw.ElapsedMilliseconds); + + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("uSync First boot complete {changes} changes in ({time}ms)", changes, sw.ElapsedMilliseconds); } catch (Exception ex) { diff --git a/uSync.BackOffice/Notifications/SyncScopedNotificationPublisher.cs b/uSync.BackOffice/Notifications/SyncScopedNotificationPublisher.cs index 6f90f13c6..5e8a03be2 100644 --- a/uSync.BackOffice/Notifications/SyncScopedNotificationPublisher.cs +++ b/uSync.BackOffice/Notifications/SyncScopedNotificationPublisher.cs @@ -60,21 +60,28 @@ protected override void PublishScopedNotifications(IList notifica { if (notifications.Count == 0) return; - _logger.LogDebug(">> Publishing Notifications [{count}]", notifications.Count); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug(">> Publishing Notifications [{count}]", notifications.Count); + var sw = Stopwatch.StartNew(); SetNotificationStates(notifications); if (_uSyncConfig.Settings.BackgroundNotifications is true && _backgroundTaskQueue != null) { - _logger.LogDebug("Processing notifications in background queue"); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Processing notifications in background queue"); + _backgroundTaskQueue.QueueBackgroundWorkItem( cancellationToken => { using (ExecutionContext.SuppressFlow()) { Task.Run(() => base.PublishScopedNotifications(notifications), cancellationToken); - _logger.LogDebug("Background Events Processed"); + + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Background Events Processed"); + return Task.CompletedTask; } }); @@ -95,7 +102,9 @@ protected override void PublishScopedNotifications(IList notifica } sw.Stop(); - _logger.LogDebug("<< Notifications processed - {elapsed}ms", sw.ElapsedMilliseconds); + + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("<< Notifications processed - {elapsed}ms", sw.ElapsedMilliseconds); if (sw.ElapsedMilliseconds / notifications.Count > 2000) _logger.LogWarning("Processing notifications is slow, you should check for custom code running on notification events that may slow this down"); diff --git a/uSync.BackOffice/Notifications/uSyncApplicationStartingHandler.cs b/uSync.BackOffice/Notifications/uSyncApplicationStartingHandler.cs index 267a292aa..33acc533a 100644 --- a/uSync.BackOffice/Notifications/uSyncApplicationStartingHandler.cs +++ b/uSync.BackOffice/Notifications/uSyncApplicationStartingHandler.cs @@ -70,19 +70,25 @@ public async Task HandleAsync(UmbracoApplicationStartingNotification notificatio // are not running on a replica. if (_runtimeState.Level < RuntimeLevel.Run) { - _logger.LogInformation("Umbraco is in {mode} mode, so uSync will not run this time.", _runtimeState.Level); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("Umbraco is in {mode} mode, so uSync will not run this time.", _runtimeState.Level); + return; } if (_serverRegistrar.CurrentServerRole == ServerRole.Subscriber) { - _logger.LogInformation("This is a replicate server in a load balanced setup - uSync will not run {serverRole}", _serverRegistrar.CurrentServerRole); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("This is a replicate server in a load balanced setup - uSync will not run {serverRole}", _serverRegistrar.CurrentServerRole); + return; } if (_uSyncConfig.Settings.BackgroundStartup || _uSyncConfig.Settings.ProcessingMode == SyncProcessingMode.Background) { - _logger.LogInformation("uSync: Running startup in background"); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("uSync: Running startup in background"); + _backgroundTaskQueue.QueueBackgroundWorkItem( cancellationToken => { @@ -119,7 +125,8 @@ private async Task InituSyncAsync() Group = _uSyncConfig.Settings.ExportOnSave }; - _logger.LogInformation("uSync: Running export at startup"); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("uSync: Running export at startup"); _uSyncService.StartupExportAsync(_uSyncConfig.GetWorkingFolder(), options).Wait(); @@ -127,7 +134,8 @@ private async Task InituSyncAsync() if (IsImportAtStartupEnabled()) { - _logger.LogInformation("uSync: Running Import at startup {group}", _uSyncConfig.Settings.ImportAtStartup); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("uSync: Running Import at startup {group}", _uSyncConfig.Settings.ImportAtStartup); var workingFolder = _uSyncConfig.GetWorkingFolder(); var hasStopFile = HasStopFile(workingFolder); @@ -144,7 +152,8 @@ private async Task InituSyncAsync() } else { - _logger.LogInformation("Startup Import blocked by {stopFile} file", _uSyncConfig.Settings.StopFile); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("Startup Import blocked by {stopFile} file", _uSyncConfig.Settings.StopFile); } } } @@ -156,7 +165,9 @@ private async Task InituSyncAsync() finally { sw.Stop(); - _logger.LogInformation("uSync: Startup Complete {elapsed}ms", sw.ElapsedMilliseconds); + + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("uSync: Startup Complete {elapsed}ms", sw.ElapsedMilliseconds); } } @@ -215,7 +226,9 @@ private async Task ProcessOnceFileAsync(string folder) { _syncFileService.DeleteFile($"{folder}/{_uSyncConfig.Settings.OnceFile}"); await _syncFileService.SaveFileAsync($"{folder}/{_uSyncConfig.Settings.StopFile}", "uSync Stop file, prevents startup import"); - _logger.LogInformation($"{_uSyncConfig.Settings.OnceFile} file replaced by {_uSyncConfig.Settings.StopFile} file"); + + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("{onceFile} file replaced by {stopFile} file", _uSyncConfig.Settings.OnceFile, _uSyncConfig.Settings.StopFile); } } diff --git a/uSync.BackOffice/Services/SyncActionService.cs b/uSync.BackOffice/Services/SyncActionService.cs index def996b78..07fc5d00f 100644 --- a/uSync.BackOffice/Services/SyncActionService.cs +++ b/uSync.BackOffice/Services/SyncActionService.cs @@ -186,8 +186,9 @@ private string MakeValidImportFolder(string folder) /// public async Task StartProcessAsync(SyncStartActionRequest request) { - _logger.LogInformation("[uSync {version}] {user} Starting {action} process", - uSync.Version.ToString(3), request.Username, request.HandlerAction); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("[uSync {version}] {user} Starting {action} process", uSync.Version.ToString(3), request.Username, request.HandlerAction); + _timer = Stopwatch.StartNew(); await _uSyncService.StartBulkProcessAsync(request.HandlerAction); @@ -211,9 +212,12 @@ public async Task FinishProcessAsync(SyncFinalActionRequest re _timer?.Stop(); var elapsed = _timer?.ElapsedMilliseconds ?? 0; - _logger.LogInformation("[uSync {version}] {user} finished {action} process ({changes}/{count} changes) in ({time:#,#}ms)", - uSync.Version.ToString(3), request.Username, request.HandlerAction, - request.Actions.CountChanges(), request.Actions.Count(), elapsed); + if (_logger.IsEnabled(LogLevel.Information)) + { + _logger.LogInformation("[uSync {version}] {user} finished {action} process ({changes}/{count} changes) in ({time:#,#}ms)", + uSync.Version.ToString(3), request.Username, request.HandlerAction, + request.Actions.CountChanges(), request.Actions.Count(), elapsed); + } request.Callbacks?.Update?.Invoke($"{request.HandlerAction} completed ({elapsed:#,#}ms)", 1, 1); diff --git a/uSync.BackOffice/Services/SyncFileService.cs b/uSync.BackOffice/Services/SyncFileService.cs index 9d79aa015..6a0c96c9c 100644 --- a/uSync.BackOffice/Services/SyncFileService.cs +++ b/uSync.BackOffice/Services/SyncFileService.cs @@ -213,7 +213,8 @@ public async Task LoadXElementAsync(string file) /// public async Task SaveFileAsync(string filename, Stream stream) { - _logger.LogDebug("Saving File: {file}", filename); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Saving File: {file}", filename); using (Stream fileStream = OpenWrite(filename)) { @@ -227,7 +228,9 @@ public async Task SaveFileAsync(string filename, Stream stream) public async Task SaveFileAsync(string filename, string content) { var localFile = GetAbsPath(filename); - _logger.LogDebug("Saving File: {local} [{length}]", localFile, content.Length); + + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Saving File: {local} [{length}]", localFile, content.Length); using (Stream stream = OpenWrite(localFile)) { diff --git a/uSync.BackOffice/Services/SyncService.cs b/uSync.BackOffice/Services/SyncService.cs index 4cd546274..e65c6161d 100644 --- a/uSync.BackOffice/Services/SyncService.cs +++ b/uSync.BackOffice/Services/SyncService.cs @@ -129,7 +129,9 @@ public async Task> StartupImportAsync(string[] folders, if (_lastStartupRun.HasValue && _lastStartupRun.Value == runHash) { - _logger.LogInformation("uSync: Skipping [duplicate] startup import has already ran with these parameters"); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("uSync: Skipping [duplicate] startup import has already ran with these parameters"); + return []; } @@ -212,11 +214,14 @@ public async Task> ImportAsync(string[] folders, bool f // fire complete await _mutexService.FireBulkCompleteAsync(new uSyncImportCompletedNotification(actions, handlerOptions.Group)); - _logger.LogInformation("uSync Import: {handlerCount} handlers, processed {itemCount} items, {changeCount} changes in {ElapsedMilliseconds}ms", - handlers.Count(), - actions.Count, - actions.CountChanges(), - sw.ElapsedMilliseconds); + if (_logger.IsEnabled(LogLevel.Information)) + { + _logger.LogInformation("uSync Import: {handlerCount} handlers, processed {itemCount} items, {changeCount} changes in {ElapsedMilliseconds}ms", + handlers.Count(), + actions.Count, + actions.CountChanges(), + sw.ElapsedMilliseconds); + } if (actions.ContainsErrors()) _logger.LogWarning("uSync Import: Errors detected in import : {count}", actions.CountErrors()); @@ -419,10 +424,13 @@ public async Task> ExportAsync(string folder, IEnumerab sw.Stop(); - _logger.LogInformation("uSync Export: {handlerCount} handlers, processed {itemCount} items, {changeCount} changes in {ElapsedMilliseconds}ms", - handlers.Count(), actions.Count, - actions.CountChanges(), - sw.ElapsedMilliseconds); + if (_logger.IsEnabled(LogLevel.Information)) + { + _logger.LogInformation("uSync Export: {handlerCount} handlers, processed {itemCount} items, {changeCount} changes in {ElapsedMilliseconds}ms", + handlers.Count(), actions.Count, + actions.CountChanges(), + sw.ElapsedMilliseconds); + } callbacks?.Update?.Invoke($"Processed {actions.Count} items in {sw.ElapsedMilliseconds}ms", 1, 1); @@ -439,7 +447,8 @@ private void USyncTriggers_DoImport(uSyncTriggerArgs e) { if (e.EntityTypes != null && !string.IsNullOrWhiteSpace(e.Folder)) { - _logger.LogInformation("Import Triggered by downlevel change {folder}", e.Folder); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("Import Triggered by downlevel change {folder}", e.Folder); var handlers = _handlerFactory .GetValidHandlersByEntityType(e.EntityTypes, e.HandlerOptions); @@ -464,7 +473,8 @@ private void USyncTriggers_DoExport(uSyncTriggerArgs e) { if (e.EntityTypes != null && !string.IsNullOrWhiteSpace(e.Folder)) { - _logger.LogInformation("Export Triggered by downlevel change {folder}", e.Folder); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("Export Triggered by downlevel change {folder}", e.Folder); var handlers = _handlerFactory .GetValidHandlersByEntityType(e.EntityTypes, e.HandlerOptions); diff --git a/uSync.BackOffice/Services/SyncService_Single.cs b/uSync.BackOffice/Services/SyncService_Single.cs index 445e5337e..dbba5adbf 100644 --- a/uSync.BackOffice/Services/SyncService_Single.cs +++ b/uSync.BackOffice/Services/SyncService_Single.cs @@ -142,7 +142,9 @@ public async Task> ImportPartialAsync(IList path.InvariantStartsWith(x))) { - logger.LogDebug("Not processing item, {alias} path {path} not in include path", node.GetAlias(), path); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Not processing item, {alias} path {path} not in include path", node.GetAlias(), path); + return false; } } @@ -131,7 +133,9 @@ private bool ImportPaths(XElement node, HandlerSettings config) var path = node.Element("Info")?.Element("Path").ValueOrDefault(string.Empty); if (!string.IsNullOrWhiteSpace(path) && exclude.Any(x => path.InvariantStartsWith(x))) { - logger.LogDebug("Not processing item, {alias} path {path} is excluded", node.GetAlias(), path); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Not processing item, {alias} path {path} is excluded", node.GetAlias(), path); + return false; } } @@ -148,14 +152,18 @@ private bool ByDocTypeConfigCheck(XElement node, HandlerSettings config) if (includeDocTypes.Length > 0 && !includeDocTypes.InvariantContains(doctype)) { - logger.LogDebug("Not processing {alias} as it in not in the Included by ContentType list {contentType}", node.GetAlias(), doctype); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Not processing {alias} as it in not in the Included by ContentType list {contentType}", node.GetAlias(), doctype); + return false; } var excludeDocTypes = config.GetSetting("ExcludeContentTypes", "").Split(',', StringSplitOptions.RemoveEmptyEntries); if (excludeDocTypes.Length > 0 && excludeDocTypes.InvariantContains(doctype)) { - logger.LogDebug("Not processing {alias} as it is excluded by ContentType {contentType}", node.GetAlias(), doctype); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Not processing {alias} as it is excluded by ContentType {contentType}", node.GetAlias(), doctype); + return false; } @@ -231,7 +239,9 @@ protected override async Task CleanUpAsync(TObject item, string newFile, string bool quickCleanup = this.DefaultConfig.GetSetting("QuickCleanup", false); if (quickCleanup) { - logger.LogDebug("Quick cleanup is on, so not looking in all config files"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Quick cleanup is on, so not looking in all config files"); + return; } diff --git a/uSync.BackOffice/SyncHandlers/Handlers/LanguageHandler.cs b/uSync.BackOffice/SyncHandlers/Handlers/LanguageHandler.cs index 1f8234a8d..1c1367935 100644 --- a/uSync.BackOffice/SyncHandlers/Handlers/LanguageHandler.cs +++ b/uSync.BackOffice/SyncHandlers/Handlers/LanguageHandler.cs @@ -140,7 +140,9 @@ protected override async Task CleanUpAsync(ILanguage item, string newFile, strin // not the file we just saved, but matching IsoCode, we remove it. if (node.Element("IsoCode").ValueOrDefault(string.Empty) == item.IsoCode) { - logger.LogDebug("Found Matching Lang File, cleaning"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Found Matching Lang File, cleaning"); + var attempt = await serializer.SerializeEmptyAsync(item, SyncActionType.Rename, node.GetAlias()); if (attempt.Success && attempt.Item is not null) { @@ -152,7 +154,9 @@ protected override async Task CleanUpAsync(ILanguage item, string newFile, strin if (!installedLanguages.InvariantContains(IsoCode)) { // language is no longer installed, make the file empty. - logger.LogDebug("Language in file is not on the site, cleaning"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Language in file is not on the site, cleaning"); + var attempt = await serializer.SerializeEmptyAsync(item, SyncActionType.Delete, node.GetAlias()); if (attempt.Success && attempt.Item is not null) { diff --git a/uSync.BackOffice/SyncHandlers/SyncHandlerBase.cs b/uSync.BackOffice/SyncHandlers/SyncHandlerBase.cs index 27e9a996b..0f37fa09b 100644 --- a/uSync.BackOffice/SyncHandlers/SyncHandlerBase.cs +++ b/uSync.BackOffice/SyncHandlers/SyncHandlerBase.cs @@ -81,7 +81,8 @@ protected override async Task> CleanFolderAsync(string var parentKey = await GetCleanParentKeyAsync(cleanFile); if (parentKey is null) return []; - logger.LogDebug("Got parent with {Id} from clean file {file}", parentKey, Path.GetFileName(cleanFile)); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Got parent with {Id} from clean file {file}", parentKey, Path.GetFileName(cleanFile)); // keys should aways have at least one entry (the key from cleanFile) // if it doesn't then something might have gone wrong. @@ -133,12 +134,14 @@ protected override async Task> DeleteMissingItemsAsync( { var items = (await GetChildItemsAsync(key)).ToArray(); - logger.LogDebug("DeleteMissingItems: {parentId} Checking {itemCount} items for {keyCount} keys", key, items.Length, keysToKeep.Count()); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("DeleteMissingItems: {parentId} Checking {itemCount} items for {keyCount} keys", key, items.Length, keysToKeep.Count()); var actions = new List(); foreach (var item in items.Where(x => !keysToKeep.Contains(x.Key))) { - logger.LogDebug("DeleteMissingItems: Found {item} that is not in file list (Reporting: {reportOnly})", item.Id, reportOnly); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("DeleteMissingItems: Found {item} that is not in file list (Reporting: {reportOnly})", item.Id, reportOnly); var name = String.Empty; if (item is IEntitySlim slim) name = slim.Name; @@ -148,7 +151,9 @@ protected override async Task> DeleteMissingItemsAsync( var actualItem = await GetFromServiceAsync(item.Key); if (actualItem == null) { - logger.LogDebug("Actual Item {id} can't be found", item.Id); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Actual Item {id} can't be found", item.Id); + continue; } @@ -157,7 +162,9 @@ protected override async Task> DeleteMissingItemsAsync( // actually do the delete if we are really not reporting if (!reportOnly) { - logger.LogInformation("Deleting item: {id} {name} as part of a 'clean' import", actualItem.Id, name); + if (logger.IsEnabled(LogLevel.Information)) + logger.LogInformation("Deleting item: {id} {name} as part of a 'clean' import", actualItem.Id, name); + await DeleteViaServiceAsync(actualItem); } } diff --git a/uSync.BackOffice/SyncHandlers/SyncHandlerContainerBase.cs b/uSync.BackOffice/SyncHandlers/SyncHandlerContainerBase.cs index 4b76fb953..16350399f 100644 --- a/uSync.BackOffice/SyncHandlers/SyncHandlerContainerBase.cs +++ b/uSync.BackOffice/SyncHandlers/SyncHandlerContainerBase.cs @@ -83,7 +83,9 @@ protected async Task> CleanFoldersAsync(Guid parentKey) if (ObjectTypes.GetUmbracoObjectType(slim.NodeObjectType) != this.ItemContainerType) continue; name = slim.Name ?? name; - logger.LogDebug("Folder has no children {name} {type}", name, slim.NodeObjectType); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Folder has no children {name} {type}", name, slim.NodeObjectType); } actions.Add(uSyncAction.SetAction(true, name, typeof(EntityContainer).Name, ChangeType.Delete, "Empty Container")); @@ -228,7 +230,8 @@ private async Task ProcessContainerChangesAsync(IEnumerable con { foreach (var folder in containers) { - logger.LogDebug("Processing container change : {name} [{id}]", folder.Name, folder.Id); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Processing container change : {name} [{id}]", folder.Name, folder.Id); var targetFolders = RootFolders.Select(x => Path.Combine(x, DefaultFolder)).ToArray(); diff --git a/uSync.BackOffice/SyncHandlers/SyncHandlerFactory.cs b/uSync.BackOffice/SyncHandlers/SyncHandlerFactory.cs index f5e3d1654..75f44f6b0 100644 --- a/uSync.BackOffice/SyncHandlers/SyncHandlerFactory.cs +++ b/uSync.BackOffice/SyncHandlers/SyncHandlerFactory.cs @@ -155,7 +155,9 @@ public IEnumerable GetValidHandlers(SyncHandlerOptions? optio if (!options.IncludeDisabled && handlerSetSettings.DisabledHandlers.InvariantContains(handler.Alias)) { - _logger.LogTrace("Handler {handler} is in the disabled handler list", handler.Alias); + if (_logger.IsEnabled(LogLevel.Trace)) + _logger.LogTrace("Handler {handler} is in the disabled handler list", handler.Alias); + continue; } diff --git a/uSync.BackOffice/SyncHandlers/SyncHandlerRoot.cs b/uSync.BackOffice/SyncHandlers/SyncHandlerRoot.cs index 8ad5b21cd..e1aecb350 100644 --- a/uSync.BackOffice/SyncHandlers/SyncHandlerRoot.cs +++ b/uSync.BackOffice/SyncHandlers/SyncHandlerRoot.cs @@ -327,7 +327,8 @@ public async Task> ImportAllAsync(string[] folders, Han CleanCaches(cacheKey); options.Callbacks?.Update?.Invoke("Done", 3, 3); - logger.LogDebug("ImportAll: {count} items imported", actions.Count); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("ImportAll: {count} items imported", actions.Count); return actions; } @@ -562,7 +563,9 @@ virtual public async Task> ImportSecondPassAsync(uSyncA if (result.Success && result.Change > ChangeType.NoChange && result.Saved is false && result.Item is not null) { - logger.LogTrace("Second Pass Import for {alias} - Saving item {key}", this.Alias, node.GetKey()); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Second Pass Import for {alias} - Saving item {key}", this.Alias, node.GetKey()); + await serializer.SaveItemAsync(result.Item); } @@ -621,7 +624,9 @@ protected virtual async Task> CleanFolderAsync(string c // move parent to here, we only need to check it if there are files. var parent = await GetCleanParentAsync(cleanFile); if (parent == null) return []; - logger.LogDebug("Got parent with {alias} from clean file {file}", GetItemAlias(parent), Path.GetFileName(cleanFile)); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Got parent with {alias} from clean file {file}", GetItemAlias(parent), Path.GetFileName(cleanFile)); // keys should aways have at least one entry (the key from cleanFile) // if it doesn't then something might have gone wrong. @@ -670,7 +675,8 @@ protected IList GetFolderKeys(string folder, bool flat) return runtimeCache.GetCacheItem(cacheKey, () => { - logger.LogDebug("Getting Folder Keys : {cacheKey}", cacheKey); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Getting Folder Keys : {cacheKey}", cacheKey); // when it's not flat structure we also get the sub folders. (extra defensive get them all) var keys = new List(); @@ -686,7 +692,8 @@ protected IList GetFolderKeys(string folder, bool flat) } } - logger.LogDebug("Loaded {count} keys from {folder} [{cacheKey}]", keys.Count, folder, cacheKey); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Loaded {count} keys from {folder} [{cacheKey}]", keys.Count, folder, cacheKey); return keys; @@ -743,11 +750,15 @@ virtual protected async Task ShouldImportAsync(XElement node, HandlerSetti { if (config.AllowCreateOnlyDeletes() is false || node.IsEmpty is false || node.GetEmptyAction() != SyncActionType.Delete) { - logger.LogDebug("CreateOnly: Item {alias} is a delete - deletes are also blocked for existing items.", node.GetAlias()); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("CreateOnly: Item {alias} is a delete - deletes are also blocked for existing items.", node.GetAlias()); + return false; } - logger.LogDebug("CreateOnly: Item {alias} already exist not importing it.", node.GetAlias()); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("CreateOnly: Item {alias} already exist not importing it.", node.GetAlias()); + return false; } } @@ -761,7 +772,9 @@ virtual protected async Task ShouldImportAsync(XElement node, HandlerSetti var ignoreList = ignore.ToDelimitedList(); if (ignoreList.InvariantContains(node.GetAlias())) { - logger.LogDebug("Ignore: Item {alias} is in the ignore list", node.GetAlias()); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Ignore: Item {alias} is in the ignore list", node.GetAlias()); + return false; } } @@ -1175,7 +1188,9 @@ private List ReportMissingParents(uSyncAction[] actions) { if (actions.Any(x => x.Key == guid && (x.Change < ChangeType.Fail || x.Change == ChangeType.ParentMissing))) { - logger.LogDebug("Found existing key in actions {item}", actions[i].Name); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Found existing key in actions {item}", actions[i].Name); + actions[i].Change = ChangeType.Create; } else @@ -1199,7 +1214,8 @@ protected virtual async Task> ReportFolderAsync(string int count = 0; - logger.LogDebug("ReportFolder: {folder} ({count} files)", folder, files.Count); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("ReportFolder: {folder} ({count} files)", folder, files.Count); foreach (string file in files) { @@ -1567,7 +1583,9 @@ protected virtual async Task CleanUpAsync(TObject item, string newFile, string f if (DoItemsMatch(node, item)) { - logger.LogDebug("Duplicate {file} of {alias}, saving as rename", Path.GetFileName(file), this.GetItemAlias(item)); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Duplicate {file} of {alias}, saving as rename", Path.GetFileName(file), this.GetItemAlias(item)); var attempt = await serializer.SerializeEmptyAsync(item, SyncActionType.Rename, node.GetAlias()); if (attempt.Success && attempt.Item is not null) diff --git a/uSync.Core/DataTypes/DataTypeSerializers/RichTextEditorMigratingSerializer.cs b/uSync.Core/DataTypes/DataTypeSerializers/RichTextEditorMigratingSerializer.cs index 3d1c998c1..7fa15693b 100644 --- a/uSync.Core/DataTypes/DataTypeSerializers/RichTextEditorMigratingSerializer.cs +++ b/uSync.Core/DataTypes/DataTypeSerializers/RichTextEditorMigratingSerializer.cs @@ -77,11 +77,15 @@ private IDictionary MigrateToTipTap(IDictionary if (configuration.ContainsKey("extensions") is true) { - _logger.LogDebug("Skipping Tiptap migration as it already contains 'extensions'."); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Skipping Tiptap migration as it already contains 'extensions'."); + return configuration; } - _logger.LogDebug("Migrating TinyMCE configuration to Tiptap format."); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Migrating TinyMCE configuration to Tiptap format."); + // do the tip tap things. // update we don't skip if the toolbar is missing, i can be for some older configs @@ -98,11 +102,13 @@ private IDictionary MigrateToTipTap(IDictionary configuration.Remove("mode"); configuration.Remove("hideLabel"); - _logger.LogDebug("Original toolbar items: {ToolbarItems}", string.Join(", ", toolbarList)); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Original toolbar items: {ToolbarItems}", string.Join(", ", toolbarList)); var newToolbar = toolbarList.Select(MapToolbarItem).WhereNotNull().ToList(); - _logger.LogDebug("Mapped toolbar items: {ToolbarItems}", string.Join(", ", newToolbar)); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Mapped toolbar items: {ToolbarItems}", string.Join(", ", newToolbar)); var extensions = _defaultExtensions.ToList(); if (configuration.TryGetValue("blocks", out var blocks) && blocks is not null) diff --git a/uSync.Core/Documents/SyncDocumentUrlCleaner.cs b/uSync.Core/Documents/SyncDocumentUrlCleaner.cs index 85036bcd5..895b0e1a7 100644 --- a/uSync.Core/Documents/SyncDocumentUrlCleaner.cs +++ b/uSync.Core/Documents/SyncDocumentUrlCleaner.cs @@ -24,7 +24,9 @@ public void CleanUrlsForDocument(Guid key) { using (_scopeProvider.CreateCoreScope(autoComplete: true)) { - _logger.LogDebug("Cleaning urls for document {DocumentKey}", key); + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Cleaning urls for document {DocumentKey}", key); + _documentUrlRepository.DeleteByDocumentKey([key]); } } diff --git a/uSync.Core/Mapping/Mappers/ImagePathMapper.cs b/uSync.Core/Mapping/Mappers/ImagePathMapper.cs index 9e890de7b..ff7fea058 100644 --- a/uSync.Core/Mapping/Mappers/ImagePathMapper.cs +++ b/uSync.Core/Mapping/Mappers/ImagePathMapper.cs @@ -55,10 +55,8 @@ public ImagePathMapper( _mediaFolder = GetMediaFolderSetting(_globalOptions.CurrentValue.UmbracoMediaPath.TrimStart('~')); _globalOptions.OnChange(x => _mediaFolder = GetMediaFolderSetting(x.UmbracoMediaPath.TrimStart('~'))); - if (!string.IsNullOrWhiteSpace(_mediaFolder)) - { - logger.LogDebug("Media Folders: [{media}]", _mediaFolder); - } + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Media Folders: [{media}]", _mediaFolder ?? "(Blank)"); _imageUrlGenerator = imageUrlGenerator; } diff --git a/uSync.Core/Mapping/SyncBlockMapperBase.cs b/uSync.Core/Mapping/SyncBlockMapperBase.cs index 064f6cd1c..7ace8e519 100644 --- a/uSync.Core/Mapping/SyncBlockMapperBase.cs +++ b/uSync.Core/Mapping/SyncBlockMapperBase.cs @@ -55,7 +55,10 @@ public SyncBlockMapperBase( private async Task GetImportProperty(object? value, string propertyEditorAlias) { if (_mapperCollection.Value is null) return value; - _logger.LogDebug("Importing block value for {PropertyEditorAlias} {valueType}", propertyEditorAlias, value?.GetType().Name ?? "blank"); + + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Importing block value for {PropertyEditorAlias} {valueType}", propertyEditorAlias, value?.GetType().Name ?? "blank"); + var importString = SyncBlockMapperBase.GetStringValue(value) ?? string.Empty; return await _mapperCollection.Value.GetImportValueAsync(importString, propertyEditorAlias); } @@ -63,7 +66,10 @@ public SyncBlockMapperBase( private async Task GetExportProperty(object? value, string propertyEditorAlias) { if (_mapperCollection.Value is null) return value; - _logger.LogDebug("Exporting block value for {PropertyEditorAlias} {valueType}", propertyEditorAlias, value?.GetType().Name ?? "blank"); + + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("Exporting block value for {PropertyEditorAlias} {valueType}", propertyEditorAlias, value?.GetType().Name ?? "blank"); + var exportValueAsString = SyncBlockMapperBase.GetStringValue(value) ?? string.Empty; var result = await _mapperCollection.Value.GetExportValueAsync(exportValueAsString, propertyEditorAlias); return result.ConvertToJsonNode()?.ExpandAllJsonInToken() ?? result; diff --git a/uSync.Core/Serialization/Serializers/ContentSerializerBase.cs b/uSync.Core/Serialization/Serializers/ContentSerializerBase.cs index 75599d1a4..df3e71128 100644 --- a/uSync.Core/Serialization/Serializers/ContentSerializerBase.cs +++ b/uSync.Core/Serialization/Serializers/ContentSerializerBase.cs @@ -337,7 +337,8 @@ protected virtual async Task> DeserializeBaseAsync(TObj { if (parentNode.GetKey() == Guid.Empty) { - logger.LogDebug("Parent is root (-1)"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Parent is root (-1)"); } else { @@ -347,7 +348,9 @@ protected virtual async Task> DeserializeBaseAsync(TObj var friendlyPath = info.Element(uSyncConstants.Xml.Path).ValueOrDefault(string.Empty); if (!string.IsNullOrWhiteSpace(friendlyPath)) { - logger.LogDebug("Find Parent failed, will search by path {FriendlyPath}", friendlyPath); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Find Parent failed, will search by path {FriendlyPath}", friendlyPath); + parent = await FindParentByPathAsync(friendlyPath); } } @@ -360,7 +363,8 @@ protected virtual async Task> DeserializeBaseAsync(TObj } else { - logger.LogDebug("Unable to find parent but parent node is set in configuration"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Unable to find parent but parent node is set in configuration"); } } } @@ -372,7 +376,10 @@ protected virtual async Task> DeserializeBaseAsync(TObj if (item.ParentId != parentId) { changes.AddUpdate(uSyncConstants.Xml.Parent, item.ParentId, parentId); - logger.LogTrace("{Id} Setting Parent {ParentId}", item.Id, parentId); + + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("{Id} Setting Parent {ParentId}", item.Id, parentId); + item.ParentId = parentId; } @@ -381,7 +388,10 @@ protected virtual async Task> DeserializeBaseAsync(TObj if (item.Path != nodePath) { changes.AddUpdate(uSyncConstants.Xml.Path, item.Path, nodePath); - logger.LogDebug("{Id} Setting Path {idPath} was {oldPath}", item.Id, nodePath, item.Path); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("{Id} Setting Path {idPath} was {oldPath}", item.Id, nodePath, item.Path); + item.Path = nodePath; } } @@ -389,7 +399,10 @@ protected virtual async Task> DeserializeBaseAsync(TObj if (item.Level != nodeLevel) { changes.AddUpdate(uSyncConstants.Xml.Level, item.Level, nodeLevel); - logger.LogDebug("{Id} Setting Level to {Level} was {OldLevel}", item.Id, nodeLevel, item.Level); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("{Id} Setting Level to {Level} was {OldLevel}", item.Id, nodeLevel, item.Level); + item.Level = nodeLevel; } } @@ -409,7 +422,9 @@ protected virtual async Task> DeserializeBaseAsync(TObj if (key != Guid.Empty && item.Key != key) { changes.AddUpdate(uSyncConstants.Xml.Key, item.Key, key); - logger.LogTrace("{Id} Setting Key {Key}", item.Id, key); + + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("{Id} Setting Key {Key}", item.Id, key); if (item.Id > 0) await OnKeyChange(item, item.Key, key); @@ -421,7 +436,10 @@ protected virtual async Task> DeserializeBaseAsync(TObj if (item.CreateDate != createDate) { changes.AddUpdate("CreateDate", item.CreateDate, createDate); - logger.LogDebug("{id} Setting CreateDate: {createDate}", item.Id, createDate); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("{id} Setting CreateDate: {createDate}", item.Id, createDate); + item.CreateDate = createDate; } @@ -433,7 +451,9 @@ protected virtual async Task> DeserializeBaseAsync(TObj protected virtual Task OnKeyChange(TObject item, Guid oldKey, Guid newKey) { // nothing to do here, but subclasses might need to act on key changes. - logger.LogDebug("{id} Key changed from {oldKey} to {newKey}", item.Id, oldKey, newKey); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("{id} Key changed from {oldKey} to {newKey}", item.Id, oldKey, newKey); + return Task.CompletedTask; } @@ -514,7 +534,8 @@ protected async Task, string>> DeserializePropertiesAs var current = item.Properties[alias]; if (current is null) continue; - logger.LogTrace("De-serialize Property {alias} {editorAlias}", alias, current.PropertyType.PropertyEditorAlias); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("De-serialize Property {alias} {editorAlias}", alias, current.PropertyType.PropertyEditorAlias); var values = property.Elements("Value").ToList(); @@ -524,7 +545,8 @@ protected async Task, string>> DeserializePropertiesAs var segment = value.Attribute("Segment").ValueOrDefault(string.Empty); var propValue = value.ValueOrDefault(string.Empty); - logger.LogTrace("{item} {Property} Culture {Culture} Segment {Segment}", item.Name, alias, culture, segment); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("{item} {Property} Culture {Culture} Segment {Segment}", item.Name, alias, culture, segment); try { @@ -535,7 +557,9 @@ protected async Task, string>> DeserializePropertiesAs // if (!current.PropertyType.VariesByCulture()) { - logger.LogTrace("Item does not vary by culture - but uSync item file contains culture"); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Item does not vary by culture - but uSync item file contains culture"); + // if we get here, then things are wrong, so we will try to fix them. // // if the content config thinks it should vary by culture, but the document type doesn't @@ -568,11 +592,15 @@ protected async Task, string>> DeserializePropertiesAs { // there is only one value - so we should set the default variant with this for consistency? culture = defaultLanguageIsoCode; - logger.LogDebug("Property {Alias} contains a single value that has no culture setting default culture {Culture}", alias, culture); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Property {Alias} contains a single value that has no culture setting default culture {Culture}", alias, culture); } else { - logger.LogDebug("{item} Property {Alias} contains a value that has no culture but this property varies by culture so this value has no effect", item.Name, alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("{item} Property {Alias} contains a value that has no culture but this property varies by culture so this value has no effect", item.Name, alias); + continue; } } @@ -590,7 +618,8 @@ protected async Task, string>> DeserializePropertiesAs string.IsNullOrEmpty(culture) ? null : culture, string.IsNullOrEmpty(segment) ? null : segment); - logger.LogDebug("Property [{id}] {item} set {alias} value", item.Id, item.Name, alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Property [{id}] {item} set {alias} value", item.Id, item.Name, alias); } } catch (Exception ex) @@ -671,7 +700,8 @@ private static bool IsUpdatedValue(object? current, object? newValue) { if (sortOrder != -1 && item.SortOrder != sortOrder) { - logger.LogTrace("{id} Setting Sort Order {sortOrder}", item.Name ?? item.Key.ToString(), sortOrder); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("{id} Setting Sort Order {sortOrder}", item.Name ?? item.Key.ToString(), sortOrder); var currentSortOrder = item.SortOrder; item.SortOrder = sortOrder; @@ -752,7 +782,8 @@ protected async Task GetExportValueAsync(object? value, IPropertyType pr // this is where the mapping magic will happen. // at the moment there are no value mappers, but if we need // them they plug in as ISyncMapper things - logger.LogTrace("Getting ExportValue [{PropertyEditorAlias}]", propertyType.PropertyEditorAlias); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Getting ExportValue [{PropertyEditorAlias}]", propertyType.PropertyEditorAlias); var exportValue = await syncMappers.GetExportValueAsync(value, propertyType.PropertyEditorAlias); @@ -763,7 +794,10 @@ protected async Task GetExportValueAsync(object? value, IPropertyType pr { return jsonNode.SerializeJsonNode(); } - logger.LogTrace("Export Value {PropertyEditorAlias} {exportValue}", propertyType.PropertyEditorAlias, exportValue ?? string.Empty); + + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Export Value {PropertyEditorAlias} {exportValue}", propertyType.PropertyEditorAlias, exportValue ?? string.Empty); + return exportValue ?? string.Empty; } @@ -773,10 +807,14 @@ protected async Task GetExportValueAsync(object? value, IPropertyType pr // this is where the mapping magic will happen. // at the moment there are no value mappers, but if we need // them they plug in as ISyncMapper things - logger.LogTrace("Getting ImportValue [{PropertyEditorAlias}]", propertyType.PropertyEditorAlias); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Getting ImportValue [{PropertyEditorAlias}]", propertyType.PropertyEditorAlias); var importValue = await syncMappers.GetImportValueAsync(value, propertyType); - logger.LogTrace("Import Value {PropertyEditorAlias} {importValue}", propertyType.PropertyEditorAlias, importValue); + + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Import Value {PropertyEditorAlias} {importValue}", propertyType.PropertyEditorAlias, importValue); + return importValue; } @@ -978,7 +1016,9 @@ public override string ItemAlias(TObject item) var key = node.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty); if (key != Guid.Empty) { - logger.LogTrace("Looking for Parent by Key {Key}", key); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Looking for Parent by Key {Key}", key); + item = await FindItemAsync(key); if (item != null) return item; } @@ -986,7 +1026,10 @@ public override string ItemAlias(TObject item) if (item == null && searchByAlias) { var alias = node.ValueOrDefault(string.Empty); - logger.LogTrace("Looking for Parent by Alias {Alias}", alias); + + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Looking for Parent by Alias {Alias}", alias); + if (!string.IsNullOrEmpty(alias)) { item = await FindItemAsync(node.ValueOrDefault(alias)); @@ -1008,12 +1051,15 @@ public override string ItemAlias(TObject item) var item = default(TObject); foreach (var folder in folders) { - logger.LogTrace("Looking for Item in folder {folder}", folder); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Looking for Item in folder {folder}", folder); + var next = await FindItemAsync(folder, item); if (next == null) { // if we get lost 1/2 way we are returning that as the path? which would put us in an odd place? - logger.LogTrace("Didn't find {folder} returning last found Parent", folder); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Didn't find {folder} returning last found Parent", folder); // if we don't fail on exact this is OK, // else its not - so we haven't 'found' the right place. @@ -1025,11 +1071,13 @@ public override string ItemAlias(TObject item) if (item == null) { - logger.LogDebug("Parent not found in the path"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Parent not found in the path"); } else { - logger.LogTrace("Parent Item Found {Name} {id}", item.Name, item.Id); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Parent Item Found {Name} {id}", item.Name, item.Id); } return item; @@ -1170,8 +1218,8 @@ private List GetExcludedProperties(SyncSerializerOptions options) } catch (ArgumentException ex) { - logger.LogDebug("Unable to parse pattern '{pattern}' from '{settingsKey}' as Regex. {error}. Pattern will not be considered.", pattern, - uSyncConstants.DefaultSettings.DoNotSerializePattern, ex.Message); + logger.LogWarning("Unable to parse pattern '{pattern}' from '{settingsKey}' as Regex. {error}. Pattern will not be considered.", pattern, + uSyncConstants.DefaultSettings.DoNotSerializePattern, ex.Message); return null; } } diff --git a/uSync.Core/Serialization/Serializers/ContentTypeBaseSerializer.cs b/uSync.Core/Serialization/Serializers/ContentTypeBaseSerializer.cs index 03e4fc583..72d26ab92 100644 --- a/uSync.Core/Serialization/Serializers/ContentTypeBaseSerializer.cs +++ b/uSync.Core/Serialization/Serializers/ContentTypeBaseSerializer.cs @@ -223,8 +223,6 @@ protected XElement SerializeCompositions(ContentTypeCompositionBase item) protected async Task> DeserializeBaseAsync(TObject item, XElement node) { - logger.LogDebug("De-serializing Base"); - if (node == null) return []; var info = node.Element(uSyncConstants.Xml.Info); @@ -341,8 +339,6 @@ protected SyncAttempt DeserializedResult(TObject item, List> DeserializeStructureAsync(TObject item, XElement node) { - logger.LogDebug("De-serializing Structure"); - var structure = node.Element("Structure"); if (structure == null) return []; @@ -357,27 +353,37 @@ protected async Task> DeserializeStructureAsync(TObject foreach (var baseNode in nodes) { - logger.LogDebug("baseNode {base}", baseNode.ToString()); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("baseNode {base}", baseNode.ToString()); + var alias = baseNode.Value; var key = baseNode.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty); - logger.LogDebug("Structure: {key}", key); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Structure: {key}", key); + var itemSortOrder = baseNode.Attribute(uSyncConstants.Xml.SortOrder).ValueOrDefault(sortOrder); - logger.LogDebug("Sort Order: {sortOrder}", itemSortOrder); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Sort Order: {sortOrder}", itemSortOrder); IContentTypeBase? baseItem = default; if (key != Guid.Empty) { - logger.LogDebug("Structure By Key {key}", key); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Structure By Key {key}", key); + // lookup by key (our preferred way) baseItem = await FindItemAsync(key); } if (baseItem == null) { - logger.LogDebug("Structure By Alias: {alias}", alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Structure By Alias: {alias}", alias); + // lookup by alias (less nice) baseItem = await FindItemAsync(alias); } @@ -415,8 +421,6 @@ protected async Task> DeserializeStructureAsync(TObject protected async Task> DeserializePropertiesAsync(TObject item, XElement node, SyncSerializerOptions options) { - logger.LogDebug("De-serializing Properties"); - var propertiesNode = node?.Element("GenericProperties"); if (propertiesNode == null) return []; @@ -437,7 +441,8 @@ protected async Task> DeserializePropertiesAsync(TObjec var definitionKey = propertyNode.Element("Definition").ValueOrDefault(Guid.Empty); var propertyEditorAlias = propertyNode.Element("Type").ValueOrDefault(string.Empty); - logger.LogDebug(" > Property: {alias} {key} {definitionKey} {editorAlias}", alias, key, definitionKey, propertyEditorAlias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug(" > Property: {alias} {key} {definitionKey} {editorAlias}", alias, key, definitionKey, propertyEditorAlias); var result = await GetOrCreatePropertyAsync(item, key, alias, definitionKey, propertyEditorAlias, compositeProperties); if (result.Property == null) @@ -521,7 +526,9 @@ protected async Task> DeserializePropertiesAsync(TObjec if (result.IsNew) { changes.AddNew(alias, name, alias); - logger.LogDebug("Property {alias} is new adding to tab. {tabAlias}", alias, tabAlias ?? "(No tab name)"); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Property {alias} is new adding to tab. {tabAlias}", alias, tabAlias ?? "(No tab name)"); if (string.IsNullOrWhiteSpace(tabAlias)) { @@ -544,7 +551,9 @@ protected async Task> DeserializePropertiesAsync(TObjec } else { - logger.LogDebug("Property {alias} exists, checking tab location {tabAlias}", alias, tabAlias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Property {alias} exists, checking tab location {tabAlias}", alias, tabAlias); + // we need to see if this one has moved. if (!string.IsNullOrWhiteSpace(tabAlias)) { @@ -577,7 +586,8 @@ protected async Task> DeserializePropertiesAsync(TObjec } else { - logger.LogDebug("Property Removal disabled by configuration"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Property Removal disabled by configuration"); } return changes; @@ -654,7 +664,9 @@ protected string GetSafeItemAlias(string alias) if (aliasCache?.Contains(alias) is true) { - logger.LogDebug("Alias clash {alias} already exists", alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Alias clash {alias} already exists", alias); + return $"{alias}_{Guid.NewGuid().ToShortKeyString(8)}"; } @@ -677,8 +689,8 @@ protected void RemoveAlias(string alias) RefreshAliasCache(); - logger.LogDebug("remove [{alias}] - {cache}", alias, - aliasCache != null ? string.Join(",", aliasCache) : "Empty"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("remove [{alias}] - {cache}", alias, aliasCache != null ? string.Join(",", aliasCache) : "Empty"); } private void RefreshAliasCache() @@ -695,7 +707,9 @@ protected void AddAlias(string alias) aliasCache?.Add(alias); RefreshAliasCache(); - logger.LogDebug("Add [{aliaS}] - {cache}", alias, string.Join(",", aliasCache ?? [])); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Add [{alias}] - {cache}", alias, string.Join(",", aliasCache ?? [])); } @@ -802,8 +816,6 @@ public TabInfo(string alias) protected IEnumerable DeserializeTabs(TObject item, XElement node) { - logger.LogDebug("De-serializing Tabs"); - bool supportsPublishing = item is ContentType; var tabs = ContentTypeBaseSerializer.LoadTabInfo(node); @@ -813,7 +825,8 @@ protected IEnumerable DeserializeTabs(TObject item, XElement node) foreach (var tab in tabs.OrderBy(x => x.Depth)) { - logger.LogDebug("> Tab {name} {alias} {sortOrder} {depth}", tab.Name, tab.Alias, tab.SortOrder, tab.Depth); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("> Tab {name} {alias} {sortOrder} {depth}", tab.Name, tab.Alias, tab.SortOrder, tab.Depth); var existing = ContentTypeBaseSerializer.FindTab(item, tab.Alias, tab.Name, tab.Key); if (existing != null) @@ -900,7 +913,9 @@ protected IEnumerable DeserializeTabs(TObject item, XElement node) // does the root tab already exist. if (item.PropertyGroups.Contains(tabRoot) is true) { - logger.LogDebug("Parent Tab {tabRoot} already exists", tabRoot); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Parent Tab {tabRoot} already exists", tabRoot); + return null; } @@ -911,7 +926,9 @@ protected IEnumerable DeserializeTabs(TObject item, XElement node) return null; } - logger.LogDebug("Parent Tab {tabRoot} doesn't exist, creating", tabRoot); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Parent Tab {tabRoot} doesn't exist, creating", tabRoot); + item.AddPropertyGroup(tabRoot, compositionParent.Name ?? tabRoot); item.PropertyGroups[tabRoot].Type = compositionParent.Type; item.PropertyGroups[tabRoot].SortOrder = compositionParent.SortOrder; @@ -1023,7 +1040,9 @@ protected IEnumerable CleanTabs(TObject item, XElement node, SyncSe } else { - logger.LogInformation("Removing tab : {alias}", tab.Alias); + if (logger.IsEnabled(LogLevel.Information)) + logger.LogInformation("Removing tab : {alias}", tab.Alias); + changes.Add(uSyncChange.Delete($"Tabs/{tab.Alias}", tab.Alias, tab.Alias)); item.PropertyGroups.Remove(tab); } @@ -1044,20 +1063,20 @@ protected async Task CleanFolderAsync(TObject item, XElement node) var key = folderNode.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty); if (key == Guid.Empty) return; - - logger.LogDebug("Folder Key {key}", key.ToString()); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Folder Key {key}", key.ToString()); var folder = await FindContainerAsync(key); if (folder is not null) return; - logger.LogDebug("Clean folder - Key doesn't not match"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Clean folder - Key doesn't match"); + await FindFolderAsync(key, folderNode.Value); } protected async Task> DeserializeCompositionsAsync(TObject item, XElement node) { - logger.LogDebug("{alias} De-serializing Compositions", item.Alias); - var comps = node?.Element(uSyncConstants.Xml.Info)?.Element("Compositions"); if (comps == null) return []; @@ -1068,7 +1087,8 @@ protected async Task> DeserializeCompositionsAsync(TObj var alias = compositionNode.Value; var key = compositionNode.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty); - logger.LogDebug("{itemAlias} > Comp {alias} {key}", item.Alias, alias, key); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("{itemAlias} > Comp {alias} {key}", item.Alias, alias, key); var type = await FindItemAsync(key, alias); if (type != null) @@ -1149,8 +1169,6 @@ private async Task GetOrCreatePropertyAsync(TObject item, string propertyEditorAlias, List? compositeProperties) { - logger.LogDebug("GetOrCreateProperty {key} [{alias}]", key, alias); - var result = new PropertyTypeResult { IsNew = false, @@ -1196,7 +1214,9 @@ private async Task GetOrCreatePropertyAsync(TObject item, if (PropertyExistsOnComposite(item, alias, compositeProperties)) { - logger.LogDebug("Cannot create property here {name} as it exist on Composition", item.Name); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Cannot create property here {name} as it exist on Composition", item.Name); + // can't create here, its on a composite return new PropertyTypeResult(); } @@ -1213,7 +1233,9 @@ private async Task GetOrCreatePropertyAsync(TObject item, // also update it if its not the same as the DataType, (because that has to match) if (!result.Property.PropertyEditorAlias.Equals(editorAlias)) { - logger.LogDebug("Property Editor Alias mismatch {propertyEditorAlias} != {editorAlias} fixing...", result.Property.PropertyEditorAlias, editorAlias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Property Editor Alias mismatch {propertyEditorAlias} != {editorAlias} fixing...", result.Property.PropertyEditorAlias, editorAlias); + result.Property.PropertyEditorAlias = editorAlias; } @@ -1262,7 +1284,8 @@ private List RemoveProperties(IContentTypeBase item, XElement prope { // if you remove something with lots of // content this can timeout (still? - need to check on v8) - logger.LogDebug("Removing {alias}", alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Removing {alias}", alias); changes.Add(uSyncChange.Delete($"Property/{alias}", alias, "")); @@ -1353,10 +1376,11 @@ protected virtual bool PropertyExistsOnComposite(TObject item, string alias, Lis public override async Task SaveItemAsync(TObject item) { - logger.LogDebug("Save Item {name} ({alias})", item.Name, item.Alias); if (item.IsDirty() is false) { - logger.LogDebug("Item not dirty, skipping save"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Item not dirty, skipping save"); + return; } diff --git a/uSync.Core/Serialization/Serializers/ContentTypeSerializer.cs b/uSync.Core/Serialization/Serializers/ContentTypeSerializer.cs index 6d9eb925e..e04e21d16 100644 --- a/uSync.Core/Serialization/Serializers/ContentTypeSerializer.cs +++ b/uSync.Core/Serialization/Serializers/ContentTypeSerializer.cs @@ -52,7 +52,10 @@ protected override void EnsureAliasCache() var sw = Stopwatch.StartNew(); var aliases = _contentTypeService.GetAllContentTypeAliases().ToList(); sw.Stop(); - this.logger.LogDebug("Cache hit, 'usync_{id}' fetching all aliases {time}ms", this.Id, sw.ElapsedMilliseconds); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Cache hit, 'usync_{id}' fetching all aliases {time}ms", this.Id, sw.ElapsedMilliseconds); + return aliases; }); } @@ -168,8 +171,6 @@ protected override IEnumerable DeserializeExtraProperties(IContentT public override async Task> DeserializeSecondPassAsync(IContentType item, XElement node, SyncSerializerOptions options) { - logger.LogDebug("Deserialize Second Pass {alias}", item.Alias); - var details = new List(); SetSafeAliasValue(item, node, false); @@ -198,7 +199,10 @@ public override async Task> DeserializeSecondPassAsync dirty += string.Join(", ", item.PropertyGroups.Where(x => x.IsDirty()).Select(x => $"Group:{x.Name}")); dirty += string.Join(", ", item.PropertyTypes.Where(x => x.IsDirty()).Select(x => $"Property:{x.Name}")); dirty += historyUpdated ? " CleanupHistory" : ""; - logger.LogDebug("Saving in Serializer because item is dirty [{properties}]", dirty); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Saving in Serializer because item is dirty [{properties}]", dirty); + await _contentTypeService.UpdateAsync(item, Constants.Security.SuperUserKey); } @@ -276,7 +280,9 @@ private async Task> DeserializeTemplatesAsync(IContentType ite if (templateItem is not null) { - logger.LogDebug("Adding Template: {alias}", templateItem.Alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Adding Template: {alias}", templateItem.Alias); + allowedTemplates.Add(templateItem); } } @@ -407,7 +413,9 @@ private List DeserializeCleanupHistory(IContentType item, XElement var updatedValue = element.Value.TryConvertTo(property.PropertyType); if (updatedValue.Success) { - logger.LogDebug("Saving HistoryCleanup Value: {name} {value}", element.Name.LocalName, updatedValue.Result); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Saving HistoryCleanup Value: {name} {value}", element.Name.LocalName, updatedValue.Result); + changes.AddUpdate($"{_historyCleanupName}:{element.Name.LocalName}", current.ToNonBlankValue(), updatedValue.Result, $"{_historyCleanupName}/{element.Name.LocalName}"); property.SetValue(historyCleanup, updatedValue.Result); } diff --git a/uSync.Core/Serialization/Serializers/DataTypeSerializer.cs b/uSync.Core/Serialization/Serializers/DataTypeSerializer.cs index 20843ddab..898cf5745 100644 --- a/uSync.Core/Serialization/Serializers/DataTypeSerializer.cs +++ b/uSync.Core/Serialization/Serializers/DataTypeSerializer.cs @@ -78,11 +78,15 @@ protected override async Task> ProcessDeleteAsync(Guid ke { if (flags.HasFlag(SerializerFlags.LastPass)) { - logger.LogDebug("Processing deletes as part of the last pass)"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Processing deletes as part of the last pass"); + return await base.ProcessDeleteAsync(key, alias, flags); } - logger.LogDebug("Delete not processing as this is not the final pass"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Delete not processing as this is not the final pass"); + return SyncAttempt.Succeed(alias, ChangeType.Hidden); } @@ -202,14 +206,19 @@ private async Task> DeserializeConfiguration(IDataType item, X var serializers = _configurationSerializers.GetSerializers(editorAlias); foreach (var serializer in serializers) { - logger.LogDebug("Running Configuration Serializer : {name} for {type}", serializer.Name, editorAlias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Running Configuration Serializer : {name} for {type}", serializer.Name, editorAlias); + importData = await serializer.GetConfigurationImportAsync(item.Name ?? node.GetAlias(), importData); } if (importData.IsJsonEqual(item.ConfigurationData) is false) { changes.AddUpdateJson("Data", item.ConfigurationData, importData, "Configuration Data"); - logger.LogDebug("Setting Config for {item} : {data}", item.Name, importData); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Setting Config for {item} : {data}", item.Name, importData); + item.ConfigurationData = importData; } // else no change. @@ -254,7 +263,9 @@ private async Task SerializeConfiguration(IDataType item) var serializers = _configurationSerializers.GetSerializers(item.EditorAlias); foreach(var serializer in serializers) { - logger.LogDebug("Running Configuration Serializer : {name} for {type}", serializer.Name, item.EditorAlias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Running Configuration Serializer : {name} for {type}", serializer.Name, item.EditorAlias); + merged = await serializer.GetConfigurationExportAsync(item.Name ?? item.Id.ToString(), merged); } @@ -320,7 +331,9 @@ private async Task SerializeConfiguration(IDataType item) if (newEditor is not null) { - logger.LogDebug("Editor replacement for {alias} found : {newAlias}", editorAlias, newAlias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Editor replacement for {alias} found : {newAlias}", editorAlias, newAlias); + return newEditor; } } diff --git a/uSync.Core/Serialization/Serializers/DictionaryItemSerializer.cs b/uSync.Core/Serialization/Serializers/DictionaryItemSerializer.cs index 1a71823ac..b4e658fbf 100644 --- a/uSync.Core/Serialization/Serializers/DictionaryItemSerializer.cs +++ b/uSync.Core/Serialization/Serializers/DictionaryItemSerializer.cs @@ -73,13 +73,16 @@ protected override async Task> DeserializeCoreAsync // renaming of mismatched key values might result in duplicates. // but the workarounds could also end up creating far to many extra records // (we would delete/recreate one each time you synced) + + logger.LogWarning("Dictionary keys (Guids) do not match - we can continue with this, but renaming dictionary items from a source computer with a mismatched key value might result in duplicate entries in your dictionary values."); - logger.LogInformation("Dictionary keys (Guids) do not match - we can continue with this, but renaming dictionary items from a source computer with a mismatched key value might result in duplicate entries in your dictionary values."); details.AddUpdate(uSyncConstants.Xml.Key, item.Key, key); if (options.GetSetting(uSyncConstants.DefaultSettings.ForceKeySync, uSyncConstants.DefaultSettings.ForceKeySync_Default)) { - logger.LogDebug("Forcing key sync of dictionary item - if the keys are out of sync on existing items this can cause a SQL Constraint error"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Forcing key sync of dictionary item - if the keys are out of sync on existing items this can cause a SQL Constraint error"); + item.Key = key; } } diff --git a/uSync.Core/Serialization/Serializers/LanguageSerializer.cs b/uSync.Core/Serialization/Serializers/LanguageSerializer.cs index c87eca084..cec96e243 100644 --- a/uSync.Core/Serialization/Serializers/LanguageSerializer.cs +++ b/uSync.Core/Serialization/Serializers/LanguageSerializer.cs @@ -68,8 +68,6 @@ protected override async Task> DeserializeCoreAsync(XElem /// public override async Task> DeserializeSecondPassAsync(ILanguage item, XElement node, SyncSerializerOptions options) { - logger.LogDebug("Language Second Pass {IsoCode}", item.IsoCode); - var details = new List(); var isDefault = node.Element("IsDefault").ValueOrDefault(false); diff --git a/uSync.Core/Serialization/Serializers/TemplateSerializer.cs b/uSync.Core/Serialization/Serializers/TemplateSerializer.cs index ded394b78..eee89a97c 100644 --- a/uSync.Core/Serialization/Serializers/TemplateSerializer.cs +++ b/uSync.Core/Serialization/Serializers/TemplateSerializer.cs @@ -55,11 +55,15 @@ protected override async Task> ProcessDeleteAsync(Guid ke { if (flags.HasFlag(SerializerFlags.LastPass)) { - logger.LogDebug("Processing deletes as part of the last pass"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Processing deletes as part of the last pass"); + return await base.ProcessDeleteAsync(key, alias, flags); } - logger.LogDebug("Delete not processing as this is not the final pass"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Delete not processing as this is not the final pass"); + return SyncAttempt.Succeed(alias, ChangeType.Hidden); } @@ -103,7 +107,9 @@ protected override async Task> DeserializeCoreAsync(XElem item = attempt.Result; details.AddNew(alias, alias, "Template"); - logger.LogDebug("New Template: {alias} {path}", item.Alias, item.Path); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("New Template: {alias} {path}", item.Alias, item.Path); // don't need to go through the process, the create also saves it. return SyncAttempt.Succeed(name, item, ChangeType.Import, "Created", true, details); @@ -155,14 +161,18 @@ protected override async Task> DeserializeCoreAsync(XElem { if (ShouldGetContentFromNode(node, options)) { - logger.LogDebug("Getting content for Template from XML"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Getting content for Template from XML"); + return Attempt.Succeed(GetContentFromConfig(node)); } var templatePath = ViewPath(node.GetAlias()); if (templatePath is not null && _viewFileSystem?.FileExists(templatePath) is true) { - logger.LogDebug("Reading {path} contents", templatePath); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Reading {path} contents", templatePath); + return Attempt.Succeed(GetContentFromFile(templatePath)); } @@ -172,7 +182,9 @@ protected override async Task> DeserializeCoreAsync(XElem { // template is not on disk, we could use the viewEngine to find the view // if this finds the view it tells us that the view is somewhere else ? - logger.LogDebug("Failed to find content, but UsingRazorViews so if Umbraco create's anyway, we will then delete the file"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Failed to find content, but UsingRazorViews so if Umbraco creates anyway, we will then delete the file"); + return Attempt.Succeed($""); } @@ -198,7 +210,9 @@ private bool ShouldGetContentFromNode(XElement node, SyncSerializerOptions optio { if (ViewsAreCompiled(options)) { - logger.LogDebug("Template contents will not be imported because site is running in Production mode"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Template contents will not be imported because site is running in Production mode"); + return false; } @@ -272,7 +286,9 @@ public override async Task> DeserializeSecondPassAsync(IT var content = await System.IO.File.ReadAllTextAsync(fullPath); if (content.Contains($"[uSyncMarker:{this.Id}]")) { - logger.LogDebug("Removing the file from disk, because it exists in a razor view {templatePath}", templatePath); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Removing the file from disk, because it exists in a razor view {templatePath}", templatePath); + _viewFileSystem.DeleteFile(templatePath); // we have to tell the handlers we saved it - or they will and write the file back @@ -335,15 +351,23 @@ public override async Task SaveItemAsync(ITemplate item) if (item.HasIdentity) { // update - logger.LogDebug("Saving: {alias} {path}", item.Alias, item.Path); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Saving: {alias} {path}", item.Alias, item.Path); + var result = await _templateService.UpdateAsync(item, userKey); - logger.LogDebug("Update Template Result: [{key}] {result} {status}", item.Key, result.Success, result.Status); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Update Template Result: [{key}] {result} {status}", item.Key, result.Success, result.Status); } else { - logger.LogDebug("Creating: {alias} {path}", item.Alias, item.Path); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Creating: {alias} {path}", item.Alias, item.Path); + var result = await _templateService.CreateAsync(item.Name ?? item.Alias, item.Alias, item.Content, userKey, item.Key); - logger.LogDebug("Update Template Result: [{key}] {result} {status}", item.Key, result.Success, result.Status); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Update Template Result: [{key}] {result} {status}", item.Key, result.Success, result.Status); } } diff --git a/uSync.Core/Serialization/SyncContainerSerializerBase.cs b/uSync.Core/Serialization/SyncContainerSerializerBase.cs index a819fc02c..be67b39f5 100644 --- a/uSync.Core/Serialization/SyncContainerSerializerBase.cs +++ b/uSync.Core/Serialization/SyncContainerSerializerBase.cs @@ -37,11 +37,15 @@ protected override async Task> ProcessDeleteAsync(Guid key, { if (flags.HasFlag(SerializerFlags.LastPass)) { - logger.LogDebug("Processing deletes as part of the last pass"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Processing deletes as part of the last pass"); + return await base.ProcessDeleteAsync(key, alias, flags); } - logger.LogDebug("Delete not processing as this is not the final pass"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Delete not processing as this is not the final pass"); + return SyncAttempt.Succeed(alias, ChangeType.Hidden); } @@ -50,8 +54,6 @@ protected override async Task> ProcessDeleteAsync(Guid key, TObject? item = await FindItemAsync(node); if (item is not null) return Attempt.Succeed(item); - logger.LogDebug("FindOrCreate: Creating"); - // create var parent = default(TObject); var treeItem = default(ITreeEntity); @@ -61,13 +63,13 @@ protected override async Task> ProcessDeleteAsync(Guid key, var parentNode = info?.Element(uSyncConstants.Xml.Parent); if (parentNode is not null) { - logger.LogDebug("Finding Parent"); - var parentKey = parentNode.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty); parent = await FindItemAsync(parentKey, parentNode.Value); if (parent != null) { - logger.LogDebug("Parent Found {parentId}", parent.Id); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Parent Found {parentId}", parent.Id); + treeItem = parent; } } @@ -81,20 +83,25 @@ protected override async Task> ProcessDeleteAsync(Guid key, var folderKey = folder.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty); - logger.LogDebug("Searching for Parent by folder {folderKey} {folderValue}", folderKey, folder.Value); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Searching for Parent by folder {folderKey} {folderValue}", folderKey, folder.Value); var container = await FindFolderAsync(folderKey, folder.Value); if (container != null) { treeItem = container; - logger.LogDebug("Parent is Folder {TreeItemId}", treeItem.Key); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Parent is Folder {TreeItemId}", treeItem.Key); // update the container key if its different (because we don't serialize folders on their own) if (container.Key != folderKey) { if (container.Key != folderKey) { - logger.LogDebug("Folder Found: Key Different"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Folder Found: Key Different"); + container.Key = folderKey; await SaveContainerAsync(treeItem.Key, container); } diff --git a/uSync.Core/Serialization/SyncSerializerRoot.cs b/uSync.Core/Serialization/SyncSerializerRoot.cs index 017225de8..197464d76 100644 --- a/uSync.Core/Serialization/SyncSerializerRoot.cs +++ b/uSync.Core/Serialization/SyncSerializerRoot.cs @@ -71,21 +71,29 @@ public async Task> DeserializeAsync(XElement node, SyncSeri var alias = node.GetAlias(); - logger.LogDebug(" >> Deserializing {alias} - {type}", alias, ItemType); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug(" >> Deserializing {alias} - {type}", alias, ItemType); + var result = await DeserializeCoreAsync(node, options); - logger.LogDebug(" << Deserialized result {alias} - {result}", alias, result.Success); + + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug(" << Deserialized result {alias} - {result}", alias, result.Success); if (result.Success && result.Item is not null) { if (!result.Saved && !options.Flags.HasFlag(SerializerFlags.DoNotSave)) { - logger.LogDebug("Saving - {alias}", alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Saving - {alias}", alias); + await SaveItemAsync(result.Item); } if (options.OnePass) { - logger.LogDebug("Deserialized {alias} - second pass", alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Deserialized {alias} - second pass", alias); + return await DeserializeSecondPassAsync(result.Item, node, options); } } @@ -153,7 +161,8 @@ protected async Task> ProcessActionAsync(XElement node, Syn var (key, alias) = FindKeyAndAlias(node); - logger.LogDebug("Empty Node : Processing Action {actionType} ({key} {alias})", actionType, key, alias); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Empty Node : Processing Action {actionType} ({key} {alias})", actionType, key, alias); switch (actionType) { @@ -175,8 +184,6 @@ protected async Task> ProcessActionAsync(XElement node, Syn protected virtual async Task> ProcessDeleteAsync(Guid key, string alias, SerializerFlags flags) { - logger.LogDebug("Processing Delete {key} {alias}", key, alias); - var item = await this.FindItemAsync(key); if (item == null && !string.IsNullOrWhiteSpace(alias)) { @@ -194,18 +201,24 @@ protected virtual async Task> ProcessDeleteAsync(Guid key, if (item != null) { - logger.LogDebug("Deleting Item : {alias}", ItemAlias(item)); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Deleting Item : {alias}", ItemAlias(item)); + await DeleteItemAsync(item); return SyncAttempt.Succeed(alias, ChangeType.Delete); } - logger.LogDebug("Delete Item not found"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Delete Item not found"); + return SyncAttempt.Succeed(alias, ChangeType.NoChange); } protected virtual SyncAttempt ProcessRename(Guid key, string alias, SerializerFlags flags) { - logger.LogDebug("Process Rename (no action)"); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Process Rename (no action)"); + return SyncAttempt.Succeed(alias, ChangeType.NoChange); } @@ -274,7 +287,8 @@ private static ChangeType CalculateEmptyChange(XElement node, XElement current) public virtual Task> SerializeEmptyAsync(TObject item, SyncActionType change, string alias) { - logger.LogDebug("Base: Serializing Empty Element {alias} {change}", alias, change); + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Base: Serializing Empty Element {alias} {change}", alias, change); if (string.IsNullOrEmpty(alias)) alias = ItemAlias(item); @@ -339,7 +353,8 @@ public virtual async Task SaveAsync(IEnumerable items) { var (key, alias) = FindKeyAndAlias(node); - logger.LogTrace("Base: Find Item {key} [{alias}]", key, alias); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Base: Find Item {key} [{alias}]", key, alias); if (key != Guid.Empty) { @@ -349,7 +364,9 @@ public virtual async Task SaveAsync(IEnumerable items) if (!string.IsNullOrWhiteSpace(alias)) { - logger.LogTrace("Base: Lookup by Alias: {alias}", alias); + if (logger.IsEnabled(LogLevel.Trace)) + logger.LogTrace("Base: Lookup by Alias: {alias}", alias); + return await FindItemAsync(alias); }