v12 - clean up some logging

KevinJump · Aug 8, 2023 · 0e6ac22 · 0e6ac22
1 parent 51a2d3a
commit 0e6ac22
Show file tree

Hide file tree

Showing 5 changed files with 33 additions and 21 deletions.
diff --git a/uSync.BackOffice/Notifications/SyncScopedNotificationPublisher.cs b/uSync.BackOffice/Notifications/SyncScopedNotificationPublisher.cs
@@ -1,4 +1,5 @@
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 
 using Microsoft.Extensions.Logging;
@@ -33,7 +34,8 @@ protected override void PublishScopedNotifications(IList<INotification> notifica
         if (notifications.Count > 0)
         {
             //_updateCallback?.Invoke($"Processing notifications [{notifications.Count}]", 9, 10);
-            _logger.LogDebug("Publishing Notifications [{count}]", notifications.Count);
+            _logger.LogDebug(">> Publishing Notifications [{count}]", notifications.Count);
+            var sw = Stopwatch.StartNew();
 
             var groupedNotifications = notifications
                 .Where(x => x != null)
@@ -44,6 +46,12 @@ protected override void PublishScopedNotifications(IList<INotification> notifica
                 _updateCallback?.Invoke($"Processing {items.Key}s ({items.Count()})", 90, 100);
                 _eventAggregator.Publish(items);
             }
+
+            sw.Stop();
+            _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/SyncHandlers/SyncHandlerLevelBase.cs b/uSync.BackOffice/SyncHandlers/SyncHandlerLevelBase.cs
@@ -69,7 +69,7 @@ protected override IEnumerable<uSyncAction> ImportFolder(string folder, HandlerS
             {
                 callback?.Invoke(item.Node.Alias, item.Index, orderedFiles.Count);
 
-                logger.LogTrace("{Index} Importing: {File}, [Level {Level}]", item.Index, item.Node.Alias, item.Node.Level);
+                logger.LogDebug(">> {Index} Importing: {alias}, [Level {Level}]", item.Index, item.Node.Alias, item.Node.Level);
 
                 var result = Import(item.Node.File, config, flags);
                 foreach (var attempt in result)
@@ -89,6 +89,7 @@ protected override IEnumerable<uSyncAction> ImportFolder(string folder, HandlerS
                     if (attempt.Change != ChangeType.Clean)
                         actions.Add(attempt);
                 }
+                logger.LogDebug("<< {index} Imported: {alias}", item.Index, item.Node.Alias);
             }
 
             if (flags.HasFlag(SerializerFlags.DoNotSave) && updates.Any())
@@ -147,9 +148,6 @@ private IList<LeveledFile> GetLevelOrderedFiles(string folder, IList<uSyncAction
                             Level = (node.GetLevel() * 1000) + node.GetItemSortOrder(), // will hopefully let us put things in sort order in one go. 
                             File = file
                         });
-
-                        // debug.
-                        logger.LogDebug("{file} {level}", file, (node.GetLevel() * 1000) + node.GetItemSortOrder());
                     }
                 }
                 catch (XmlException ex)
@@ -162,7 +160,6 @@ private IList<LeveledFile> GetLevelOrderedFiles(string folder, IList<uSyncAction
             }
 
             return nodes.OrderBy(x => x.Level).ToList();
-
         }
 
         private class LeveledFile

diff --git a/uSync.Core/Serialization/Serializers/ContentSerializer.cs b/uSync.Core/Serialization/Serializers/ContentSerializer.cs
@@ -515,6 +515,7 @@ public Attempt<string> PublishItem(IContent item, int userId)
         {
             try
             {
+                logger.LogDebug("Publishing: {item} as User:{user}", item.Name, userId);
                 var result = contentService.SaveAndPublish(item, userId: userId);
                 if (!result.Success)
                 {
@@ -559,6 +560,9 @@ private Attempt<string> PublishItem(IContent item, IDictionary<string, uSyncCont
 
                 if (publishedCultures.Length > 0)
                 {
+                    logger.LogDebug("Publishing {item} as {user} for {cultures}", item.Name, userId,
+                        string.Join(",", publishedCultures));
+
                     var result = contentService.SaveAndPublish(item, publishedCultures, userId);
 
                     // if this fails, we return the result
@@ -590,7 +594,13 @@ private Attempt<string> PublishItem(IContent item, IDictionary<string, uSyncCont
                     {
                         // unpublish if the culture is currently published.
                         if (item.PublishedCultures.InvariantContains(culture))
+                        {
+                            logger.LogDebug("Unpublishing {item} as {user} for {culture}",
+                                item.Name, userId, culture);
+
                             contentService.Unpublish(item, culture, userId);
+                        }
+
                     }
                 }
 
@@ -600,7 +610,10 @@ private Attempt<string> PublishItem(IContent item, IDictionary<string, uSyncCont
 
                 // if we get to this point and no save has been called, we should call it. 
                 if (!hasBeenSaved && item.IsDirty())
+                {
+                    logger.LogDebug("Saving {item} because we didn't publish it", item.Name);
                     contentService.Save(item);
+                }
 
                 return Attempt.Succeed("Done");
             }
@@ -629,7 +642,7 @@ private void UnpublishMissingCultures(IContent item, string[] allCultures)
             {
                 foreach (var culture in missingCultures)
                 {
-                    logger.LogDebug("Unpublishing culture not defined in config file {culture}", culture);
+                    logger.LogDebug("Unpublishing {item} culture not defined in config file {culture}", item.Name, culture);
                     contentService.Unpublish(item, culture);
                 }
             }

diff --git a/uSync.Core/Serialization/Serializers/ContentSerializerBase.cs b/uSync.Core/Serialization/Serializers/ContentSerializerBase.cs
@@ -339,7 +339,7 @@ protected virtual IEnumerable<uSyncChange> DeserializeBase(TObject item, XElemen
                 var nodePath = CalculateNodePath(item, default(TObject));
 
                 var parentNode = info.Element(uSyncConstants.Xml.Parent);
-                if (parentNode != null)
+                if (parentNode != null && parentNode.Attribute(uSyncConstants.Xml.Key).ValueOrDefault(Guid.Empty) != Guid.Empty)
                 {
                     var parent = FindParent(parentNode, false);
                     if (parent == null)

diff --git a/uSync.Core/Serialization/SyncSerializerRoot.cs b/uSync.Core/Serialization/SyncSerializerRoot.cs
@@ -75,30 +75,24 @@ public SyncAttempt<TObject> Deserialize(XElement node, SyncSerializerOptions opt
                 var check = CanDeserialize(node, options);
                 if (!check.Success) return check;
 
-                logger.LogDebug("Base: Deserializing {0}", ItemType);
+                var alias = node.GetAlias();
+
+                logger.LogDebug(" >> Deserializing {alias} - {type}", alias, ItemType);
                 var result = DeserializeCore(node, options);
+                logger.LogDebug(" << Deserialized result {alias} - {result}", alias, result.Success);
 
                 if (result.Success)
                 {
-                    logger.LogDebug("Base: Deserialize Core Success {0}", ItemType);
-
                     if (!result.Saved && !options.Flags.HasFlag(SerializerFlags.DoNotSave))
                     {
-                        logger.LogDebug("Base: Serializer Saving (No DoNotSaveFlag) {0}", ItemAlias(result.Item));
-                        // save 
+                        logger.LogDebug("Saving - {alias}", alias);
                         SaveItem(result.Item);
                     }
 
                     if (options.OnePass)
                     {
-                        logger.LogDebug("Base: Processing item in one pass {0}", ItemAlias(result.Item));
-
-                        var secondAttempt = DeserializeSecondPass(result.Item, node, options);
-
-                        logger.LogDebug("Base: Second Pass Result {0} {1}", ItemAlias(result.Item), secondAttempt.Success);
-
-                        // if its the second pass, we return the results of that pass
-                        return secondAttempt;
+                        logger.LogDebug("Deserialized {alias} - second pass", alias);
+                        return DeserializeSecondPass(result.Item, node, options);
                     }
                 }