MOAR Logging for V8 #2935
MOAR Logging for V8 #2935
Conversation
…not sure how useful a log for start & end request IMO (Stephan may think otherwise)
… (we dont want all thex extra bloat such as handlers etc)
…for the duration in milliseconds to be consistently called 'Duration'
ghost
assigned 
|
@zpqrtbnk as you had concerns over the Request ID stuff I had done previously, please can you look over these implementations to make sure they will work as you would expect. I have tested with SEQ and are able to see these properties and find related log entries to a request successfully, but a 2nd opinion would be appreciated please :) |
|
Reviewing - will comment on the code. |
| .Enrich.With<Log4NetLevelMapperEnricher>() | ||
| .Enrich.With<HttpSessionIdEnricher>() | ||
| .Enrich.With<HttpRequestNumberEnricher>() | ||
| .Enrich.With<HttpRequestIdEnricher>(); |
There was a problem hiding this comment.
IIC the RequestId enricher will bind a GUID to each request whereas the RequestNumber will bind an INT - both aiming at being a unique identifier for the request - do we actually want both? I realize... during restarts, we may see duplicate INT identifiers whereas GUIDs will always be unique... yet INTs give an idea of order. So maybe having the two is good. Thoughts?
There was a problem hiding this comment.
I will keep both for now, as you say its easier if you want to quickly see the previous or next requests by increasing/decreasing the INT
src/Umbraco.Web/UmbracoModule.cs
Outdated
| @@ -561,7 +561,6 @@ public void Init(HttpApplication app) | |||
| //Create a new Request ID/GUID | |||
| requestId = Guid.NewGuid(); | |||
|
|
|||
| Logger.Verbose<UmbracoModule>("Begin request [{RequestId}]: {RequestUrl}", requestId, httpContext.Request.Url); | |||
There was a problem hiding this comment.
I am not sure we want to get rid of that one - when debugging it's nice to see which requests are being processed. That being said: we should exclude client-side (css, js...) requests ie anything that we know we don't process - I think there's some code in the module to figure them out. And then, yes, creating a GUID this way is not going to work due to concurrency (one module instance for many requests) - see how the RequestId enricher works, it needs to store the ID in context.
There was a problem hiding this comment.
I can re-use the RequestGUID from the enricher in this start message log and add this log line back in
src/Umbraco.Web/UmbracoModule.cs
Outdated
| @@ -605,8 +604,7 @@ public void Init(HttpApplication app) | |||
| if (UmbracoContext.Current != null) | |||
| { | |||
| Logger.Verbose<UmbracoModule>( | |||
| "End Request [{RequestId}]: {RequestUrl} ({RequestTotalMilliseconds}ms)", | |||
| requestId, | |||
| "Request: {RequestUrl} took {Duration}ms", | |||
There was a problem hiding this comment.
See comment above. In fact... if you get rid of RequestId here and let the RequestId enricher deal with it, how will it show in the text log? In other words where would the RequestId show, if it's not part of the logged string but added by the enricher? I understand it would show in the JSON blob but what about text?
There was a problem hiding this comment.
Good point - will add it back in. I hope people will stop using the old and hard to read .txt file and swap to use the built in logviewer work I am doing, to help them search and query logs instead.
…ng with logs makes these logs impossible to find
…emplate for text log files for begin & end request verbose logs
To carry on my other recent related PR's here is some MOAR logging updates & improvements
Adds in some useful Serilog Enrichers from the
Serilog.Web.Classicproject, but rather than adding that Nupkg directly, I have copied over what I think is useful. As there seems some extra bloat we would not such as a HTTPModule and it potentially capturing/logging sensitve info from FORM DATA.This PR also contains an update to keep Serilog properties more consistent, rather than having too many uniquly named properties. So all the timing related log messages now use
Durationwhich will make it alot easier to query for any timing based log where the value is greater than XAlso the very verbose messages for Begin and End request, has now been changed to only log the end of the request and it's timing, as not sure the beginning message was too useful.