Add work on PublishedSnapshotService

src/Umbraco.PublishedCache.NuCache/ContentStore.cs

@@ -46,7 +46,8 @@ namespace Umbraco.Web.PublishedCache.NuCache
         private readonly ConcurrentDictionary<Guid, int> _contentTypeKeyToIdMap;
         private readonly ConcurrentDictionary<Guid, int> _contentKeyToIdMap;
 
-        private readonly ILogger _logger;
+        private readonly ILogger<ContentStore> _logger;
+        private readonly ILogger<Snapshot> _snapShotLogger;
         private readonly IPublishedModelFactory _publishedModelFactory;
         private BPlusTree<int, ContentNodeKit> _localDb;
         private readonly ConcurrentQueue<GenObj> _genObjs;
@@ -67,13 +68,15 @@ namespace Umbraco.Web.PublishedCache.NuCache
         public ContentStore(
             IPublishedSnapshotAccessor publishedSnapshotAccessor,
             IVariationContextAccessor variationContextAccessor,
-            ILogger logger,
+            ILogger<ContentStore> logger,
+            ILogger<Snapshot> snapShotLogger,
             IPublishedModelFactory publishedModelFactory,
             BPlusTree<int, ContentNodeKit> localDb = null)
         {
             _publishedSnapshotAccessor = publishedSnapshotAccessor;
             _variationContextAccessor = variationContextAccessor;
             _logger = logger;
+            _snapShotLogger = snapShotLogger;
             _publishedModelFactory = publishedModelFactory;
             _localDb = localDb;
 
@@ -253,7 +256,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                     catch (Exception ex)
                     {
                         /* TBD: May already be throwing so don't throw again */
-                        _logger.LogError<ContentStore>(ex, "Error trying to release DB");
+                        _logger.LogError(ex, "Error trying to release DB");
                     }
                     finally
                     {
@@ -264,7 +267,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             }
             catch (Exception ex)
             {
-                _logger.LogError<ContentStore>(ex, "Error trying to lock");
+                _logger.LogError(ex, "Error trying to lock");
                 throw;
             }
             finally
@@ -521,7 +524,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             parent = GetParentLink(kit.Node, null);
             if (parent == null)
             {
-                _logger.LogWarning<ContentStore>($"Skip item id={kit.Node.Id}, could not find parent id={kit.Node.ParentContentId}.");
+                _logger.LogWarning($"Skip item id={kit.Node.Id}, could not find parent id={kit.Node.ParentContentId}.");
                 return false;
             }
 
@@ -530,21 +533,21 @@ namespace Umbraco.Web.PublishedCache.NuCache
             // because the data sort operation is by path.
             if (parent.Value == null)
             {
-                _logger.LogWarning<ContentStore>($"Skip item id={kit.Node.Id}, no Data assigned for linked node with path {kit.Node.Path} and parent id {kit.Node.ParentContentId}. This can indicate data corruption for the Path value for node {kit.Node.Id}. See the Health Check dashboard in Settings to resolve data integrity issues.");
+                _logger.LogWarning($"Skip item id={kit.Node.Id}, no Data assigned for linked node with path {kit.Node.Path} and parent id {kit.Node.ParentContentId}. This can indicate data corruption for the Path value for node {kit.Node.Id}. See the Health Check dashboard in Settings to resolve data integrity issues.");
                 return false;
             }
 
             // make sure the kit is valid
             if (kit.DraftData == null && kit.PublishedData == null)
             {
-                _logger.LogWarning<ContentStore>($"Skip item id={kit.Node.Id}, both draft and published data are null.");
+                _logger.LogWarning($"Skip item id={kit.Node.Id}, both draft and published data are null.");
                 return false;
             }
 
             // unknown = bad
             if (_contentTypesById.TryGetValue(kit.ContentTypeId, out var link) == false || link.Value == null)
             {
-                _logger.LogWarning<ContentStore>($"Skip item id={kit.Node.Id}, could not find content type id={kit.ContentTypeId}.");
+                _logger.LogWarning($"Skip item id={kit.Node.Id}, could not find content type id={kit.ContentTypeId}.");
                 return false;
             }
 
@@ -601,7 +604,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 throw new ArgumentException("Kit content cannot have children.", nameof(kit));
             // ReSharper restore LocalizableElement
 
-            _logger.Debug<ContentStore>("Set content ID: {KitNodeId}", kit.Node.Id);
+            _logger.LogDebug("Set content ID: {KitNodeId}", kit.Node.Id);
 
             // get existing
             _contentNodes.TryGetValue(kit.Node.Id, out var link);
@@ -720,7 +723,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                     previousNode = null; // there is no previous sibling
                 }
 
-                _logger.Debug<ContentStore>($"Set {thisNode.Id} with parent {thisNode.ParentContentId}");
+                _logger.LogDebug($"Set {thisNode.Id} with parent {thisNode.ParentContentId}");
                 SetValueLocked(_contentNodes, thisNode.Id, thisNode);
 
                 // if we are initializing from the database source ensure the local db is updated
@@ -777,7 +780,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                     ok = false;
                     continue; // skip that one
                 }
-                _logger.Debug<ContentStore>($"Set {kit.Node.Id} with parent {kit.Node.ParentContentId}");
+                _logger.LogDebug($"Set {kit.Node.Id} with parent {kit.Node.ParentContentId}");
                 SetValueLocked(_contentNodes, kit.Node.Id, kit.Node);
 
                 if (_localDb != null) RegisterChange(kit.Node.Id, kit);
@@ -866,7 +869,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             if (link?.Value == null) return false;
 
             var content = link.Value;
-            _logger.Debug<ContentStore>("Clear content ID: {ContentId}", content.Id);
+            _logger.LogDebug("Clear content ID: {ContentId}", content.Id);
 
             // clear the entire branch
             ClearBranchLocked(content);
@@ -1308,7 +1311,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 if (_nextGen == false && _genObj != null)
                     return new Snapshot(this, _genObj.GetGenRef()
 #if DEBUG
-                        , _logger
+                        , _snapShotLogger
 #endif
                         );
 
@@ -1344,7 +1347,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
                 var snapshot = new Snapshot(this, _genObj.GetGenRef()
 #if DEBUG
-                    , _logger
+                    , _snapShotLogger
 #endif
                     );
 
@@ -1358,7 +1361,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
         public Snapshot LiveSnapshot => new Snapshot(this, _liveGen
 #if DEBUG
-            , _logger
+            , _snapShotLogger
 #endif
         );
 
@@ -1393,14 +1396,14 @@ namespace Umbraco.Web.PublishedCache.NuCache
         {
             // see notes in CreateSnapshot
 #if DEBUG
-            _logger.Debug<ContentStore>("Collect.");
+            _logger.LogDebug("Collect.");
 #endif
             while (_genObjs.TryPeek(out var genObj) && (genObj.Count == 0 || genObj.WeakGenRef.IsAlive == false))
             {
                 _genObjs.TryDequeue(out genObj); // cannot fail since TryPeek has succeeded
                 _floorGen = genObj.Gen;
 #if DEBUG
-                //_logger.Debug<ContentStore>("_floorGen=" + _floorGen + ", _liveGen=" + _liveGen);
+                //_logger.LogDebug("_floorGen=" + _floorGen + ", _liveGen=" + _liveGen);
 #endif
             }
 
@@ -1438,7 +1441,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 var link = kvp.Value;
 
 #if DEBUG
-                //_logger.Debug<ContentStore>("Collect id:" + kvp.Key + ", gen:" + link.Gen +
+                //_logger.LogDebug("Collect id:" + kvp.Key + ", gen:" + link.Gen +
                 //    ", nxt:" + (link.Next == null ? "null" : "link") +
                 //    ", val:" + (link.Value == null ? "null" : "value"));
 #endif
@@ -1546,7 +1549,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             private readonly GenRef _genRef;
             private long _gen;
 #if DEBUG
-            private readonly ILogger _logger;
+            private readonly ILogger<Snapshot> _logger;
 #endif
 
             //private static int _count;
@@ -1554,7 +1557,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
             internal Snapshot(ContentStore store, GenRef genRef
 #if DEBUG
-                    , ILogger logger
+                    , ILogger<Snapshot> logger
 #endif
                 )
             {
@@ -1566,13 +1569,13 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
 #if DEBUG
                 _logger = logger;
-                _logger.Debug<Snapshot>("Creating snapshot.");
+                _logger.LogDebug("Creating snapshot.");
 #endif
             }
 
             internal Snapshot(ContentStore store, long gen
 #if DEBUG
-                , ILogger logger
+                , ILogger<Snapshot> logger
 #endif
                 )
             {
@@ -1581,7 +1584,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
 #if DEBUG
                 _logger = logger;
-                _logger.Debug<Snapshot>("Creating live.");
+                _logger.LogDebug("Creating live.");
 #endif
             }
 
@@ -1669,7 +1672,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             {
                 if (_gen < 0) return;
 #if DEBUG
-                _logger.Debug<Snapshot>("Dispose snapshot ({Snapshot})", _genRef?.GenObj.Count.ToString() ?? "live");
+                _logger.LogDebug("Dispose snapshot ({Snapshot})", _genRef?.GenObj.Count.ToString() ?? "live");
 #endif
                 _gen = -1;
                 if (_genRef != null)

src/Umbraco.PublishedCache.NuCache/PublishedSnapshotService.cs

@@ -39,9 +39,11 @@ namespace Umbraco.Web.PublishedCache.NuCache
     {
         private readonly ServiceContext _serviceContext;
         private readonly IPublishedContentTypeFactory _publishedContentTypeFactory;
+        private readonly IProfilingLogger _profilingLogger;
         private readonly IScopeProvider _scopeProvider;
         private readonly IDataSource _dataSource;
-        private readonly IProfilingLogger _logger;
+        private readonly ILogger<PublishedSnapshotService> _logger;
+        private readonly ILogger<PublishedContentTypeCache> _publishedContentTypeCacheLogger;
         private readonly IDocumentRepository _documentRepository;
         private readonly IMediaRepository _mediaRepository;
         private readonly IMemberRepository _memberRepository;
@@ -81,7 +83,9 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
         public PublishedSnapshotService(PublishedSnapshotServiceOptions options, IMainDom mainDom, IRuntimeState runtime,
             ServiceContext serviceContext, IPublishedContentTypeFactory publishedContentTypeFactory,
-            IPublishedSnapshotAccessor publishedSnapshotAccessor, IVariationContextAccessor variationContextAccessor, IProfilingLogger logger, IScopeProvider scopeProvider,
+            IPublishedSnapshotAccessor publishedSnapshotAccessor, IVariationContextAccessor variationContextAccessor,
+            IProfilingLogger profilingLogger, ILogger<PublishedSnapshotService> logger, ILogger<ContentStore> contentLogger, ILogger<ContentStore.Snapshot> snapshotLogger, ILogger<PublishedContentTypeCache> publishedContentTypeCacheLogger,
+            IScopeProvider scopeProvider,
             IDocumentRepository documentRepository, IMediaRepository mediaRepository, IMemberRepository memberRepository,
             IDefaultCultureAccessor defaultCultureAccessor,
             IDataSource dataSource, IGlobalSettings globalSettings,
@@ -99,8 +103,10 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
             _serviceContext = serviceContext;
             _publishedContentTypeFactory = publishedContentTypeFactory;
+            _profilingLogger = profilingLogger;
             _dataSource = dataSource;
             _logger = logger;
+            _publishedContentTypeCacheLogger = publishedContentTypeCacheLogger;
             _scopeProvider = scopeProvider;
             _documentRepository = documentRepository;
             _mediaRepository = mediaRepository;
@@ -144,18 +150,18 @@ namespace Umbraco.Web.PublishedCache.NuCache
                     // stores are created with a db so they can write to it, but they do not read from it,
                     // stores need to be populated, happens in OnResolutionFrozen which uses _localDbExists to
                     // figure out whether it can read the databases or it should populate them from sql
-
-                    _logger.Info<PublishedSnapshotService>("Creating the content store, localContentDbExists? {LocalContentDbExists}", _localContentDbExists);
-                    _contentStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, logger,  publishedModelFactory, _localContentDb);
-                    _logger.Info<PublishedSnapshotService>("Creating the media store, localMediaDbExists? {LocalMediaDbExists}", _localMediaDbExists);
-                    _mediaStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, logger, publishedModelFactory, _localMediaDb);
+                    
+                    _logger.LogInformation("Creating the content store, localContentDbExists? {LocalContentDbExists}", _localContentDbExists);
+                    _contentStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, contentLogger, snapshotLogger,  publishedModelFactory, _localContentDb);
+                    _logger.LogInformation("Creating the media store, localMediaDbExists? {LocalMediaDbExists}", _localMediaDbExists);
+                    _mediaStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, contentLogger, snapshotLogger, publishedModelFactory, _localMediaDb);
                 }
                 else
                 {
-                    _logger.Info<PublishedSnapshotService>("Creating the content store (local db ignored)");
-                    _contentStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, logger, publishedModelFactory);
-                    _logger.Info<PublishedSnapshotService>("Creating the media store (local db ignored)");
-                    _mediaStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, logger, publishedModelFactory);
+                    _logger.LogInformation("Creating the content store (local db ignored)");
+                    _contentStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, contentLogger, snapshotLogger, publishedModelFactory);
+                    _logger.LogInformation("Creating the media store (local db ignored)");
+                    _mediaStore = new ContentStore(publishedSnapshotAccessor, variationContextAccessor, contentLogger, snapshotLogger, publishedModelFactory);
                 }
 
                 _domainStore = new SnapDictionary<int, Domain>();
@@ -201,7 +207,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             _localContentDb = BTree.GetTree(localContentDbPath, _localContentDbExists, _config);
             _localMediaDb = BTree.GetTree(localMediaDbPath, _localMediaDbExists, _config);
 
-            _logger.Info<PublishedSnapshotService>("Registered with MainDom, localContentDbExists? {LocalContentDbExists}, localMediaDbExists? {LocalMediaDbExists}", _localContentDbExists, _localMediaDbExists);
+            _logger.LogInformation("Registered with MainDom, localContentDbExists? {LocalContentDbExists}, localMediaDbExists? {LocalMediaDbExists}", _localContentDbExists, _localMediaDbExists);
         }
 
         /// <summary>
@@ -212,19 +218,19 @@ namespace Umbraco.Web.PublishedCache.NuCache
         /// </remarks>
         private void MainDomRelease()
         {
-            _logger.Debug<PublishedSnapshotService>("Releasing from MainDom...");
+            _logger.LogDebug("Releasing from MainDom...");
 
             lock (_storesLock)
             {
-                _logger.Debug<PublishedSnapshotService>("Releasing content store...");
+                _logger.LogDebug("Releasing content store...");
                 _contentStore?.ReleaseLocalDb(); //null check because we could shut down before being assigned
                 _localContentDb = null;
 
-                _logger.Debug<PublishedSnapshotService>("Releasing media store...");
+                _logger.LogDebug("Releasing media store...");
                 _mediaStore?.ReleaseLocalDb(); //null check because we could shut down before being assigned
                 _localMediaDb = null;
 
-                _logger.Info<PublishedSnapshotService>("Released from MainDom");
+                _logger.LogInformation("Released from MainDom");
             }
         }
 
@@ -243,14 +249,14 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 {
                     okContent = LockAndLoadContent(scope => LoadContentFromLocalDbLocked(true));
                     if (!okContent)
-                        _logger.LogWarning<PublishedSnapshotService>("Loading content from local db raised warnings, will reload from database.");
+                        _logger.LogWarning("Loading content from local db raised warnings, will reload from database.");
                 }
 
                 if (_localMediaDbExists)
                 {
                     okMedia = LockAndLoadMedia(scope => LoadMediaFromLocalDbLocked(true));
                     if (!okMedia)
-                        _logger.LogWarning<PublishedSnapshotService>("Loading media from local db raised warnings, will reload from database.");
+                        _logger.LogWarning("Loading media from local db raised warnings, will reload from database.");
                 }
 
                 if (!okContent)
@@ -263,7 +269,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             }
             catch (Exception ex)
             {
-                _logger.Fatal<PublishedSnapshotService>(ex, "Panic, exception while loading cache data.");
+                _logger.LogCritical(ex, "Panic, exception while loading cache data.");
                 throw;
             }
 
@@ -406,7 +412,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
             _contentStore.SetAllContentTypesLocked(contentTypes);
 
-            using (_logger.TraceDuration<PublishedSnapshotService>("Loading content from database"))
+            using (_profilingLogger.TraceDuration<PublishedSnapshotService>("Loading content from database"))
             {
                 // beware! at that point the cache is inconsistent,
                 // assuming we are going to SetAll content items!
@@ -425,7 +431,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                     .Select(x => _publishedContentTypeFactory.CreateContentType(x));
             _contentStore.SetAllContentTypesLocked(contentTypes);
 
-            using (_logger.TraceDuration<PublishedSnapshotService>("Loading content from local cache file"))
+            using (_profilingLogger.TraceDuration<PublishedSnapshotService>("Loading content from local cache file"))
             {
                 // beware! at that point the cache is inconsistent,
                 // assuming we are going to SetAll content items!
@@ -477,14 +483,14 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 .Select(x => _publishedContentTypeFactory.CreateContentType(x));
             _mediaStore.SetAllContentTypesLocked(mediaTypes);
 
-            using (_logger.TraceDuration<PublishedSnapshotService>("Loading media from database"))
+            using (_profilingLogger.TraceDuration<PublishedSnapshotService>("Loading media from database"))
             {
                 // beware! at that point the cache is inconsistent,
                 // assuming we are going to SetAll content items!
 
                 _localMediaDb?.Clear();
 
-                _logger.Debug<PublishedSnapshotService>("Loading media from database...");
+                _logger.LogDebug("Loading media from database...");
                 // IMPORTANT GetAllMediaSources sorts kits by level + parentId + sortOrder
                 var kits = _dataSource.GetAllMediaSources(scope);
                 return onStartup ? _mediaStore.SetAllFastSortedLocked(kits, true) : _mediaStore.SetAllLocked(kits);
@@ -497,7 +503,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                     .Select(x => _publishedContentTypeFactory.CreateContentType(x));
             _mediaStore.SetAllContentTypesLocked(mediaTypes);
 
-            using (_logger.TraceDuration<PublishedSnapshotService>("Loading media from local cache file"))
+            using (_profilingLogger.TraceDuration<PublishedSnapshotService>("Loading media from local cache file"))
             {
                 // beware! at that point the cache is inconsistent,
                 // assuming we are going to SetAll content items!
@@ -532,7 +538,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 // Update: We will still return false here even though the above mentioned race condition has been fixed since we now
                 // lock the entire operation of creating/populating the cache file with the same lock as releasing/closing the cache file
 
-                _logger.Info<PublishedSnapshotService>($"Tried to load {entityType} from the local cache file but it was empty.");
+                _logger.LogInformation($"Tried to load {entityType} from the local cache file but it was empty.");
                 return false;
             }
 
@@ -709,7 +715,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
             foreach (var payload in payloads)
             {
-                _logger.Debug<PublishedSnapshotService>("Notified {ChangeTypes} for content {ContentId}", payload.ChangeTypes, payload.Id);
+                _logger.LogDebug("Notified {ChangeTypes} for content {ContentId}", payload.ChangeTypes, payload.Id);
 
                 if (payload.ChangeTypes.HasType(TreeChangeTypes.RefreshAll))
                 {
@@ -802,7 +808,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
             foreach (var payload in payloads)
             {
-                _logger.Debug<PublishedSnapshotService>("Notified {ChangeTypes} for media {MediaId}", payload.ChangeTypes, payload.Id);
+                _logger.LogDebug("Notified {ChangeTypes} for media {MediaId}", payload.ChangeTypes, payload.Id);
 
                 if (payload.ChangeTypes.HasType(TreeChangeTypes.RefreshAll))
                 {
@@ -873,7 +879,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
                 return;
 
             foreach (var payload in payloads)
-                _logger.Debug<PublishedSnapshotService>("Notified {ChangeTypes} for {ItemType} {ItemId}", payload.ChangeTypes, payload.ItemType, payload.Id);
+                _logger.LogDebug("Notified {ChangeTypes} for {ItemType} {ItemId}", payload.ChangeTypes, payload.ItemType, payload.Id);
 
             Notify<IContentType>(_contentStore, payloads, RefreshContentTypesLocked);
             Notify<IMediaType>(_mediaStore, payloads, RefreshMediaTypesLocked);
@@ -957,7 +963,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
             var idsA = payloads.Select(x => x.Id).ToArray();
 
             foreach (var payload in payloads)
-                _logger.Debug<PublishedSnapshotService>("Notified {RemovedStatus} for data type {DataTypeId}",
+                _logger.LogDebug("Notified {RemovedStatus} for data type {DataTypeId}",
                     payload.Removed ? "Removed" : "Refreshed",
                     payload.Id);
 
@@ -1229,7 +1235,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
             var snapshotCache = new DictionaryAppCache();
 
-            var memberTypeCache = new PublishedContentTypeCache(null, null, _serviceContext.MemberTypeService, _publishedContentTypeFactory, _logger);
+            var memberTypeCache = new PublishedContentTypeCache(null, null, _serviceContext.MemberTypeService, _publishedContentTypeFactory, _publishedContentTypeCacheLogger);
 
             var defaultCulture = _defaultCultureAccessor.DefaultCulture;
             var domainCache = new DomainCache(domainSnap, defaultCulture);
@@ -1490,7 +1496,7 @@ namespace Umbraco.Web.PublishedCache.NuCache
 
         public override void Rebuild()
         {
-            _logger.Debug<PublishedSnapshotService>("Rebuilding...");
+            _logger.LogDebug("Rebuilding...");
             using (var scope = _scopeProvider.CreateScope(repositoryCacheMode: RepositoryCacheMode.Scoped))
             {
                 scope.ReadLock(Constants.Locks.ContentTree);