Adding Logging #65

JunTaoLuo · 2016-10-03T18:06:30Z

#42 Adding logging to response caching

JunTaoLuo · 2016-10-03T18:07:23Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCachePolicyProvider.cs

                        return false;
                    }

                    // Request allows stale values
-                    if (age < context.RequestCacheControlHeaderValue.MaxStaleLimit)
+                    var maxStaleLimit = context.RequestCacheControlHeaderValue.MaxStaleLimit;
+                    if (maxStaleLimit.HasValue && age - lowestMaxAge < maxStaleLimit)


Misread the RFC previously, the stale limit is the difference between current age and the specified max-age.

JunTaoLuo · 2016-10-03T18:07:54Z

src/Microsoft.AspNetCore.ResponseCaching/ResponseCacheMiddleware.cs

                    return true;
                }

                if (cachedResponseHeaders.ETag != null)
                {
                    foreach (var tag in ifNoneMatchHeader)
                    {
-                        if (cachedResponseHeaders.ETag.Compare(tag, useStrongComparison: true))
+                        if (cachedResponseHeaders.ETag.Compare(tag, useStrongComparison: false))


Misread the RFC previously, the comparison should be a weak comparison.

I suggest to have this change singled out in a separate commit.

JunTaoLuo · 2016-10-03T18:08:20Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+                formatString: "A valid cached response was retrieved for this request. The cached response will be served.");
+            _log504GatewayTimeoutServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 23,


JunTaoLuo · 2016-10-03T18:25:16Z

test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCacheMiddlewareTests.cs

+            TestUtils.AssertLoggedMessageContains(
+                sink.Writes[0],
+                LogLevel.Debug,
+                "Retrieving cache entry for base key");


Actually it's probably better to use eventIDs instead of string matches. More specific and less verbose

JunTaoLuo · 2016-10-03T19:27:48Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+                eventId: 26,
+                formatString: "No valid response was retrieved for this request.");
+            _logVaryByRulesStored = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Information,


This is an internal detail. Will set to Debug level

Tratcher · 2016-10-03T19:25:16Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _log304NotModifiedServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 23,
+                formatString: $"The content requested is not modified. A {StatusCodes.Status304NotModified} {ReasonPhrases.GetReasonPhrase(StatusCodes.Status304NotModified)} response will be served.");


"The content requested has not been modified."
The 304 will be logged by hosting.

Tratcher · 2016-10-03T19:25:53Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logCachedResponseServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 24,
+                formatString: "A valid cached response was retrieved for this request. The cached response will be served.");


"Serving response from cache."

Tratcher · 2016-10-03T19:27:49Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _log504GatewayTimeoutServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 25,
+                formatString: $"No valid response was retrieved for this request but a only-if-cached cache directive was specified. A {StatusCodes.Status504GatewayTimeout} {ReasonPhrases.GetReasonPhrase(StatusCodes.Status504GatewayTimeout)} response will be served.");


"The request could not be satisfied from cache and only-if-cached was specified."

"No cached response available for this request and the only-if-cached cache directive was specified."?

Tratcher · 2016-10-03T19:28:23Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logNoResponseServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 26,
+                formatString: "No valid response was retrieved for this request.");


"No cached response available."

"No cached response available for this request."?

Tratcher · 2016-10-03T19:29:04Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logVaryByRulesStored = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Information,
+                eventId: 27,
+                formatString: "Vary by rules were updated at key {Key}.");


Don't give the key, give the components.

Should I purge the keys from the messages logged during retrieval as well? Those are debug levels so maybe it doesn't hurt to keep them?

Tratcher · 2016-10-03T19:30:18Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseStored = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Information,
+                eventId: 28,
+                formatString: "The response for this request was stored at key {Key}.");


"The response has been stored in the cache."

Tratcher · 2016-10-03T19:30:54Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseNotStored = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 29,
+                formatString: "The response could not be stored for this request.");


"The response could not be cached." Why?

Lots of reasons, response was not deemed cacheable, buffering was disabled due to invalid operations or exceeding the maximum body length. This is a generic message but I might add more debug messages that can indicate why the response was not stored.

Tratcher · 2016-10-03T19:32:31Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseContentLengthMismatchNotStored = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 30,
+                formatString: $"The response could not be stored for this request. The content length specified in the {HeaderNames.ContentLength} header did not match the length of the response.");


Warning? Error? This is an app error, though not a cache error. "The response could not be cached because the Content-Length did not match the body length."

Tratcher · 2016-10-03T20:24:23Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logRequestMethodNotCacheable = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Debug,
+                eventId: 1,
+                formatString: "Request is not cacheable since it is a {Method} HTTP Method.");


due to the HTTP method: {Method}

Tratcher · 2016-10-03T20:24:41Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logRequestWithAuthorizationNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 2,
+                formatString: $"Request is not cacheable since it contains an {HeaderNames.Authorization} header.");


because it contains an...

Tratcher · 2016-10-03T20:25:00Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logRequestWithNoCacheNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 3,
+                formatString: "Request is not cacheable since it contains a no-cache cache directive.");


Tratcher · 2016-10-03T20:25:24Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logRequestWithPragmaNoCacheNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 4,
+                formatString: "Request is not cacheable since it contains a no-cache pragma directive.");


Tratcher · 2016-10-03T20:26:43Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logExpirationMinFreshAdded = LoggerMessage.Define<TimeSpan>(
+                logLevel: LogLevel.Debug,
+                eventId: 5,
+                formatString: "A requirement of minimum freshness of {Duration} specified by min-fresh is added.");


Adding a min-fresh requirement of {Duration}

JunTaoLuo · 2016-10-03T20:59:51Z

🆙📅

Tratcher

@glennc

Tratcher · 2016-10-03T21:58:12Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCacheContext.cs

        }

        public HttpContext HttpContext { get; }

+        public ILogger Logger { get; }


Tratcher · 2016-10-03T22:12:42Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logRequestMethodNotCacheable = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Debug,
+                eventId: 1,
+                formatString: "Request is not cacheable due to the HTTP method: {Method}.");


'Request is not cacheable'... is the request ever cacheable? 'The request cannot be served from cache...'

Yea that might be better. I just went with the current name of the method that generates these logs, which is also a little misleading.

Tratcher · 2016-10-03T23:21:13Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseNotStored = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 27,
+                formatString: "The response could not be stored for this request.");


Tratcher · 2016-10-03T23:21:34Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseContentLengthMismatchNotStored = LoggerMessage.Define(
+                logLevel: LogLevel.Warning,
+                eventId: 28,
+                formatString: $"The response could not be stored for this request because the {HeaderNames.ContentLength} did not match the body length.");


troydai · 2016-10-04T21:36:04Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCacheContext.cs

@@ -24,9 +25,11 @@ public class ResponseCacheContext
        private bool _parsedResponseExpires;

        internal ResponseCacheContext(
-            HttpContext httpContext)
+            HttpContext httpContext,
+            ILogger logger)


this is short enough to be kept on same line.

troydai · 2016-10-04T21:37:42Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCacheContext.cs

@@ -37,6 +40,8 @@ public class ResponseCacheContext

        public CachedVaryByRules CachedVaryByRules { get; internal set; }

+        internal ILogger Logger { get; }


why not public? after all the context itself is public which means it is open to application consumption.

talked with @JunTaoLuo and @Tratcher, I bought the explanation. keep it internal then.

troydai · 2016-10-04T21:40:08Z

src/Microsoft.AspNetCore.ResponseCaching/ResponseCacheMiddleware.cs

                    return true;
                }

                if (cachedResponseHeaders.ETag != null)
                {
                    foreach (var tag in ifNoneMatchHeader)
                    {
-                        if (cachedResponseHeaders.ETag.Compare(tag, useStrongComparison: true))
+                        if (cachedResponseHeaders.ETag.Compare(tag, useStrongComparison: false))


I suggest to have this change singled out in a separate commit.

BrennanConroy · 2016-10-05T16:58:18Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logExpirationMustRevalidate = LoggerMessage.Define<TimeSpan, TimeSpan>(
+                logLevel: LogLevel.Debug,
+                eventId: 7,
+                formatString: "The age of the entry is {Age} and has exceeded the maximum age of {MaxAge} specified by max-age. It must be revalidated becauses must-revalidate is specified.");


BrennanConroy · 2016-10-05T17:03:26Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseWithoutPublicNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 11,
+                formatString: "Response is not cacheable because it does not contain the public cache directive.");


Should this be "... the 'public' cache directive"

I was wondering how we format all the header names and cache directives. In a few middlewares I didn't see any formatting. Guess I'll use single quotes here.

BrennanConroy · 2016-10-05T17:31:36Z

Tratcher · 2016-10-05T19:21:25Z

src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs

+            _logResponseCached = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 26,
+                formatString: "The response has been cached in the cache.");


"The response has been cached."

dnfclas added the cla-already-signed label Oct 3, 2016

JunTaoLuo commented Oct 3, 2016

View reviewed changes

Tratcher reviewed Oct 3, 2016

View reviewed changes

troydai suggested changes Oct 4, 2016

View reviewed changes

troydai approved these changes Oct 4, 2016

View reviewed changes

JunTaoLuo force-pushed the johluo/logging branch from 42ef871 to eb21f74 Compare October 4, 2016 23:54

BrennanConroy reviewed Oct 5, 2016

View reviewed changes

Tratcher reviewed Oct 5, 2016

View reviewed changes

JunTaoLuo force-pushed the johluo/logging branch from 46f021d to 39d380c Compare October 5, 2016 19:24

JunTaoLuo closed this Oct 6, 2016

JunTaoLuo force-pushed the johluo/logging branch from 7141041 to 3b2a2eb Compare October 6, 2016 01:02

JunTaoLuo deleted the johluo/logging branch October 6, 2016 01:02

JunTaoLuo mentioned this pull request Oct 6, 2016

Review logged messages #68

Closed

aspnet-hello mentioned this pull request Jan 2, 2018

Review logged messages dotnet/aspnetcore#2615

Closed

		@@ -37,6 +40,8 @@ public class ResponseCacheContext

		public CachedVaryByRules CachedVaryByRules { get; internal set; }

		internal ILogger Logger { get; }

Adding Logging #65

Adding Logging #65

Uh oh!

Conversation

JunTaoLuo commented Oct 3, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

troydai Oct 4, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

JunTaoLuo commented Oct 3, 2016

Uh oh!

Tratcher left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

troydai Oct 4, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

JunTaoLuo commented Oct 3, 2016 •

edited

Loading

troydai Oct 4, 2016 •

edited

Loading

troydai Oct 4, 2016 •

edited

Loading