Merge pull request #2935 from umbraco/temp8-MOAR-LOGGING

MOAR Logging for V8

src/Umbraco.Core/Logging/DisposableTimer.cs

@@ -84,15 +84,15 @@ protected override void DisposeResources()
             {
                 if (_failed)
                 {
-                    _logger.Error(_loggerType, _failException, "[Timing {TimingId}] {FailMessage} ({TimingDuration}ms)", _timingId, _failMessage, Stopwatch.ElapsedMilliseconds);
+                    _logger.Error(_loggerType, _failException, "[Timing {TimingId}] {FailMessage} ({Duration}ms)", _timingId, _failMessage, Stopwatch.ElapsedMilliseconds);
                 }
                 else switch (_level)
                 {
                     case LogLevel.Debug:
-                        _logger.Debug(_loggerType, "[Timing {TimingId}] {EndMessage} ({TimingDuration}ms)", _timingId, _endMessage, Stopwatch.ElapsedMilliseconds);
+                        _logger.Debug(_loggerType, "[Timing {TimingId}] {EndMessage} ({Duration}ms)", _timingId, _endMessage, Stopwatch.ElapsedMilliseconds);
                         break;
                     case LogLevel.Information:
-                        _logger.Info(_loggerType, "[Timing {TimingId}] {EndMessage} ({TimingDuration}ms)", _timingId, _endMessage, Stopwatch.ElapsedMilliseconds);
+                        _logger.Info(_loggerType, "[Timing {TimingId}] {EndMessage} ({Duration}ms)", _timingId, _endMessage, Stopwatch.ElapsedMilliseconds);
                         break;
                     // filtered in the ctor
                     //default:

src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestIdEnricher.cs

@@ -0,0 +1,61 @@
+using System;
+using System.Web;
+using Serilog.Core;
+using Serilog.Events;
+
+namespace Umbraco.Core.Logging.Serilog.Enrichers
+{
+    /// <summary>
+    /// Enrich log events with a HttpRequestId GUID.
+    /// Original source - https://github.com/serilog-web/classic/blob/master/src/SerilogWeb.Classic/Classic/Enrichers/HttpRequestIdEnricher.cs
+    /// Nupkg: 'Serilog.Web.Classic' contains handlers & extra bits we do not want
+    /// </summary>
+    internal class HttpRequestIdEnricher : ILogEventEnricher
+    {
+        /// <summary>
+        /// The property name added to enriched log events.
+        /// </summary>
+        public const string HttpRequestIdPropertyName = "HttpRequestId";
+
+        static readonly string RequestIdItemName = typeof(HttpRequestIdEnricher).Name + "+RequestId";
+
+        /// <summary>
+        /// Enrich the log event with an id assigned to the currently-executing HTTP request, if any.
+        /// </summary>
+        /// <param name="logEvent">The log event to enrich.</param>
+        /// <param name="propertyFactory">Factory for creating new properties to add to the event.</param>
+        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+        {
+            if (logEvent == null) throw new ArgumentNullException("logEvent");
+
+            Guid requestId;
+            if (!TryGetCurrentHttpRequestId(out requestId))
+                return;
+
+            var requestIdProperty = new LogEventProperty(HttpRequestIdPropertyName, new ScalarValue(requestId));
+            logEvent.AddPropertyIfAbsent(requestIdProperty);
+        }
+
+        /// <summary>
+        /// Retrieve the id assigned to the currently-executing HTTP request, if any.
+        /// </summary>
+        /// <param name="requestId">The request id.</param>
+        /// <returns><c>true</c> if there is a request in progress; <c>false</c> otherwise.</returns>
+        public static bool TryGetCurrentHttpRequestId(out Guid requestId)
+        {
+            if (HttpContext.Current == null)
+            {
+                requestId = default(Guid);
+                return false;
+            }
+
+            var requestIdItem = HttpContext.Current.Items[RequestIdItemName];
+            if (requestIdItem == null)
+                HttpContext.Current.Items[RequestIdItemName] = requestId = Guid.NewGuid();
+            else
+                requestId = (Guid)requestIdItem;
+
+            return true;
+        }
+    }
+}

src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestNumberEnricher.cs

@@ -0,0 +1,48 @@
+using System;
+using System.Threading;
+using System.Web;
+using Serilog.Core;
+using Serilog.Events;
+
+namespace Umbraco.Core.Logging.Serilog.Enrichers
+{
+    /// <summary>
+    /// Enrich log events with a HttpRequestNumber unique within the current
+    /// logging session.
+    /// Original source - https://github.com/serilog-web/classic/blob/master/src/SerilogWeb.Classic/Classic/Enrichers/HttpRequestNumberEnricher.cs
+    /// Nupkg: 'Serilog.Web.Classic' contains handlers & extra bits we do not want
+    /// </summary>
+    internal class HttpRequestNumberEnricher : ILogEventEnricher
+    {
+        /// <summary>
+        /// The property name added to enriched log events.
+        /// </summary>
+        public const string HttpRequestNumberPropertyName = "HttpRequestNumber";
+
+        static int _lastRequestNumber;
+        static readonly string RequestNumberItemName = typeof(HttpRequestNumberEnricher).Name + "+RequestNumber";
+
+        /// <summary>
+        /// Enrich the log event with the number assigned to the currently-executing HTTP request, if any.
+        /// </summary>
+        /// <param name="logEvent">The log event to enrich.</param>
+        /// <param name="propertyFactory">Factory for creating new properties to add to the event.</param>
+        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+        {
+            if (logEvent == null) throw new ArgumentNullException("logEvent");
+
+            if (HttpContext.Current == null)
+                return;
+
+            int requestNumber;
+            var requestNumberItem = HttpContext.Current.Items[RequestNumberItemName];
+            if (requestNumberItem == null)
+                HttpContext.Current.Items[RequestNumberItemName] = requestNumber = Interlocked.Increment(ref _lastRequestNumber);
+            else
+                requestNumber = (int)requestNumberItem;
+
+            var requestNumberProperty = new LogEventProperty(HttpRequestNumberPropertyName, new ScalarValue(requestNumber));
+            logEvent.AddPropertyIfAbsent(requestNumberProperty);
+        }
+    }
+}

src/Umbraco.Core/Logging/Serilog/Enrichers/HttpSessionIdEnricher.cs

@@ -0,0 +1,39 @@
+using Serilog.Core;
+using Serilog.Events;
+using System;
+using System.Web;
+
+namespace Umbraco.Core.Logging.Serilog.Enrichers
+{
+    /// <summary>
+    /// Enrich log events with the HttpSessionId property.
+    /// Original source - https://github.com/serilog-web/classic/blob/master/src/SerilogWeb.Classic/Classic/Enrichers/HttpSessionIdEnricher.cs
+    /// Nupkg: 'Serilog.Web.Classic' contains handlers & extra bits we do not want
+    /// </summary>
+    internal class HttpSessionIdEnricher : ILogEventEnricher
+    {
+        /// <summary>
+        /// The property name added to enriched log events.
+        /// </summary>
+        public const string HttpSessionIdPropertyName = "HttpSessionId";
+
+        /// <summary>
+        /// Enrich the log event with the current ASP.NET session id, if sessions are enabled.</summary>
+        /// <param name="logEvent">The log event to enrich.</param>
+        /// <param name="propertyFactory">Factory for creating new properties to add to the event.</param>
+        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+        {
+            if (logEvent == null) throw new ArgumentNullException("logEvent");
+
+            if (HttpContext.Current == null)
+                return;
+
+            if (HttpContext.Current.Session == null)
+                return;
+
+            var sessionId = HttpContext.Current.Session.SessionID;
+            var sessionIdProperty = new LogEventProperty(HttpSessionIdPropertyName, new ScalarValue(sessionId));
+            logEvent.AddPropertyIfAbsent(sessionIdProperty);
+        }
+    }
+}

src/Umbraco.Core/Logging/Serilog/Log4NetLevelMapperEnricher.cs → src/Umbraco.Core/Logging/Serilog/Enrichers/Log4NetLevelMapperEnricher.cs

@@ -1,7 +1,7 @@
 using Serilog.Core;
 using Serilog.Events;
 
-namespace Umbraco.Core.Logging.Serilog
+namespace Umbraco.Core.Logging.Serilog.Enrichers
 {
     /// <summary>
     /// This is used to create a new property in Logs called 'Log4NetLevel'

src/Umbraco.Core/Logging/Serilog/LoggerConfigExtensions.cs

@@ -3,6 +3,7 @@
 using Serilog;
 using Serilog.Events;
 using Serilog.Formatting.Compact;
+using Umbraco.Core.Logging.Serilog.Enrichers;
 
 namespace Umbraco.Core.Logging.Serilog
 {
@@ -21,16 +22,19 @@ public static LoggerConfiguration MinimalConfiguration(this LoggerConfiguration
             //Set this environment variable - so that it can be used in external config file
             //add key="serilog:write-to:RollingFile.pathFormat" value="%BASEDIR%\logs\log.txt" />
             Environment.SetEnvironmentVariable("BASEDIR", AppDomain.CurrentDomain.BaseDirectory, EnvironmentVariableTarget.Process);
-            
+
             logConfig.MinimumLevel.Verbose() //Set to highest level of logging (as any sinks may want to restrict it to Errors only)
                 .Enrich.WithProcessId()
                 .Enrich.WithProcessName()
                 .Enrich.WithThreadId()
                 .Enrich.WithProperty("AppDomainId", AppDomain.CurrentDomain.Id)
                 .Enrich.WithProperty("AppDomainAppId", HttpRuntime.AppDomainAppId.ReplaceNonAlphanumericChars(string.Empty))
                 .Enrich.WithProperty("MachineName", Environment.MachineName)
-                .Enrich.With<Log4NetLevelMapperEnricher>();
-
+                .Enrich.With<Log4NetLevelMapperEnricher>()
+                .Enrich.With<HttpSessionIdEnricher>()
+                .Enrich.With<HttpRequestNumberEnricher>()
+                .Enrich.With<HttpRequestIdEnricher>();
+
             return logConfig;
         }
 

src/Umbraco.Core/Runtime/CoreRuntime.cs

@@ -363,7 +363,7 @@ protected virtual bool EnsureUmbracoUpgradeState(IUmbracoDatabaseFactory databas
             _state.CurrentMigrationState = state;
             _state.FinalMigrationState = umbracoPlan.FinalState;
 
-            logger.Debug<CoreRuntime>("Final upgrade state is '{FinalMigrationState}', database contains {DatabaseState}", _state.FinalMigrationState, state ?? "<null>");
+            logger.Debug<CoreRuntime>("Final upgrade state is {FinalMigrationState}, database contains {DatabaseState}", _state.FinalMigrationState, state ?? "<null>");
 
             return state == _state.FinalMigrationState;
         }

src/Umbraco.Core/RuntimeState.cs

@@ -117,7 +117,7 @@ internal void EnsureApplicationUrl(HttpRequestBase request = null)
             var change = url != null && !_applicationUrls.Contains(url);
             if (change)
             {
-                _logger.Info(typeof(ApplicationUrlHelper), "New url '{Url}' detected, re-discovering application url.", url);
+                _logger.Info(typeof(ApplicationUrlHelper), "New url {Url} detected, re-discovering application url.", url);
                 _applicationUrls.Add(url);
             }
 

src/Umbraco.Core/Services/Implement/ContentService.cs

@@ -2178,31 +2178,31 @@ internal PublishResult StrategyCanPublish(IScope scope, IContent content, int us
             // raise Publishing event
             if (scope.Events.DispatchCancelable(Publishing, this, new PublishEventArgs<IContent>(content, evtMsgs)))
             {
-                Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "publishing was cancelled");
+                Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "publishing was cancelled");
                 return new PublishResult(PublishResultType.FailedCancelledByEvent, evtMsgs, content);
             }
 
             // ensure that the document has published values
             // either because it is 'publishing' or because it already has a published version
             if (((Content) content).PublishedState != PublishedState.Publishing && content.PublishedVersionId == 0)
             {
-                Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document does not have published values");
+                Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document does not have published values");
                 return new PublishResult(PublishResultType.FailedNoPublishedValues, evtMsgs, content);
             }
 
             // ensure that the document status is correct
             switch (content.Status)
             {
                 case ContentStatus.Expired:
-                    Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document has expired");
+                    Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document has expired");
                     return new PublishResult(PublishResultType.FailedHasExpired, evtMsgs, content);
 
                 case ContentStatus.AwaitingRelease:
-                    Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document is awaiting release");
+                    Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document is awaiting release");
                     return new PublishResult(PublishResultType.FailedAwaitingRelease, evtMsgs, content);
 
                 case ContentStatus.Trashed:
-                    Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document is trashed");
+                    Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document is trashed");
                     return new PublishResult(PublishResultType.FailedIsTrashed, evtMsgs, content);
             }
 
@@ -2214,7 +2214,7 @@ internal PublishResult StrategyCanPublish(IScope scope, IContent content, int us
             var pathIsOk = content.ParentId == Constants.System.Root || IsPathPublished(GetParent(content));
             if (pathIsOk == false)
             {
-                Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "parent is not published");
+                Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "parent is not published");
                 return new PublishResult(PublishResultType.FailedPathNotPublished, evtMsgs, content);
             }
 
@@ -2238,7 +2238,7 @@ internal PublishResult StrategyPublish(IScope scope, IContent content, bool canP
             // change state to publishing
             ((Content) content).PublishedState = PublishedState.Publishing;
 
-            Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) has been published.", content.Name, content.Id);
+            Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) has been published.", content.Name, content.Id);
             return result;
         }
 
@@ -2248,7 +2248,7 @@ internal UnpublishResult StrategyCanUnpublish(IScope scope, IContent content, in
             // raise UnPublishing event
             if (scope.Events.DispatchCancelable(UnPublishing, this, new PublishEventArgs<IContent>(content, evtMsgs)))
             {
-                Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) cannot be unpublished: unpublishing was cancelled.", content.Name, content.Id);
+                Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) cannot be unpublished: unpublishing was cancelled.", content.Name, content.Id);
                 return new UnpublishResult(UnpublishResultType.FailedCancelledByEvent, evtMsgs, content);
             }
 
@@ -2271,13 +2271,13 @@ internal UnpublishResult StrategyUnpublish(IScope scope, IContent content, bool
             if (content.ReleaseDate.HasValue && content.ReleaseDate.Value <= DateTime.Now)
             {
                 content.ReleaseDate = null;
-                Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) had its release date removed, because it was unpublished.", content.Name, content.Id);
+                Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) had its release date removed, because it was unpublished.", content.Name, content.Id);
             }
 
             // change state to unpublishing
             ((Content) content).PublishedState = PublishedState.Unpublishing;
 
-            Logger.Info<ContentService>("Document '{ContentName}' (id={ContentId}) has been unpublished.", content.Name, content.Id);
+            Logger.Info<ContentService>("Document {ContentName} (id={ContentId}) has been unpublished.", content.Name, content.Id);
             return attempt;
         }
 

src/Umbraco.Core/Umbraco.Core.csproj

@@ -328,8 +328,11 @@
     <Compile Include="KeyValuePairExtensions.cs" />
     <Compile Include="Logging\LogLevel.cs" />
     <Compile Include="Logging\MessageTemplates.cs" />
+    <Compile Include="Logging\Serilog\Enrichers\HttpRequestIdEnricher.cs" />
+    <Compile Include="Logging\Serilog\Enrichers\HttpRequestNumberEnricher.cs" />
+    <Compile Include="Logging\Serilog\Enrichers\HttpSessionIdEnricher.cs" />
     <Compile Include="Logging\Serilog\LoggerConfigExtensions.cs" />
-    <Compile Include="Logging\Serilog\Log4NetLevelMapperEnricher.cs" />
+    <Compile Include="Logging\Serilog\Enrichers\Log4NetLevelMapperEnricher.cs" />
     <Compile Include="Migrations\MigrationBase_Extra.cs" />
     <Compile Include="Migrations\Upgrade\V_7_10_0\RenamePreviewFolder.cs" />
     <Compile Include="Migrations\Upgrade\V_7_12_0\AddRelationTypeForMediaFolderOnDelete.cs" />

src/Umbraco.Web/PublishedCache/NuCache/PublishedSnapshotService.cs

@@ -303,7 +303,7 @@ private void LoadContentFromDatabaseLocked(IScope scope)
             var kits = _dataSource.GetAllContentSources(scope);
             _contentStore.SetAll(kits);
             sw.Stop();
-            _logger.Debug<PublishedSnapshotService>("Loaded content from database ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds);
+            _logger.Debug<PublishedSnapshotService>("Loaded content from database ({Duration}ms)", sw.ElapsedMilliseconds);
         }
 
         private void LoadContentFromLocalDbLocked(IScope scope)
@@ -317,7 +317,7 @@ private void LoadContentFromLocalDbLocked(IScope scope)
             var kits = _localContentDb.Select(x => x.Value).OrderBy(x => x.Node.Level);
             _contentStore.SetAll(kits);
             sw.Stop();
-            _logger.Debug<PublishedSnapshotService>("Loaded content from local db ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds);
+            _logger.Debug<PublishedSnapshotService>("Loaded content from local db ({Duration}ms)", sw.ElapsedMilliseconds);
         }
 
         // keep these around - might be useful
@@ -370,7 +370,7 @@ private void LoadMediaFromDatabaseLocked(IScope scope)
             var kits = _dataSource.GetAllMediaSources(scope);
             _mediaStore.SetAll(kits);
             sw.Stop();
-            _logger.Debug<PublishedSnapshotService>("Loaded media from database ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds);
+            _logger.Debug<PublishedSnapshotService>("Loaded media from database ({Duration}ms)", sw.ElapsedMilliseconds);
         }
 
         private void LoadMediaFromLocalDbLocked(IScope scope)
@@ -384,7 +384,7 @@ private void LoadMediaFromLocalDbLocked(IScope scope)
             var kits = _localMediaDb.Select(x => x.Value);
             _mediaStore.SetAll(kits);
             sw.Stop();
-            _logger.Debug<PublishedSnapshotService>("Loaded media from local db ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds);
+            _logger.Debug<PublishedSnapshotService>("Loaded media from local db ({Duration}ms)", sw.ElapsedMilliseconds);
         }
 
         // keep these around - might be useful