From 64e148f9945f4da97518c99dd172378e87541c71 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 6 Sep 2018 20:18:33 +0100 Subject: [PATCH 01/12] Update UmbracoModule to only log the end of the request & its time - not sure how useful a log for start & end request IMO (Stephan may think otherwise) --- src/Umbraco.Web/UmbracoModule.cs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/Umbraco.Web/UmbracoModule.cs b/src/Umbraco.Web/UmbracoModule.cs index 2094781ee0..126c713236 100644 --- a/src/Umbraco.Web/UmbracoModule.cs +++ b/src/Umbraco.Web/UmbracoModule.cs @@ -561,7 +561,6 @@ namespace Umbraco.Web //Create a new Request ID/GUID requestId = Guid.NewGuid(); - Logger.Verbose("Begin request [{RequestId}]: {RequestUrl}", requestId, httpContext.Request.Url); BeginRequest(new HttpContextWrapper(httpContext)); }; @@ -605,8 +604,7 @@ namespace Umbraco.Web if (UmbracoContext.Current != null) { Logger.Verbose( - "End Request [{RequestId}]: {RequestUrl} ({RequestTotalMilliseconds}ms)", - requestId, + "Request: {RequestUrl} ({RequestTotalMilliseconds}ms)", httpContext.Request.Url, DateTime.Now.Subtract(UmbracoContext.Current.ObjectCreated).TotalMilliseconds); } From cd20348be5bf5a93b727ca22ef931c2090c32094 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 6 Sep 2018 20:19:32 +0100 Subject: [PATCH 02/12] Move Log4NetLevelMapper enricher into seperate folder - as we plan to add more --- .../Serilog/{ => Enrichers}/Log4NetLevelMapperEnricher.cs | 2 +- src/Umbraco.Core/Umbraco.Core.csproj | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) rename src/Umbraco.Core/Logging/Serilog/{ => Enrichers}/Log4NetLevelMapperEnricher.cs (96%) diff --git a/src/Umbraco.Core/Logging/Serilog/Log4NetLevelMapperEnricher.cs b/src/Umbraco.Core/Logging/Serilog/Enrichers/Log4NetLevelMapperEnricher.cs similarity index 96% rename from src/Umbraco.Core/Logging/Serilog/Log4NetLevelMapperEnricher.cs rename to src/Umbraco.Core/Logging/Serilog/Enrichers/Log4NetLevelMapperEnricher.cs index 1424fa0b55..0c255fa8b4 100644 --- a/src/Umbraco.Core/Logging/Serilog/Log4NetLevelMapperEnricher.cs +++ b/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 { /// /// This is used to create a new property in Logs called 'Log4NetLevel' diff --git a/src/Umbraco.Core/Umbraco.Core.csproj b/src/Umbraco.Core/Umbraco.Core.csproj index f584621fc0..4177cfbd99 100644 --- a/src/Umbraco.Core/Umbraco.Core.csproj +++ b/src/Umbraco.Core/Umbraco.Core.csproj @@ -329,7 +329,7 @@ - + From d27b4cce09c5b8d93593fdfc64261a7c2ca013ac Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 6 Sep 2018 20:20:24 +0100 Subject: [PATCH 03/12] Adds a few most useful enrichers from the Serilog.Classic.Web project (we dont want all thex extra bloat such as handlers etc) --- .../Enrichers/HttpRequestIdEnricher.cs | 61 +++++++++++++++++++ .../Enrichers/HttpRequestNumberEnricher.cs | 48 +++++++++++++++ .../Enrichers/HttpSessionIdEnricher.cs | 39 ++++++++++++ src/Umbraco.Core/Umbraco.Core.csproj | 3 + 4 files changed, 151 insertions(+) create mode 100644 src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestIdEnricher.cs create mode 100644 src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestNumberEnricher.cs create mode 100644 src/Umbraco.Core/Logging/Serilog/Enrichers/HttpSessionIdEnricher.cs diff --git a/src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestIdEnricher.cs b/src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestIdEnricher.cs new file mode 100644 index 0000000000..856b50bce5 --- /dev/null +++ b/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 +{ + /// + /// 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 + /// + internal class HttpRequestIdEnricher : ILogEventEnricher + { + /// + /// The property name added to enriched log events. + /// + public const string HttpRequestIdPropertyName = "HttpRequestId"; + + static readonly string RequestIdItemName = typeof(HttpRequestIdEnricher).Name + "+RequestId"; + + /// + /// Enrich the log event with an id assigned to the currently-executing HTTP request, if any. + /// + /// The log event to enrich. + /// Factory for creating new properties to add to the event. + 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); + } + + /// + /// Retrieve the id assigned to the currently-executing HTTP request, if any. + /// + /// The request id. + /// true if there is a request in progress; false otherwise. + 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; + } + } +} diff --git a/src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestNumberEnricher.cs b/src/Umbraco.Core/Logging/Serilog/Enrichers/HttpRequestNumberEnricher.cs new file mode 100644 index 0000000000..48415cccbc --- /dev/null +++ b/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 +{ + /// + /// 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 + /// + internal class HttpRequestNumberEnricher : ILogEventEnricher + { + /// + /// The property name added to enriched log events. + /// + public const string HttpRequestNumberPropertyName = "HttpRequestNumber"; + + static int _lastRequestNumber; + static readonly string RequestNumberItemName = typeof(HttpRequestNumberEnricher).Name + "+RequestNumber"; + + /// + /// Enrich the log event with the number assigned to the currently-executing HTTP request, if any. + /// + /// The log event to enrich. + /// Factory for creating new properties to add to the event. + 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); + } + } +} diff --git a/src/Umbraco.Core/Logging/Serilog/Enrichers/HttpSessionIdEnricher.cs b/src/Umbraco.Core/Logging/Serilog/Enrichers/HttpSessionIdEnricher.cs new file mode 100644 index 0000000000..d2fbfd4627 --- /dev/null +++ b/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 +{ + /// + /// 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 + /// + internal class HttpSessionIdEnricher : ILogEventEnricher + { + /// + /// The property name added to enriched log events. + /// + public const string HttpSessionIdPropertyName = "HttpSessionId"; + + /// + /// Enrich the log event with the current ASP.NET session id, if sessions are enabled. + /// The log event to enrich. + /// Factory for creating new properties to add to the event. + 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); + } + } +} diff --git a/src/Umbraco.Core/Umbraco.Core.csproj b/src/Umbraco.Core/Umbraco.Core.csproj index 4177cfbd99..b747b0960f 100644 --- a/src/Umbraco.Core/Umbraco.Core.csproj +++ b/src/Umbraco.Core/Umbraco.Core.csproj @@ -328,6 +328,9 @@ + + + From a825dd1b92c147e380ec7752fa40552bbe730c14 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 6 Sep 2018 20:35:02 +0100 Subject: [PATCH 04/12] Configures the default logging pipeline to use the new enrichers --- .../Logging/Serilog/LoggerConfigExtensions.cs | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/Umbraco.Core/Logging/Serilog/LoggerConfigExtensions.cs b/src/Umbraco.Core/Logging/Serilog/LoggerConfigExtensions.cs index 8861c808df..2d333ed916 100644 --- a/src/Umbraco.Core/Logging/Serilog/LoggerConfigExtensions.cs +++ b/src/Umbraco.Core/Logging/Serilog/LoggerConfigExtensions.cs @@ -3,6 +3,7 @@ using System.Web; using Serilog; using Serilog.Events; using Serilog.Formatting.Compact; +using Umbraco.Core.Logging.Serilog.Enrichers; namespace Umbraco.Core.Logging.Serilog { @@ -21,7 +22,7 @@ namespace Umbraco.Core.Logging.Serilog //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() @@ -29,8 +30,11 @@ namespace Umbraco.Core.Logging.Serilog .Enrich.WithProperty("AppDomainId", AppDomain.CurrentDomain.Id) .Enrich.WithProperty("AppDomainAppId", HttpRuntime.AppDomainAppId.ReplaceNonAlphanumericChars(string.Empty)) .Enrich.WithProperty("MachineName", Environment.MachineName) - .Enrich.With(); - + .Enrich.With() + .Enrich.With() + .Enrich.With() + .Enrich.With(); + return logConfig; } From 4184b277aa4314b717b396ae22f255076e6ab921 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 6 Sep 2018 20:38:03 +0100 Subject: [PATCH 05/12] Reduce the number of different properties, for the timing based logs for the duration in milliseconds to be consistently called 'Duration' --- src/Umbraco.Core/Logging/DisposableTimer.cs | 6 +++--- .../PublishedCache/NuCache/PublishedSnapshotService.cs | 8 ++++---- src/Umbraco.Web/Templates/TemplateUtilities.cs | 2 +- src/Umbraco.Web/UmbracoModule.cs | 2 +- 4 files changed, 9 insertions(+), 9 deletions(-) diff --git a/src/Umbraco.Core/Logging/DisposableTimer.cs b/src/Umbraco.Core/Logging/DisposableTimer.cs index db530e5339..e0e6227159 100644 --- a/src/Umbraco.Core/Logging/DisposableTimer.cs +++ b/src/Umbraco.Core/Logging/DisposableTimer.cs @@ -84,15 +84,15 @@ namespace Umbraco.Core.Logging { 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: diff --git a/src/Umbraco.Web/PublishedCache/NuCache/PublishedSnapshotService.cs b/src/Umbraco.Web/PublishedCache/NuCache/PublishedSnapshotService.cs index 5bcb2f70d4..a39f034a39 100644 --- a/src/Umbraco.Web/PublishedCache/NuCache/PublishedSnapshotService.cs +++ b/src/Umbraco.Web/PublishedCache/NuCache/PublishedSnapshotService.cs @@ -303,7 +303,7 @@ namespace Umbraco.Web.PublishedCache.NuCache var kits = _dataSource.GetAllContentSources(scope); _contentStore.SetAll(kits); sw.Stop(); - _logger.Debug("Loaded content from database ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds); + _logger.Debug("Loaded content from database ({Duration}ms)", sw.ElapsedMilliseconds); } private void LoadContentFromLocalDbLocked(IScope scope) @@ -317,7 +317,7 @@ namespace Umbraco.Web.PublishedCache.NuCache var kits = _localContentDb.Select(x => x.Value).OrderBy(x => x.Node.Level); _contentStore.SetAll(kits); sw.Stop(); - _logger.Debug("Loaded content from local db ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds); + _logger.Debug("Loaded content from local db ({Duration}ms)", sw.ElapsedMilliseconds); } // keep these around - might be useful @@ -370,7 +370,7 @@ namespace Umbraco.Web.PublishedCache.NuCache var kits = _dataSource.GetAllMediaSources(scope); _mediaStore.SetAll(kits); sw.Stop(); - _logger.Debug("Loaded media from database ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds); + _logger.Debug("Loaded media from database ({Duration}ms)", sw.ElapsedMilliseconds); } private void LoadMediaFromLocalDbLocked(IScope scope) @@ -384,7 +384,7 @@ namespace Umbraco.Web.PublishedCache.NuCache var kits = _localMediaDb.Select(x => x.Value); _mediaStore.SetAll(kits); sw.Stop(); - _logger.Debug("Loaded media from local db ({ElapsedMilliseconds}ms)", sw.ElapsedMilliseconds); + _logger.Debug("Loaded media from local db ({Duration}ms)", sw.ElapsedMilliseconds); } // keep these around - might be useful diff --git a/src/Umbraco.Web/Templates/TemplateUtilities.cs b/src/Umbraco.Web/Templates/TemplateUtilities.cs index 782878b5c0..4ad14cb7ca 100644 --- a/src/Umbraco.Web/Templates/TemplateUtilities.cs +++ b/src/Umbraco.Web/Templates/TemplateUtilities.cs @@ -100,7 +100,7 @@ namespace Umbraco.Web.Templates { // find all relative urls (ie. urls that contain ~) var tags = ResolveUrlPattern.Matches(text); - Current.Logger.Debug(typeof(IOHelper), "After regex: {ElapsedMilliseconds} matched: {TagsCount}", timer.Stopwatch.ElapsedMilliseconds, tags.Count); + Current.Logger.Debug(typeof(IOHelper), "After regex: {Duration} matched: {TagsCount}", timer.Stopwatch.ElapsedMilliseconds, tags.Count); foreach (Match tag in tags) { var url = ""; diff --git a/src/Umbraco.Web/UmbracoModule.cs b/src/Umbraco.Web/UmbracoModule.cs index 126c713236..b79a697e39 100644 --- a/src/Umbraco.Web/UmbracoModule.cs +++ b/src/Umbraco.Web/UmbracoModule.cs @@ -604,7 +604,7 @@ namespace Umbraco.Web if (UmbracoContext.Current != null) { Logger.Verbose( - "Request: {RequestUrl} ({RequestTotalMilliseconds}ms)", + "Request: {RequestUrl} took {Duration}ms", httpContext.Request.Url, DateTime.Now.Subtract(UmbracoContext.Current.ObjectCreated).TotalMilliseconds); } From e86b7a59828b7ecc35f3f5c506b762d302ae4e8d Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Mon, 10 Sep 2018 16:20:23 +0100 Subject: [PATCH 06/12] Updates name of variant model mappign in list views - to use same logic as the content tree if a variant has not been set - we fallabck to the base/master lanaguage of the node name --- .../Models/Mapping/ContentMapperProfile.cs | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs index 4ce8edbdc2..0e8b818aa6 100644 --- a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs +++ b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs @@ -92,7 +92,16 @@ namespace Umbraco.Web.Models.Mapping { public string Resolve(IContent source, ContentItemBasic destination, string destMember, ResolutionContext context) { - return source.GetCultureName(context.GetCulture()); + var culture = context.GetCulture(); + + if (source.CultureNames.TryGetValue(culture, out var name) && !string.IsNullOrWhiteSpace(name)) + { + return name; + } + else + { + return $"({ source.Name })"; + } } } } From 4b47943e05df7c2b50ab6fdd633ca66d799fc532 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Tue, 11 Sep 2018 08:44:58 +0100 Subject: [PATCH 07/12] Remove quotes within logging message templates - as when doing querying with logs makes these logs impossible to find --- src/Umbraco.Core/Runtime/CoreRuntime.cs | 2 +- src/Umbraco.Core/RuntimeState.cs | 2 +- .../Services/Implement/ContentService.cs | 20 +++++++------- .../Routing/ContentFinderByRedirectUrl.cs | 6 ++--- src/Umbraco.Web/Routing/ContentFinderByUrl.cs | 2 +- src/Umbraco.Web/Routing/PublishedRouter.cs | 26 +++++++++---------- 6 files changed, 29 insertions(+), 29 deletions(-) diff --git a/src/Umbraco.Core/Runtime/CoreRuntime.cs b/src/Umbraco.Core/Runtime/CoreRuntime.cs index de86ea929f..8f3b8991e4 100644 --- a/src/Umbraco.Core/Runtime/CoreRuntime.cs +++ b/src/Umbraco.Core/Runtime/CoreRuntime.cs @@ -363,7 +363,7 @@ namespace Umbraco.Core.Runtime _state.CurrentMigrationState = state; _state.FinalMigrationState = umbracoPlan.FinalState; - logger.Debug("Final upgrade state is '{FinalMigrationState}', database contains {DatabaseState}", _state.FinalMigrationState, state ?? ""); + logger.Debug("Final upgrade state is {FinalMigrationState}, database contains {DatabaseState}", _state.FinalMigrationState, state ?? ""); return state == _state.FinalMigrationState; } diff --git a/src/Umbraco.Core/RuntimeState.cs b/src/Umbraco.Core/RuntimeState.cs index d09bd95081..0177619a68 100644 --- a/src/Umbraco.Core/RuntimeState.cs +++ b/src/Umbraco.Core/RuntimeState.cs @@ -117,7 +117,7 @@ namespace Umbraco.Core 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); } diff --git a/src/Umbraco.Core/Services/Implement/ContentService.cs b/src/Umbraco.Core/Services/Implement/ContentService.cs index 0bb00ef5a4..da59615126 100644 --- a/src/Umbraco.Core/Services/Implement/ContentService.cs +++ b/src/Umbraco.Core/Services/Implement/ContentService.cs @@ -2178,7 +2178,7 @@ namespace Umbraco.Core.Services.Implement // raise Publishing event if (scope.Events.DispatchCancelable(Publishing, this, new PublishEventArgs(content, evtMsgs))) { - Logger.Info("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "publishing was cancelled"); + Logger.Info("Document {ContentName} (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "publishing was cancelled"); return new PublishResult(PublishResultType.FailedCancelledByEvent, evtMsgs, content); } @@ -2186,7 +2186,7 @@ namespace Umbraco.Core.Services.Implement // either because it is 'publishing' or because it already has a published version if (((Content) content).PublishedState != PublishedState.Publishing && content.PublishedVersionId == 0) { - Logger.Info("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document does not have published values"); + Logger.Info("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); } @@ -2194,15 +2194,15 @@ namespace Umbraco.Core.Services.Implement switch (content.Status) { case ContentStatus.Expired: - Logger.Info("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document has expired"); + Logger.Info("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("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document is awaiting release"); + Logger.Info("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("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "document is trashed"); + Logger.Info("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 @@ namespace Umbraco.Core.Services.Implement var pathIsOk = content.ParentId == Constants.System.Root || IsPathPublished(GetParent(content)); if (pathIsOk == false) { - Logger.Info("Document '{ContentName}' (id={ContentId}) cannot be published: {Reason}", content.Name, content.Id, "parent is not published"); + Logger.Info("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 @@ namespace Umbraco.Core.Services.Implement // change state to publishing ((Content) content).PublishedState = PublishedState.Publishing; - Logger.Info("Document '{ContentName}' (id={ContentId}) has been published.", content.Name, content.Id); + Logger.Info("Document {ContentName} (id={ContentId}) has been published.", content.Name, content.Id); return result; } @@ -2248,7 +2248,7 @@ namespace Umbraco.Core.Services.Implement // raise UnPublishing event if (scope.Events.DispatchCancelable(UnPublishing, this, new PublishEventArgs(content, evtMsgs))) { - Logger.Info("Document '{ContentName}' (id={ContentId}) cannot be unpublished: unpublishing was cancelled.", content.Name, content.Id); + Logger.Info("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 @@ namespace Umbraco.Core.Services.Implement if (content.ReleaseDate.HasValue && content.ReleaseDate.Value <= DateTime.Now) { content.ReleaseDate = null; - Logger.Info("Document '{ContentName}' (id={ContentId}) had its release date removed, because it was unpublished.", content.Name, content.Id); + Logger.Info("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("Document '{ContentName}' (id={ContentId}) has been unpublished.", content.Name, content.Id); + Logger.Info("Document {ContentName} (id={ContentId}) has been unpublished.", content.Name, content.Id); return attempt; } diff --git a/src/Umbraco.Web/Routing/ContentFinderByRedirectUrl.cs b/src/Umbraco.Web/Routing/ContentFinderByRedirectUrl.cs index d50951161c..ee495b6d7d 100644 --- a/src/Umbraco.Web/Routing/ContentFinderByRedirectUrl.cs +++ b/src/Umbraco.Web/Routing/ContentFinderByRedirectUrl.cs @@ -48,7 +48,7 @@ namespace Umbraco.Web.Routing if (redirectUrl == null) { - _logger.Debug("No match for route: '{Route}'", route); + _logger.Debug("No match for route: {Route}", route); return false; } @@ -56,11 +56,11 @@ namespace Umbraco.Web.Routing var url = content == null ? "#" : content.Url; if (url.StartsWith("#")) { - _logger.Debug("Route '{Route}' matches content {ContentId} which has no url.", route, redirectUrl.ContentId); + _logger.Debug("Route {Route} matches content {ContentId} which has no url.", route, redirectUrl.ContentId); return false; } - _logger.Debug("Route '{Route}' matches content {ContentId} with url '{Url}', redirecting.", route, content.Id, url); + _logger.Debug("Route {Route} matches content {ContentId} with url '{Url}', redirecting.", route, content.Id, url); frequest.SetRedirectPermanent(url); return true; } diff --git a/src/Umbraco.Web/Routing/ContentFinderByUrl.cs b/src/Umbraco.Web/Routing/ContentFinderByUrl.cs index a3c54406a8..a0dceb23ad 100644 --- a/src/Umbraco.Web/Routing/ContentFinderByUrl.cs +++ b/src/Umbraco.Web/Routing/ContentFinderByUrl.cs @@ -46,7 +46,7 @@ namespace Umbraco.Web.Routing { if (docreq == null) throw new System.ArgumentNullException(nameof(docreq)); - Logger.Debug("Test route '{Route}'", route); + Logger.Debug("Test route {Route}", route); var node = docreq.UmbracoContext.ContentCache.GetByRoute(route, culture: docreq.Culture?.Name); if (node != null) diff --git a/src/Umbraco.Web/Routing/PublishedRouter.cs b/src/Umbraco.Web/Routing/PublishedRouter.cs index f23473e369..42137d3b9e 100644 --- a/src/Umbraco.Web/Routing/PublishedRouter.cs +++ b/src/Umbraco.Web/Routing/PublishedRouter.cs @@ -276,7 +276,7 @@ namespace Umbraco.Web.Routing // note - we are not handling schemes nor ports here. - _logger.Debug("{TracePrefix}Uri='{RequestUri}'", tracePrefix, request.Uri); + _logger.Debug("{TracePrefix}Uri={RequestUri}", tracePrefix, request.Uri); var domainsCache = request.UmbracoContext.PublishedSnapshot.Domains; var domains = domainsCache.GetAll(includeWildcards: false).ToList(); @@ -313,7 +313,7 @@ namespace Umbraco.Web.Routing if (domainAndUri != null) { // matching an existing domain - _logger.Debug("{TracePrefix}Matches domain='{Domain}', rootId={RootContentId}, culture='{Culture}'", tracePrefix, domainAndUri.Name, domainAndUri.ContentId, domainAndUri.Culture); + _logger.Debug("{TracePrefix}Matches domain={Domain}, rootId={RootContentId}, culture={Culture}", tracePrefix, domainAndUri.Name, domainAndUri.ContentId, domainAndUri.Culture); request.Domain = domainAndUri; request.Culture = domainAndUri.Culture; @@ -333,7 +333,7 @@ namespace Umbraco.Web.Routing request.Culture = defaultCulture == null ? CultureInfo.CurrentUICulture : new CultureInfo(defaultCulture); } - _logger.Debug("{TracePrefix}Culture='{CultureName}'", tracePrefix, request.Culture.Name); + _logger.Debug("{TracePrefix}Culture={CultureName}", tracePrefix, request.Culture.Name); return request.Domain != null; } @@ -349,7 +349,7 @@ namespace Umbraco.Web.Routing return; var nodePath = request.PublishedContent.Path; - _logger.Debug("{TracePrefix}Path='{NodePath}'", tracePrefix, nodePath); + _logger.Debug("{TracePrefix}Path={NodePath}", tracePrefix, nodePath); var rootNodeId = request.HasDomain ? request.Domain.ContentId : (int?)null; var domain = DomainHelper.FindWildcardDomainInPath(request.UmbracoContext.PublishedSnapshot.Domains.GetAll(true), nodePath, rootNodeId); @@ -357,7 +357,7 @@ namespace Umbraco.Web.Routing if (domain != null) { request.Culture = domain.Culture; - _logger.Debug("{TracePrefix}Got domain on node {DomainContentId}, set culture to '{CultureName}'", tracePrefix, domain.ContentId, request.Culture.Name); + _logger.Debug("{TracePrefix}Got domain on node {DomainContentId}, set culture to {CultureName}", tracePrefix, domain.ContentId, request.Culture.Name); } else { @@ -434,7 +434,7 @@ namespace Umbraco.Web.Routing /// A value indicating whether a document and template were found. private void FindPublishedContentAndTemplate(PublishedRequest request) { - _logger.Debug("FindPublishedContentAndTemplate: Path='{UriAbsolutePath}'", request.Uri.AbsolutePath); + _logger.Debug("FindPublishedContentAndTemplate: Path={UriAbsolutePath}", request.Uri.AbsolutePath); // run the document finders FindPublishedContent(request); @@ -540,7 +540,7 @@ namespace Umbraco.Web.Routing if (i == maxLoop || j == maxLoop) { - _logger.Debug("HandlePublishedContent: Looks like we're running into an infinite loop, abort"); + _logger.Debug("HandlePublishedContent: Looks like we are running into an infinite loop, abort"); request.PublishedContent = null; } @@ -712,7 +712,7 @@ namespace Umbraco.Web.Routing if (request.HasTemplate) _logger.Debug("FindTemplate: Has a template already, but also an alternative template."); - _logger.Debug("FindTemplate: Look for alternative template alias='{AltTemplate}'", altTemplate); + _logger.Debug("FindTemplate: Look for alternative template alias={AltTemplate}", altTemplate); // IsAllowedTemplate deals both with DisableAlternativeTemplates and ValidateAlternativeTemplates settings if (request.PublishedContent.IsAllowedTemplate(altTemplate)) @@ -723,16 +723,16 @@ namespace Umbraco.Web.Routing if (template != null) { request.TemplateModel = template; - _logger.Debug("FindTemplate: Got alternative template id={TemplateId} alias='{TemplateAlias}'", template.Id, template.Alias); + _logger.Debug("FindTemplate: Got alternative template id={TemplateId} alias={TemplateAlias}", template.Id, template.Alias); } else { - _logger.Debug("FindTemplate: The alternative template with alias='{AltTemplate}' does not exist, ignoring.", altTemplate); + _logger.Debug("FindTemplate: The alternative template with alias={AltTemplate} does not exist, ignoring.", altTemplate); } } else { - _logger.Warn("FindTemplate: Alternative template '{TemplateAlias}' is not allowed on node {NodeId}, ignoring.", altTemplate, request.PublishedContent.Id); + _logger.Warn("FindTemplate: Alternative template {TemplateAlias} is not allowed on node {NodeId}, ignoring.", altTemplate, request.PublishedContent.Id); // no allowed, back to default var templateId = request.PublishedContent.TemplateId; @@ -755,7 +755,7 @@ namespace Umbraco.Web.Routing } else { - _logger.Debug("FindTemplate: Running with template id={TemplateId} alias='{TemplateAlias}'", request.TemplateModel.Id, request.TemplateModel.Alias); + _logger.Debug("FindTemplate: Running with template id={TemplateId} alias={TemplateAlias}", request.TemplateModel.Id, request.TemplateModel.Alias); } } @@ -772,7 +772,7 @@ namespace Umbraco.Web.Routing var template = _services.FileService.GetTemplate(templateId); if (template == null) throw new InvalidOperationException("The template with Id " + templateId + " does not exist, the page cannot render."); - _logger.Debug("GetTemplateModel: Got template id={TemplateId} alias=\"{TemplateAlias}\"", template.Id, template.Alias); + _logger.Debug("GetTemplateModel: Got template id={TemplateId} alias={TemplateAlias}", template.Id, template.Alias); return template; } From ed94ea485d44d1606e0dfdc01d3e231b3fbae95e Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Tue, 11 Sep 2018 09:04:29 +0100 Subject: [PATCH 08/12] Gets the same HttpRequestId from the Enricher to use in the message template for text log files for begin & end request verbose logs --- src/Umbraco.Web/UmbracoModule.cs | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/src/Umbraco.Web/UmbracoModule.cs b/src/Umbraco.Web/UmbracoModule.cs index b79a697e39..d0ad7568e0 100644 --- a/src/Umbraco.Web/UmbracoModule.cs +++ b/src/Umbraco.Web/UmbracoModule.cs @@ -21,6 +21,7 @@ using Umbraco.Core.Security; using Umbraco.Core.Services; using Umbraco.Web.Composing; using Umbraco.Web.PublishedCache; +using Umbraco.Core.Logging.Serilog.Enrichers; namespace Umbraco.Web { @@ -558,8 +559,12 @@ namespace Umbraco.Web { var httpContext = ((HttpApplication) sender).Context; - //Create a new Request ID/GUID - requestId = Guid.NewGuid(); + var httpRequestId = Guid.Empty; + HttpRequestIdEnricher.TryGetCurrentHttpRequestId(out httpRequestId); + + Logger.Verbose("Begin request [{HttpRequestId}]: {RequestUrl}", + httpRequestId, + httpContext.Request.Url); BeginRequest(new HttpContextWrapper(httpContext)); }; @@ -603,8 +608,12 @@ namespace Umbraco.Web if (UmbracoContext.Current != null) { + var httpRequestId = Guid.Empty; + HttpRequestIdEnricher.TryGetCurrentHttpRequestId(out httpRequestId); + Logger.Verbose( - "Request: {RequestUrl} took {Duration}ms", + "End request [{HttpRequestId}]: {RequestUrl} took {Duration}ms", + httpRequestId, httpContext.Request.Url, DateTime.Now.Subtract(UmbracoContext.Current.ObjectCreated).TotalMilliseconds); } From 4b715d2081d02d8901443a2ec008cf54baaa4602 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 13 Sep 2018 12:07:33 +0100 Subject: [PATCH 09/12] Null checks for culture added and moved date to var to avoid getting item twice --- .../Models/Mapping/ContentMapperProfile.cs | 21 +++++++++++++++++-- 1 file changed, 19 insertions(+), 2 deletions(-) diff --git a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs index d7dc5cf46a..a2d068c32a 100644 --- a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs +++ b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs @@ -96,7 +96,13 @@ namespace Umbraco.Web.Models.Mapping public DateTime Resolve(IContent source, ContentItemBasic destination, DateTime destMember, ResolutionContext context) { var culture = context.GetCulture(); - return source.GetPublishDate(culture).HasValue ? source.GetPublishDate(culture).Value : source.UpdateDate; + + //a culture needs to be in the context for a variant content item + if (culture == null) + throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); + + var pubDate = source.GetPublishDate(culture); + return pubDate.HasValue ? pubDate.Value : source.UpdateDate; } } @@ -105,6 +111,11 @@ namespace Umbraco.Web.Models.Mapping public bool Resolve(IContent source, ContentItemBasic destination, bool destMember, ResolutionContext context) { var culture = context.GetCulture(); + + //a culture needs to be in the context for a variant content item + if (culture == null) + throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); + return source.IsCulturePublished(culture); } } @@ -113,7 +124,13 @@ namespace Umbraco.Web.Models.Mapping { public string Resolve(IContent source, ContentItemBasic destination, string destMember, ResolutionContext context) { - return source.GetCultureName(context.GetCulture()); + var culture = context.GetCulture(); + + //a culture needs to be in the context for a variant content item + if (culture == null) + throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); + + return source.GetCultureName(culture); } } } From 772c0b7b6ab4f501fda5edba3064f40aa5a68139 Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 13 Sep 2018 12:10:50 +0100 Subject: [PATCH 10/12] Merge branch 'temp8' into temp8-204-ListView-Variant-PublishedStates # Conflicts: # src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs --- .../Models/Mapping/ContentMapperProfile.cs | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs index a2d068c32a..f63f70debd 100644 --- a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs +++ b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs @@ -129,8 +129,15 @@ namespace Umbraco.Web.Models.Mapping //a culture needs to be in the context for a variant content item if (culture == null) throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); - - return source.GetCultureName(culture); + + if (source.CultureNames.TryGetValue(culture, out var name) && !string.IsNullOrWhiteSpace(name)) + { + return name; + } + else + { + return $"({ source.Name })"; + } } } } From 082d6e6792d88eb24b4a6b59ca0fe9a1101b26ec Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 13 Sep 2018 13:05:36 +0100 Subject: [PATCH 11/12] Rather than throw null ex's if culture not set - return the underlying source property (As used for both variant & invariant mapping in list views) --- src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs index f63f70debd..54c0bba86f 100644 --- a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs +++ b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs @@ -99,7 +99,7 @@ namespace Umbraco.Web.Models.Mapping //a culture needs to be in the context for a variant content item if (culture == null) - throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); + return source.UpdateDate; var pubDate = source.GetPublishDate(culture); return pubDate.HasValue ? pubDate.Value : source.UpdateDate; @@ -114,7 +114,7 @@ namespace Umbraco.Web.Models.Mapping //a culture needs to be in the context for a variant content item if (culture == null) - throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); + return source.Published; return source.IsCulturePublished(culture); } @@ -128,7 +128,7 @@ namespace Umbraco.Web.Models.Mapping //a culture needs to be in the context for a variant content item if (culture == null) - throw new InvalidOperationException($"No culture found in mapping operation when one is required for a culture variant"); + return source.Name; if (source.CultureNames.TryGetValue(culture, out var name) && !string.IsNullOrWhiteSpace(name)) { From 4782f03334e1b178fe5c5e4ffa7703c392c8d33a Mon Sep 17 00:00:00 2001 From: Warren Buckley Date: Thu, 13 Sep 2018 13:25:54 +0100 Subject: [PATCH 12/12] ping pong with shan's reviews - checks for doctype/contenttype is variant or not --- src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs index 54c0bba86f..1334cb1572 100644 --- a/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs +++ b/src/Umbraco.Web/Models/Mapping/ContentMapperProfile.cs @@ -98,7 +98,7 @@ namespace Umbraco.Web.Models.Mapping var culture = context.GetCulture(); //a culture needs to be in the context for a variant content item - if (culture == null) + if (culture == null || source.ContentType.VariesByCulture() == false) return source.UpdateDate; var pubDate = source.GetPublishDate(culture); @@ -113,7 +113,7 @@ namespace Umbraco.Web.Models.Mapping var culture = context.GetCulture(); //a culture needs to be in the context for a variant content item - if (culture == null) + if (culture == null || source.ContentType.VariesByCulture() == false) return source.Published; return source.IsCulturePublished(culture); @@ -127,7 +127,7 @@ namespace Umbraco.Web.Models.Mapping var culture = context.GetCulture(); //a culture needs to be in the context for a variant content item - if (culture == null) + if (culture == null || source.ContentType.VariesByCulture() == false) return source.Name; if (source.CultureNames.TryGetValue(culture, out var name) && !string.IsNullOrWhiteSpace(name))