Add logging

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

@@ -0,0 +1,300 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using Microsoft.Extensions.Logging;
+using Microsoft.Net.Http.Headers;
+
+namespace Microsoft.AspNetCore.ResponseCaching.Internal
+{
+    /// <summary>
+    /// Defines *all* the logger messages produced by response caching
+    /// </summary>
+    internal static class LoggerExtensions
+    {
+        private static Action<ILogger, string, Exception> _logRequestMethodNotCacheable;
+        private static Action<ILogger, Exception> _logRequestWithAuthorizationNotCacheable;
+        private static Action<ILogger, Exception> _logRequestWithNoCacheNotCacheable;
+        private static Action<ILogger, Exception> _logRequestWithPragmaNoCacheNotCacheable;
+        private static Action<ILogger, TimeSpan, Exception> _logExpirationMinFreshAdded;
+        private static Action<ILogger, TimeSpan, TimeSpan, Exception> _logExpirationSharedMaxAgeExceeded;
+        private static Action<ILogger, TimeSpan, TimeSpan, Exception> _logExpirationMustRevalidate;
+        private static Action<ILogger, TimeSpan, TimeSpan, TimeSpan, Exception> _logExpirationMaxStaleSatisfied;
+        private static Action<ILogger, TimeSpan, TimeSpan, Exception> _logExpirationMaxAgeExceeded;
+        private static Action<ILogger, DateTimeOffset, DateTimeOffset, Exception> _logExpirationExpiresExceeded;
+        private static Action<ILogger, Exception> _logResponseWithoutPublicNotCacheable;
+        private static Action<ILogger, Exception> _logResponseWithNoStoreNotCacheable;
+        private static Action<ILogger, Exception> _logResponseWithNoCacheNotCacheable;
+        private static Action<ILogger, Exception> _logResponseWithSetCookieNotCacheable;
+        private static Action<ILogger, Exception> _logResponseWithVaryStarNotCacheable;
+        private static Action<ILogger, Exception> _logResponseWithPrivateNotCacheable;
+        private static Action<ILogger, int, Exception> _logResponseWithUnsuccessfulStatusCodeNotCacheable;
+        private static Action<ILogger, Exception> _logNotModifiedIfNoneMatchStar;
+        private static Action<ILogger, EntityTagHeaderValue, Exception> _logNotModifiedIfNoneMatchMatched;
+        private static Action<ILogger, DateTimeOffset, DateTimeOffset, Exception> _logNotModifiedIfUnmodifiedSinceSatisfied;
+        private static Action<ILogger, Exception> _logNotModifiedServed;
+        private static Action<ILogger, Exception> _logCachedResponseServed;
+        private static Action<ILogger, Exception> _logGatewayTimeoutServed;
+        private static Action<ILogger, Exception> _logNoResponseServed;
+        private static Action<ILogger, string, string, Exception> _logVaryByRulesUpdated;
+        private static Action<ILogger, Exception> _logResponseCached;
+        private static Action<ILogger, Exception> _logResponseNotCached;
+        private static Action<ILogger, Exception> _logResponseContentLengthMismatchNotCached;
+
+        static LoggerExtensions()
+        {
+            _logRequestMethodNotCacheable = LoggerMessage.Define<string>(
+                logLevel: LogLevel.Debug,
+                eventId: 1,
+                formatString: "The request cannot be served from cache because it uses the HTTP method: {Method}.");
+            _logRequestWithAuthorizationNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 2,
+                formatString: $"The request cannot be served from cache because it contains an '{HeaderNames.Authorization}' header.");
+            _logRequestWithNoCacheNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 3,
+                formatString: "The request cannot be served from cache because it contains a 'no-cache' cache directive.");
+            _logRequestWithPragmaNoCacheNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 4,
+                formatString: "The request cannot be served from cache because it contains a 'no-cache' pragma directive.");
+            _logExpirationMinFreshAdded = LoggerMessage.Define<TimeSpan>(
+                logLevel: LogLevel.Debug,
+                eventId: 5,
+                formatString: "Adding a minimum freshness requirement of {Duration} specified by the 'min-fresh' cache directive.");
+            _logExpirationSharedMaxAgeExceeded = LoggerMessage.Define<TimeSpan, TimeSpan>(
+                logLevel: LogLevel.Debug,
+                eventId: 6,
+                formatString: "The age of the entry is {Age} and has exceeded the maximum age for shared caches of {SharedMaxAge} specified by the 's-maxage' cache directive.");
+            _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 the 'max-age' cache directive. It must be revalidated because the 'must-revalidate' cache directive is specified.");
+            _logExpirationMaxStaleSatisfied = LoggerMessage.Define<TimeSpan, TimeSpan, TimeSpan>(
+                logLevel: LogLevel.Debug,
+                eventId: 8,
+                formatString: "The age of the entry is {Age} and has exceeded the maximum age of {MaxAge} specified by the 'max-age' cache directive. However, it satisfied the maximum stale allowance of {MaxStale} specified by the 'max-stale' cache directive.");
+            _logExpirationMaxAgeExceeded = LoggerMessage.Define<TimeSpan, TimeSpan>(
+                logLevel: LogLevel.Debug,
+                eventId: 9,
+                formatString: "The age of the entry is {Age} and has exceeded the maximum age of {MaxAge} specified by the 'max-age' cache directive.");
+            _logExpirationExpiresExceeded = LoggerMessage.Define<DateTimeOffset, DateTimeOffset>(
+                logLevel: LogLevel.Debug,
+                eventId: 10,
+                formatString: $"The response time of the entry is {{ResponseTime}} and has exceeded the expiry date of {{Expired}} specified by the '{HeaderNames.Expires}' header.");
+            _logResponseWithoutPublicNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 11,
+                formatString: "Response is not cacheable because it does not contain the 'public' cache directive.");
+            _logResponseWithNoStoreNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 12,
+                formatString: "Response is not cacheable because it or its corresponding request contains a 'no-store' cache directive.");
+            _logResponseWithNoCacheNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 13,
+                formatString: "Response is not cacheable because it contains a 'no-cache' cache directive.");
+            _logResponseWithSetCookieNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 14,
+                formatString: $"Response is not cacheable because it contains a '{HeaderNames.SetCookie}' header.");
+            _logResponseWithVaryStarNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 15,
+                formatString: $"Response is not cacheable because it contains a '{HeaderNames.Vary}' header with a value of *.");
+            _logResponseWithPrivateNotCacheable = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 16,
+                formatString: "Response is not cacheable because it contains the 'private' cache directive.");
+            _logResponseWithUnsuccessfulStatusCodeNotCacheable = LoggerMessage.Define<int>(
+                logLevel: LogLevel.Debug,
+                eventId: 17,
+                formatString: "Response is not cacheable because its status code {StatusCode} does not indicate success.");
+            _logNotModifiedIfNoneMatchStar = LoggerMessage.Define(
+                logLevel: LogLevel.Debug,
+                eventId: 18,
+                formatString: $"The '{HeaderNames.IfNoneMatch}' header of the request contains a value of *.");
+            _logNotModifiedIfNoneMatchMatched = LoggerMessage.Define<EntityTagHeaderValue>(
+                logLevel: LogLevel.Debug,
+                eventId: 19,
+                formatString: $"The ETag {{ETag}} in the '{HeaderNames.IfNoneMatch}' header matched the ETag of a cached entry.");
+            _logNotModifiedIfUnmodifiedSinceSatisfied = LoggerMessage.Define<DateTimeOffset, DateTimeOffset>(
+                logLevel: LogLevel.Debug,
+                eventId: 20,
+                formatString: $"The last modified date of {{LastModified}} is before the date {{IfUnmodifiedSince}} specified in the '{HeaderNames.IfUnmodifiedSince}' header.");
+            _logNotModifiedServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 21,
+                formatString: "The content requested has not been modified.");
+            _logCachedResponseServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 22,
+                formatString: "Serving response from cache.");
+            _logGatewayTimeoutServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 23,
+                formatString: "No cached response available for this request and the 'only-if-cached' cache directive was specified.");
+            _logNoResponseServed = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 24,
+                formatString: "No cached response available for this request.");
+            _logVaryByRulesUpdated = LoggerMessage.Define<string, string>(
+                logLevel: LogLevel.Debug,
+                eventId: 25,
+                formatString: "Vary by rules were updated. Headers: {Headers}, Query keys: {QueryKeys}");
+            _logResponseCached = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 26,
+                formatString: "The response has been cached.");
+            _logResponseNotCached = LoggerMessage.Define(
+                logLevel: LogLevel.Information,
+                eventId: 27,
+                formatString: "The response could not be cached for this request.");
+            _logResponseContentLengthMismatchNotCached = LoggerMessage.Define(
+                logLevel: LogLevel.Warning,
+                eventId: 28,
+                formatString: $"The response could not be cached for this request because the '{HeaderNames.ContentLength}' did not match the body length.");
+        }
+
+        internal static void LogRequestMethodNotCacheable(this ILogger logger, string method)
+        {
+            _logRequestMethodNotCacheable(logger, method, null);
+        }
+
+        internal static void LogRequestWithAuthorizationNotCacheable(this ILogger logger)
+        {
+            _logRequestWithAuthorizationNotCacheable(logger, null);
+        }
+
+        internal static void LogRequestWithNoCacheNotCacheable(this ILogger logger)
+        {
+            _logRequestWithNoCacheNotCacheable(logger, null);
+        }
+
+        internal static void LogRequestWithPragmaNoCacheNotCacheable(this ILogger logger)
+        {
+            _logRequestWithPragmaNoCacheNotCacheable(logger, null);
+        }
+
+        internal static void LogExpirationMinFreshAdded(this ILogger logger, TimeSpan duration)
+        {
+            _logExpirationMinFreshAdded(logger, duration, null);
+        }
+
+        internal static void LogExpirationSharedMaxAgeExceeded(this ILogger logger, TimeSpan age, TimeSpan sharedMaxAge)
+        {
+            _logExpirationSharedMaxAgeExceeded(logger, age, sharedMaxAge, null);
+        }
+
+        internal static void LogExpirationMustRevalidate(this ILogger logger, TimeSpan age, TimeSpan maxAge)
+        {
+            _logExpirationMustRevalidate(logger, age, maxAge, null);
+        }
+
+        internal static void LogExpirationMaxStaleSatisfied(this ILogger logger, TimeSpan age, TimeSpan maxAge, TimeSpan maxStale)
+        {
+            _logExpirationMaxStaleSatisfied(logger, age, maxAge, maxStale, null);
+        }
+
+        internal static void LogExpirationMaxAgeExceeded(this ILogger logger, TimeSpan age, TimeSpan sharedMaxAge)
+        {
+            _logExpirationMaxAgeExceeded(logger, age, sharedMaxAge, null);
+        }
+
+        internal static void LogExpirationExpiresExceeded(this ILogger logger, DateTimeOffset responseTime, DateTimeOffset expires)
+        {
+            _logExpirationExpiresExceeded(logger, responseTime, expires, null);
+        }
+
+        internal static void LogResponseWithoutPublicNotCacheable(this ILogger logger)
+        {
+            _logResponseWithoutPublicNotCacheable(logger, null);
+        }
+
+        internal static void LogResponseWithNoStoreNotCacheable(this ILogger logger)
+        {
+            _logResponseWithNoStoreNotCacheable(logger, null);
+        }
+
+        internal static void LogResponseWithNoCacheNotCacheable(this ILogger logger)
+        {
+            _logResponseWithNoCacheNotCacheable(logger, null);
+        }
+
+        internal static void LogResponseWithSetCookieNotCacheable(this ILogger logger)
+        {
+            _logResponseWithSetCookieNotCacheable(logger, null);
+        }
+
+        internal static void LogResponseWithVaryStarNotCacheable(this ILogger logger)
+        {
+            _logResponseWithVaryStarNotCacheable(logger, null);
+        }
+
+        internal static void LogResponseWithPrivateNotCacheable(this ILogger logger)
+        {
+            _logResponseWithPrivateNotCacheable(logger, null);
+        }
+
+        internal static void LogResponseWithUnsuccessfulStatusCodeNotCacheable(this ILogger logger, int statusCode)
+        {
+            _logResponseWithUnsuccessfulStatusCodeNotCacheable(logger, statusCode, null);
+        }
+
+        internal static void LogNotModifiedIfNoneMatchStar(this ILogger logger)
+        {
+            _logNotModifiedIfNoneMatchStar(logger, null);
+        }
+
+        internal static void LogNotModifiedIfNoneMatchMatched(this ILogger logger, EntityTagHeaderValue etag)
+        {
+            _logNotModifiedIfNoneMatchMatched(logger, etag, null);
+        }
+
+        internal static void LogNotModifiedIfUnmodifiedSinceSatisfied(this ILogger logger, DateTimeOffset lastModified, DateTimeOffset ifUnmodifiedSince)
+        {
+            _logNotModifiedIfUnmodifiedSinceSatisfied(logger, lastModified, ifUnmodifiedSince, null);
+        }
+
+        internal static void LogNotModifiedServed(this ILogger logger)
+        {
+            _logNotModifiedServed(logger, null);
+        }
+
+        internal static void LogCachedResponseServed(this ILogger logger)
+        {
+            _logCachedResponseServed(logger, null);
+        }
+
+        internal static void LogGatewayTimeoutServed(this ILogger logger)
+        {
+            _logGatewayTimeoutServed(logger, null);
+        }
+
+        internal static void LogNoResponseServed(this ILogger logger)
+        {
+            _logNoResponseServed(logger, null);
+        }
+
+        internal static void LogVaryByRulesUpdated(this ILogger logger, string headers, string queryKeys)
+        {
+            _logVaryByRulesUpdated(logger, headers, queryKeys, null);
+        }
+
+        internal static void LogResponseCached(this ILogger logger)
+        {
+            _logResponseCached(logger, null);
+        }
+
+        internal static void LogResponseNotCached(this ILogger logger)
+        {
+            _logResponseNotCached(logger, null);
+        }
+
+        internal static void LogResponseContentLengthMismatchNotCached(this ILogger logger)
+        {
+            _logResponseContentLengthMismatchNotCached(logger, null);
+        }
+    }
+}

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

@@ -6,6 +6,7 @@ using System.IO;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Http.Headers;
+using Microsoft.Extensions.Logging;
 using Microsoft.Net.Http.Headers;
 
 namespace Microsoft.AspNetCore.ResponseCaching.Internal
@@ -23,10 +24,10 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
         private DateTimeOffset? _responseExpires;
         private bool _parsedResponseExpires;
 
-        internal ResponseCacheContext(
+        internal ResponseCacheContext(HttpContext httpContext, ILogger logger)
-            HttpContext httpContext)
         {
             HttpContext = httpContext;
+            Logger = logger;
         }
 
         public HttpContext HttpContext { get; }
@@ -37,6 +38,8 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
 
         public CachedVaryByRules CachedVaryByRules { get; internal set; }
 
+        internal ILogger Logger { get; }
+
         internal bool ShouldCacheResponse { get;  set; }
 
         internal string BaseKey { get;  set; }

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

@@ -18,12 +18,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
             var request = context.HttpContext.Request;
             if (!HttpMethods.IsGet(request.Method) && !HttpMethods.IsHead(request.Method))
             {
+                context.Logger.LogRequestMethodNotCacheable(request.Method);
                 return false;
             }
 
             // Verify existence of authorization headers
             if (!StringValues.IsNullOrEmpty(request.Headers[HeaderNames.Authorization]))
             {
+                context.Logger.LogRequestWithAuthorizationNotCacheable();
                 return false;
             }
 
@@ -32,6 +34,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
             {
                 if (context.RequestCacheControlHeaderValue.NoCache)
                 {
+                    context.Logger.LogRequestWithNoCacheNotCacheable();
                     return false;
                 }
             }
@@ -43,6 +46,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
                 {
                     if (string.Equals("no-cache", directive, StringComparison.OrdinalIgnoreCase))
                     {
+                        context.Logger.LogRequestWithPragmaNoCacheNotCacheable();
                         return false;
                     }
                 }
@@ -56,18 +60,21 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
             // Only cache pages explicitly marked with public
             if (!context.ResponseCacheControlHeaderValue.Public)
             {
+                context.Logger.LogResponseWithoutPublicNotCacheable();
                 return false;
             }
 
             // Check no-store
             if (context.RequestCacheControlHeaderValue.NoStore || context.ResponseCacheControlHeaderValue.NoStore)
             {
+                context.Logger.LogResponseWithNoStoreNotCacheable();
                 return false;
             }
 
             // Check no-cache
             if (context.ResponseCacheControlHeaderValue.NoCache)
             {
+                context.Logger.LogResponseWithNoCacheNotCacheable();
                 return false;
             }
 
@@ -76,6 +83,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
             // Do not cache responses with Set-Cookie headers
             if (!StringValues.IsNullOrEmpty(response.Headers[HeaderNames.SetCookie]))
             {
+                context.Logger.LogResponseWithSetCookieNotCacheable();
                 return false;
             }
 
@@ -83,18 +91,21 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
             var varyHeader = response.Headers[HeaderNames.Vary];
             if (varyHeader.Count == 1 && string.Equals(varyHeader, "*", StringComparison.OrdinalIgnoreCase))
             {
+                context.Logger.LogResponseWithVaryStarNotCacheable();
                 return false;
             }
 
             // Check private
             if (context.ResponseCacheControlHeaderValue.Private)
             {
+                context.Logger.LogResponseWithPrivateNotCacheable();
                 return false;
             }
 
             // Check response code
             if (response.StatusCode != StatusCodes.Status200OK)
             {
+                context.Logger.LogResponseWithUnsuccessfulStatusCodeNotCacheable(response.StatusCode);
                 return false;
             }
 
@@ -105,6 +116,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
                     !context.ResponseCacheControlHeaderValue.MaxAge.HasValue &&
                     context.ResponseTime.Value >= context.ResponseExpires)
                 {
+                    context.Logger.LogExpirationExpiresExceeded(context.ResponseTime.Value, context.ResponseExpires.Value);
                     return false;
                 }
             }
@@ -113,22 +125,27 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
                 var age = context.ResponseTime.Value - context.ResponseDate.Value;
 
                 // Validate shared max age
-                if (age >= context.ResponseCacheControlHeaderValue.SharedMaxAge)
+                var sharedMaxAge = context.ResponseCacheControlHeaderValue.SharedMaxAge;
+                if (age >= sharedMaxAge)
                 {
+                    context.Logger.LogExpirationSharedMaxAgeExceeded(age, sharedMaxAge.Value);
                     return false;
                 }
-                else if (!context.ResponseCacheControlHeaderValue.SharedMaxAge.HasValue)
+                else if (!sharedMaxAge.HasValue)
                 {
                     // Validate max age
-                    if (age >= context.ResponseCacheControlHeaderValue.MaxAge)
+                    var maxAge = context.ResponseCacheControlHeaderValue.MaxAge;
+                    if (age >= maxAge)
                     {
+                        context.Logger.LogExpirationMaxAgeExceeded(age, maxAge.Value);
                         return false;
                     }
-                    else if (!context.ResponseCacheControlHeaderValue.MaxAge.HasValue)
+                    else if (!maxAge.HasValue)
                     {
                         // Validate expiration
                         if (context.ResponseTime.Value >= context.ResponseExpires)
                         {
+                            context.Logger.LogExpirationExpiresExceeded(context.ResponseTime.Value, context.ResponseExpires.Value);
                             return false;
                         }
                     }
@@ -144,41 +161,55 @@ namespace Microsoft.AspNetCore.ResponseCaching.Internal
             var cachedControlHeaders = context.CachedResponseHeaders.CacheControl ?? EmptyCacheControl;
 
             // Add min-fresh requirements
-            if (context.RequestCacheControlHeaderValue.MinFresh.HasValue)
+            var minFresh = context.RequestCacheControlHeaderValue.MinFresh;
+            if (minFresh.HasValue)
             {
-                age += context.RequestCacheControlHeaderValue.MinFresh.Value;
+                age += minFresh.Value;
+                context.Logger.LogExpirationMinFreshAdded(minFresh.Value);
             }
 
             // Validate shared max age, this overrides any max age settings for shared caches
-            if (age >= cachedControlHeaders.SharedMaxAge)
+            var sharedMaxAge = cachedControlHeaders.SharedMaxAge;
+            if (age >= sharedMaxAge)
             {
                 // shared max age implies must revalidate
+                context.Logger.LogExpirationSharedMaxAgeExceeded(age, sharedMaxAge.Value);
                 return false;
             }
-            else if (!cachedControlHeaders.SharedMaxAge.HasValue)
+            else if (!sharedMaxAge.HasValue)
             {
+                var cachedMaxAge = cachedControlHeaders.MaxAge;
+                var requestMaxAge = context.RequestCacheControlHeaderValue.MaxAge;
+                var lowestMaxAge = cachedMaxAge < requestMaxAge ? cachedMaxAge : requestMaxAge ?? cachedMaxAge;
                 // Validate max age
-                if (age >= cachedControlHeaders.MaxAge || age >= context.RequestCacheControlHeaderValue.MaxAge)
+                if (age >= lowestMaxAge)
                 {
                     // Must revalidate
                     if (cachedControlHeaders.MustRevalidate)
                     {
+                        context.Logger.LogExpirationMustRevalidate(age, lowestMaxAge.Value);
                         return false;
                     }
 
                     // Request allows stale values
-                    if (age < context.RequestCacheControlHeaderValue.MaxStaleLimit)
+                    var maxStaleLimit = context.RequestCacheControlHeaderValue.MaxStaleLimit;
+                    if (maxStaleLimit.HasValue && age - lowestMaxAge < maxStaleLimit)
                     {
+                        context.Logger.LogExpirationMaxStaleSatisfied(age, lowestMaxAge.Value, maxStaleLimit.Value);
                         return true;
                     }
 
+                    context.Logger.LogExpirationMaxAgeExceeded(age, lowestMaxAge.Value);
                     return false;
                 }
-                else if (!cachedControlHeaders.MaxAge.HasValue && !context.RequestCacheControlHeaderValue.MaxAge.HasValue)
+                else if (!cachedMaxAge.HasValue && !requestMaxAge.HasValue)
                 {
                     // Validate expiration
-                    if (context.ResponseTime.Value >= context.CachedResponseHeaders.Expires)
+                    var responseTime = context.ResponseTime.Value;
+                    var expires = context.CachedResponseHeaders.Expires;
+                    if (responseTime >= expires)
                     {
+                        context.Logger.LogExpirationExpiresExceeded(responseTime, expires.Value);
                         return false;
                     }
                 }

src/Microsoft.AspNetCore.ResponseCaching/ResponseCacheMiddleware.cs

@@ -10,7 +10,7 @@ using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Http.Headers;
 using Microsoft.AspNetCore.ResponseCaching.Internal;
 using Microsoft.Extensions.Internal;
-using Microsoft.Extensions.ObjectPool;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 using Microsoft.Net.Http.Headers;
@@ -22,15 +22,17 @@ namespace Microsoft.AspNetCore.ResponseCaching
         private static readonly TimeSpan DefaultExpirationTimeSpan = TimeSpan.FromSeconds(10);
 
         private readonly RequestDelegate _next;
-        private readonly IResponseCacheStore _store;
         private readonly ResponseCacheOptions _options;
+        private readonly ILogger _logger;
         private readonly IResponseCachePolicyProvider _policyProvider;
+        private readonly IResponseCacheStore _store;
         private readonly IResponseCacheKeyProvider _keyProvider;
         private readonly Func<object, Task> _onStartingCallback;
 
         public ResponseCacheMiddleware(
             RequestDelegate next,
             IOptions<ResponseCacheOptions> options,
+            ILoggerFactory loggerFactory,
             IResponseCachePolicyProvider policyProvider,
             IResponseCacheStore store,
             IResponseCacheKeyProvider keyProvider)
@@ -39,34 +41,39 @@ namespace Microsoft.AspNetCore.ResponseCaching
             {
                 throw new ArgumentNullException(nameof(next));
             }
-            if (store == null)
-            {
-                throw new ArgumentNullException(nameof(store));
-            }
             if (options == null)
             {
                 throw new ArgumentNullException(nameof(options));
             }
+            if (loggerFactory == null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
             if (policyProvider == null)
             {
                 throw new ArgumentNullException(nameof(policyProvider));
             }
+            if (store == null)
+            {
+                throw new ArgumentNullException(nameof(store));
+            }
             if (keyProvider == null)
             {
                 throw new ArgumentNullException(nameof(keyProvider));
             }
 
             _next = next;
-            _store = store;
             _options = options.Value;
+            _logger = loggerFactory.CreateLogger<ResponseCacheMiddleware>();
             _policyProvider = policyProvider;
+            _store = store;
             _keyProvider = keyProvider;
             _onStartingCallback = state => OnResponseStartingAsync((ResponseCacheContext)state);
         }
 
         public async Task Invoke(HttpContext httpContext)
         {
-            var context = new ResponseCacheContext(httpContext);
+            var context = new ResponseCacheContext(httpContext, _logger);
 
             // Should we attempt any caching logic?
             if (_policyProvider.IsRequestCacheable(context))
@@ -115,8 +122,9 @@ namespace Microsoft.AspNetCore.ResponseCaching
             if (_policyProvider.IsCachedEntryFresh(context))
             {
                 // Check conditional request rules
-                if (ConditionalRequestSatisfied(context))
+                if (ContentIsNotModified(context))
                 {
+                    _logger.LogNotModifiedServed();
                     context.HttpContext.Response.StatusCode = StatusCodes.Status304NotModified;
                 }
                 else
@@ -150,8 +158,8 @@ namespace Microsoft.AspNetCore.ResponseCaching
                             context.HttpContext.Abort();
                         }
                     }
+                    _logger.LogCachedResponseServed();
                 }
-
                 return true;
             }
 
@@ -183,13 +191,14 @@ namespace Microsoft.AspNetCore.ResponseCaching
                 return true;
             }
 
-
             if (context.RequestCacheControlHeaderValue.OnlyIfCached)
             {
+                _logger.LogGatewayTimeoutServed();
                 context.HttpContext.Response.StatusCode = StatusCodes.Status504GatewayTimeout;
                 return true;
             }
 
+            _logger.LogNoResponseServed();
             return false;
         }
 
@@ -229,6 +238,7 @@ namespace Microsoft.AspNetCore.ResponseCaching
                     }
 
                     // Always overwrite the CachedVaryByRules to update the expiry information
+                    _logger.LogVaryByRulesUpdated(normalizedVaryHeaders, normalizedVaryQueryKeys);
                     await _store.SetAsync(context.BaseKey, context.CachedVaryByRules, context.CachedResponseValidFor);
 
                     context.StorageVaryKey = _keyProvider.CreateStorageVaryByKey(context);
@@ -272,8 +282,17 @@ namespace Microsoft.AspNetCore.ResponseCaching
                 if (!contentLength.HasValue || contentLength == bufferStream.Length)
                 {
                     context.CachedResponse.Body = bufferStream;
+                    _logger.LogResponseCached();
                     await _store.SetAsync(context.StorageVaryKey ?? context.BaseKey, context.CachedResponse, context.CachedResponseValidFor);
                 }
+                else
+                {
+                    _logger.LogResponseContentLengthMismatchNotCached();
+                }
+            }
+            else
+            {
+                _logger.LogResponseNotCached();
             }
         }
 
@@ -320,7 +339,7 @@ namespace Microsoft.AspNetCore.ResponseCaching
             context.HttpContext.RemoveResponseCacheFeature();
         }
 
-        internal static bool ConditionalRequestSatisfied(ResponseCacheContext context)
+        internal static bool ContentIsNotModified(ResponseCacheContext context)
         {
             var cachedResponseHeaders = context.CachedResponseHeaders;
             var ifNoneMatchHeader = context.TypedRequestHeaders.IfNoneMatch;
@@ -329,6 +348,7 @@ namespace Microsoft.AspNetCore.ResponseCaching
             {
                 if (ifNoneMatchHeader.Count == 1 && ifNoneMatchHeader[0].Equals(EntityTagHeaderValue.Any))
                 {
+                    context.Logger.LogNotModifiedIfNoneMatchStar();
                     return true;
                 }
 
@@ -338,6 +358,7 @@ namespace Microsoft.AspNetCore.ResponseCaching
                     {
                         if (cachedResponseHeaders.ETag.Compare(tag, useStrongComparison: false))
                         {
+                            context.Logger.LogNotModifiedIfNoneMatchMatched(tag);
                             return true;
                         }
                     }
@@ -346,9 +367,14 @@ namespace Microsoft.AspNetCore.ResponseCaching
             else
             {
                 var ifUnmodifiedSince = context.TypedRequestHeaders.IfUnmodifiedSince;
-                if (ifUnmodifiedSince != null && (cachedResponseHeaders.LastModified ?? cachedResponseHeaders.Date) <= ifUnmodifiedSince)
+                if (ifUnmodifiedSince != null)
                 {
-                    return true;
+                    var lastModified = cachedResponseHeaders.LastModified ?? cachedResponseHeaders.Date;
+                    if (lastModified <= ifUnmodifiedSince)
+                    {
+                        context.Logger.LogNotModifiedIfUnmodifiedSinceSatisfied(lastModified.Value, ifUnmodifiedSince.Value);
+                        return true;
+                    }
                 }
             }
 

src/Microsoft.AspNetCore.ResponseCaching/project.json

@@ -25,6 +25,7 @@
     "Microsoft.AspNetCore.Http": "1.1.0-*",
     "Microsoft.AspNetCore.Http.Extensions": "1.1.0-*",
     "Microsoft.Extensions.Caching.Memory": "1.1.0-*",
+    "Microsoft.Extensions.Logging.Abstractions": "1.1.0-*",
     "Microsoft.Extensions.TaskCache.Sources": {
       "version": "1.1.0-*",
       "type": "build"

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

@@ -7,6 +7,9 @@ using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Headers;
 using Microsoft.AspNetCore.ResponseCaching.Internal;
+using Microsoft.AspNetCore.WebUtilities;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.Primitives;
 using Microsoft.Net.Http.Headers;
 using Xunit;
@@ -19,7 +22,8 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
         public async Task TryServeFromCacheAsync_OnlyIfCached_Serves504()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store: store, keyProvider: new TestResponseCacheKeyProvider());
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store, keyProvider: new TestResponseCacheKeyProvider());
             var context = TestUtils.CreateTestContext();
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -28,24 +32,32 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             Assert.True(await middleware.TryServeFromCacheAsync(context));
             Assert.Equal(StatusCodes.Status504GatewayTimeout, context.HttpContext.Response.StatusCode);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.GatewayTimeoutServed);
         }
 
         [Fact]
         public async Task TryServeFromCacheAsync_CachedResponseNotFound_Fails()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey"));
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey"));
             var context = TestUtils.CreateTestContext();
 
             Assert.False(await middleware.TryServeFromCacheAsync(context));
             Assert.Equal(1, store.GetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NoResponseServed);
         }
 
         [Fact]
         public async Task TryServeFromCacheAsync_CachedResponseFound_Succeeds()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey"));
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey"));
             var context = TestUtils.CreateTestContext();
 
             await store.SetAsync(
@@ -58,13 +70,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             Assert.True(await middleware.TryServeFromCacheAsync(context));
             Assert.Equal(1, store.GetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.CachedResponseServed);
         }
 
         [Fact]
         public async Task TryServeFromCacheAsync_VaryByRuleFound_CachedResponseNotFound_Fails()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey", "VaryKey"));
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey", "VaryKey"));
             var context = TestUtils.CreateTestContext();
 
             await store.SetAsync(
@@ -74,13 +90,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             Assert.False(await middleware.TryServeFromCacheAsync(context));
             Assert.Equal(2, store.GetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NoResponseServed);
         }
 
         [Fact]
         public async Task TryServeFromCacheAsync_VaryByRuleFound_CachedResponseFound_Succeeds()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey", new[] { "VaryKey", "VaryKey2" }));
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey", new[] { "VaryKey", "VaryKey2" }));
             var context = TestUtils.CreateTestContext();
 
             await store.SetAsync(
@@ -97,44 +117,83 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             Assert.True(await middleware.TryServeFromCacheAsync(context));
             Assert.Equal(3, store.GetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.CachedResponseServed);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_NotConditionalRequest_Fails()
+        public async Task TryServeFromCacheAsync_CachedResponseFound_Serves304IfPossible()
         {
+            var store = new TestResponseCacheStore();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store, keyProvider: new TestResponseCacheKeyProvider("BaseKey"));
             var context = TestUtils.CreateTestContext();
+            context.HttpContext.Request.Headers[HeaderNames.IfNoneMatch] = "*";
+
+            await store.SetAsync(
+                "BaseKey",
+                new CachedResponse()
+                {
+                    Body = new SegmentReadStream(new List<byte[]>(0), 0)
+                },
+                TimeSpan.Zero);
+
+            Assert.True(await middleware.TryServeFromCacheAsync(context));
+            Assert.Equal(1, store.GetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NotModifiedServed);
+        }
+
+        [Fact]
+        public void ContentIsNotModified_NotConditionalRequest_False()
+        {
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
-            Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_IfUnmodifiedSince_FallsbackToDateHeader()
+        public void ContentIsNotModified_IfUnmodifiedSince_FallsbackToDateHeader()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
             context.TypedRequestHeaders.IfUnmodifiedSince = utcNow;
 
             // Verify modifications in the past succeeds
             context.CachedResponseHeaders.Date = utcNow - TimeSpan.FromSeconds(10);
-            Assert.True(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.True(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Equal(1, sink.Writes.Count);
 
             // Verify modifications at present succeeds
             context.CachedResponseHeaders.Date = utcNow;
-            Assert.True(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.True(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Equal(2, sink.Writes.Count);
 
             // Verify modifications in the future fails
             context.CachedResponseHeaders.Date = utcNow + TimeSpan.FromSeconds(10);
-            Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context));
+
+            // Verify logging
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NotModifiedIfUnmodifiedSinceSatisfied,
+                LoggedMessage.NotModifiedIfUnmodifiedSinceSatisfied);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_IfUnmodifiedSince_LastModifiedOverridesDateHeader()
+        public void ContentIsNotModified_IfUnmodifiedSince_LastModifiedOverridesDateHeader()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
             context.TypedRequestHeaders.IfUnmodifiedSince = utcNow;
@@ -142,24 +201,33 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             // Verify modifications in the past succeeds
             context.CachedResponseHeaders.Date = utcNow + TimeSpan.FromSeconds(10);
             context.CachedResponseHeaders.LastModified = utcNow - TimeSpan.FromSeconds(10);
-            Assert.True(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.True(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Equal(1, sink.Writes.Count);
 
             // Verify modifications at present
             context.CachedResponseHeaders.Date = utcNow + TimeSpan.FromSeconds(10);
             context.CachedResponseHeaders.LastModified = utcNow;
-            Assert.True(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.True(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Equal(2, sink.Writes.Count);
 
             // Verify modifications in the future fails
             context.CachedResponseHeaders.Date = utcNow - TimeSpan.FromSeconds(10);
             context.CachedResponseHeaders.LastModified = utcNow + TimeSpan.FromSeconds(10);
-            Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context));
+
+            // Verify logging
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NotModifiedIfUnmodifiedSinceSatisfied,
+                LoggedMessage.NotModifiedIfUnmodifiedSinceSatisfied);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_IfNoneMatch_Overrides_IfUnmodifiedSince_ToPass()
+        public void ContentIsNotModified_IfNoneMatch_Overrides_IfUnmodifiedSince_ToTrue()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
             // This would fail the IfUnmodifiedSince checks
@@ -167,14 +235,18 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedResponseHeaders.LastModified = utcNow + TimeSpan.FromSeconds(10);
 
             context.TypedRequestHeaders.IfNoneMatch = new List<EntityTagHeaderValue>(new[] { EntityTagHeaderValue.Any });
-            Assert.True(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.True(ResponseCacheMiddleware.ContentIsNotModified(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NotModifiedIfNoneMatchStar);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_IfNoneMatch_Overrides_IfUnmodifiedSince_ToFail()
+        public void ContentIsNotModified_IfNoneMatch_Overrides_IfUnmodifiedSince_ToFalse()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
             // This would pass the IfUnmodifiedSince checks
@@ -182,18 +254,21 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedResponseHeaders.LastModified = utcNow - TimeSpan.FromSeconds(10);
 
             context.TypedRequestHeaders.IfNoneMatch = new List<EntityTagHeaderValue>(new[] { new EntityTagHeaderValue("\"E1\"") });
-            Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_IfNoneMatch_AnyWithoutETagInResponse_Passes()
+        public void ContentIsNotModified_IfNoneMatch_AnyWithoutETagInResponse_False()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
             context.TypedRequestHeaders.IfNoneMatch = new List<EntityTagHeaderValue>(new[] { new EntityTagHeaderValue("\"E1\"") });
 
-            Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Empty(sink.Writes);
         }
 
         public static TheoryData<EntityTagHeaderValue, EntityTagHeaderValue> EquivalentWeakETags
@@ -212,9 +287,10 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
         [Theory]
         [MemberData(nameof(EquivalentWeakETags))]
-        public void ConditionalRequestSatisfied_IfNoneMatch_ExplicitWithMatch_Passes(EntityTagHeaderValue responseETag, EntityTagHeaderValue requestETag)
+        public void  ContentIsNotModified_IfNoneMatch_ExplicitWithMatch_True(EntityTagHeaderValue responseETag, EntityTagHeaderValue requestETag)
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
             {
                 ETag = responseETag
@@ -222,13 +298,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             context.TypedRequestHeaders.IfNoneMatch = new List<EntityTagHeaderValue>(new[] { requestETag });
 
-            Assert.True(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.True(ResponseCacheMiddleware.ContentIsNotModified(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NotModifiedIfNoneMatchMatched);
         }
 
         [Fact]
-        public void ConditionalRequestSatisfied_IfNoneMatch_ExplicitWithoutMatch_Fails()
+        public void ContentIsNotModified_IfNoneMatch_ExplicitWithoutMatch_False()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
             {
                 ETag = new EntityTagHeaderValue("\"E2\"")
@@ -236,13 +316,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             context.TypedRequestHeaders.IfNoneMatch = new List<EntityTagHeaderValue>(new[] { new EntityTagHeaderValue("\"E1\"") });
 
-            Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context));
+            Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_DoNotUpdateShouldCacheResponse_IfResponseIsNotCacheable()
         {
-            var middleware = TestUtils.CreateTestMiddleware(policyProvider: new ResponseCachePolicyProvider());
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, policyProvider: new ResponseCachePolicyProvider());
             var context = TestUtils.CreateTestContext();
 
             Assert.False(context.ShouldCacheResponse);
@@ -251,12 +333,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.False(context.ShouldCacheResponse);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_UpdateShouldCacheResponse_IfResponseIsCacheable()
         {
-            var middleware = TestUtils.CreateTestMiddleware(policyProvider: new ResponseCachePolicyProvider());
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, policyProvider: new ResponseCachePolicyProvider());
             var context = TestUtils.CreateTestContext();
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -268,24 +352,28 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.True(context.ShouldCacheResponse);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_DefaultResponseValidity_Is10Seconds()
         {
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
 
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(TimeSpan.FromSeconds(10), context.CachedResponseValidFor);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_ResponseValidity_UseExpiryIfAvailable()
         {
             var utcNow = DateTimeOffset.MinValue;
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
 
             context.ResponseTime = utcNow;
@@ -294,12 +382,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(TimeSpan.FromSeconds(11), context.CachedResponseValidFor);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_ResponseValidity_UseMaxAgeIfAvailable()
         {
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -311,12 +401,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(TimeSpan.FromSeconds(12), context.CachedResponseValidFor);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_ResponseValidity_UseSharedMaxAgeIfAvailable()
         {
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -329,13 +421,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(TimeSpan.FromSeconds(13), context.CachedResponseValidFor);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_UpdateCachedVaryByRules_IfNotEquivalentToPrevious()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store);
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
             var context = TestUtils.CreateTestContext();
 
             context.HttpContext.Response.Headers[HeaderNames.Vary] = new StringValues(new[] { "headerA", "HEADERB", "HEADERc" });
@@ -353,13 +447,18 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
             Assert.Equal(1, store.SetCount);
             Assert.NotSame(cachedVaryByRules, context.CachedVaryByRules);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NoResponseServed,
+                LoggedMessage.VaryByRulesUpdated);
         }
 
         [Fact]
-        public async Task FinalizeCacheHeaders_DoNotUpdateCachedVaryByRules_IfEquivalentToPrevious()
+        public async Task FinalizeCacheHeaders_UpdateCachedVaryByRules_IfEquivalentToPrevious()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store);
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
             var context = TestUtils.CreateTestContext();
 
             context.HttpContext.Response.Headers[HeaderNames.Vary] = new StringValues(new[] { "headerA", "HEADERB" });
@@ -379,13 +478,18 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             // An update to the cache is always made but the entry should be the same
             Assert.Equal(1, store.SetCount);
             Assert.Same(cachedVaryByRules, context.CachedVaryByRules);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NoResponseServed,
+                LoggedMessage.VaryByRulesUpdated);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_DoNotAddDate_IfSpecified()
         {
             var utcNow = DateTimeOffset.MinValue;
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
             context.ResponseTime = utcNow;
 
@@ -394,13 +498,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(utcNow, context.TypedResponseHeaders.Date);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_AddsDate_IfNoneSpecified()
         {
             var utcNow = DateTimeOffset.MinValue;
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
             context.TypedResponseHeaders.Date = utcNow;
             context.ResponseTime = utcNow + TimeSpan.FromSeconds(10);
@@ -410,12 +516,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(utcNow, context.TypedResponseHeaders.Date);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_StoresCachedResponse_InState()
         {
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
 
             Assert.Null(context.CachedResponse);
@@ -423,12 +531,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.NotNull(context.CachedResponse);
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public async Task FinalizeCacheHeaders_SplitsVaryHeaderByCommas()
         {
-            var middleware = TestUtils.CreateTestMiddleware();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink);
             var context = TestUtils.CreateTestContext();
             context.HttpContext.Response.Headers[HeaderNames.Vary] = "HeaderB, heaDera";
 
@@ -436,13 +546,18 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheHeadersAsync(context);
 
             Assert.Equal(new StringValues(new[] { "HEADERA", "HEADERB" }), context.CachedVaryByRules.Headers);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.NoResponseServed,
+                LoggedMessage.VaryByRulesUpdated);
         }
 
         [Fact]
         public async Task FinalizeCacheBody_Cache_IfContentLengthMatches()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store);
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
             var context = TestUtils.CreateTestContext();
 
             middleware.ShimResponseStream(context);
@@ -457,13 +572,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheBodyAsync(context);
 
             Assert.Equal(1, store.SetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseCached);
         }
 
         [Fact]
         public async Task FinalizeCacheBody_DoNotCache_IfContentLengthMismatches()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store);
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
             var context = TestUtils.CreateTestContext();
 
             middleware.ShimResponseStream(context);
@@ -478,13 +597,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheBodyAsync(context);
 
             Assert.Equal(0, store.SetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseContentLengthMismatchNotCached);
         }
 
         [Fact]
         public async Task FinalizeCacheBody_Cache_IfContentLengthAbsent()
         {
             var store = new TestResponseCacheStore();
-            var middleware = TestUtils.CreateTestMiddleware(store);
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
             var context = TestUtils.CreateTestContext();
 
             middleware.ShimResponseStream(context);
@@ -498,6 +621,52 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             await middleware.FinalizeCacheBodyAsync(context);
 
             Assert.Equal(1, store.SetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseCached);
+        }
+
+        [Fact]
+        public async Task FinalizeCacheBody_DoNotCache_IfShouldCacheResponseFalse()
+        {
+            var store = new TestResponseCacheStore();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
+            var context = TestUtils.CreateTestContext();
+
+            middleware.ShimResponseStream(context);
+            await context.HttpContext.Response.WriteAsync(new string('0', 10));
+
+            context.ShouldCacheResponse = false;
+
+            await middleware.FinalizeCacheBodyAsync(context);
+
+            Assert.Equal(0, store.SetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseNotCached);
+        }
+
+        [Fact]
+        public async Task FinalizeCacheBody_DoNotCache_IfBufferingDisabled()
+        {
+            var store = new TestResponseCacheStore();
+            var sink = new TestSink();
+            var middleware = TestUtils.CreateTestMiddleware(testSink: sink, store: store);
+            var context = TestUtils.CreateTestContext();
+
+            middleware.ShimResponseStream(context);
+            await context.HttpContext.Response.WriteAsync(new string('0', 10));
+
+            context.ShouldCacheResponse = true;
+            context.ResponseCacheStream.DisableBuffering();
+
+            await middleware.FinalizeCacheBodyAsync(context);
+
+            Assert.Equal(0, store.SetCount);
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseNotCached);
         }
 
         [Fact]

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

@@ -5,8 +5,10 @@ using System;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Headers;
 using Microsoft.AspNetCore.ResponseCaching.Internal;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Net.Http.Headers;
 using Xunit;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.ResponseCaching.Tests
 {
@@ -28,10 +30,12 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
         [MemberData(nameof(CacheableMethods))]
         public void IsRequestCacheable_CacheableMethods_Allowed(string method)
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = method;
 
             Assert.True(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            Assert.Empty(sink.Writes);
         }
         public static TheoryData<string> NonCacheableMethods
         {
@@ -55,26 +59,35 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
         [MemberData(nameof(NonCacheableMethods))]
         public void IsRequestCacheable_UncacheableMethods_NotAllowed(string method)
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = method;
 
             Assert.False(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.RequestMethodNotCacheable);
         }
 
         [Fact]
         public void IsRequestCacheable_AuthorizationHeaders_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = HttpMethods.Get;
             context.HttpContext.Request.Headers[HeaderNames.Authorization] = "Basic plaintextUN:plaintextPW";
 
             Assert.False(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.RequestWithAuthorizationNotCacheable);
         }
 
         [Fact]
         public void IsRequestCacheable_NoCache_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = HttpMethods.Get;
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -82,12 +95,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.RequestWithNoCacheNotCacheable);
         }
 
         [Fact]
         public void IsRequestCacheable_NoStore_Allowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = HttpMethods.Get;
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -95,53 +112,67 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.True(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsRequestCacheable_LegacyDirectives_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = HttpMethods.Get;
             context.HttpContext.Request.Headers[HeaderNames.Pragma] = "no-cache";
 
             Assert.False(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.RequestWithPragmaNoCacheNotCacheable);
         }
 
         [Fact]
         public void IsRequestCacheable_LegacyDirectives_OverridenByCacheControl()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Request.Method = HttpMethods.Get;
             context.HttpContext.Request.Headers[HeaderNames.Pragma] = "no-cache";
             context.HttpContext.Request.Headers[HeaderNames.CacheControl] = "max-age=10";
 
             Assert.True(new ResponseCachePolicyProvider().IsRequestCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsResponseCacheable_NoPublic_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithoutPublicNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_Public_Allowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 Public = true
             };
 
             Assert.True(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsResponseCacheable_NoCache_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 Public = true,
@@ -149,12 +180,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithNoCacheNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_RequestNoStore_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 NoStore = true
@@ -165,12 +200,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithNoStoreNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_ResponseNoStore_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 Public = true,
@@ -178,12 +217,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithNoStoreNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_SetCookieHeader_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 Public = true
@@ -191,12 +234,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.HttpContext.Response.Headers[HeaderNames.SetCookie] = "cookieName=cookieValue";
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithSetCookieNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_VaryHeaderByStar_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 Public = true
@@ -204,12 +251,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.HttpContext.Response.Headers[HeaderNames.Vary] = "*";
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithVaryStarNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_Private_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 Public = true,
@@ -217,13 +268,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithPrivateNotCacheable);
         }
 
         [Theory]
         [InlineData(StatusCodes.Status200OK)]
         public void IsResponseCacheable_SuccessStatusCodes_Allowed(int statusCode)
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = statusCode;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -231,6 +286,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.True(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Theory]
@@ -284,7 +340,8 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
         [InlineData(StatusCodes.Status507InsufficientStorage)]
         public void IsResponseCacheable_NonSuccessStatusCodes_NotAllowed(int statusCode)
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = statusCode;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -292,12 +349,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ResponseWithUnsuccessfulStatusCodeNotCacheable);
         }
 
         [Fact]
         public void IsResponseCacheable_NoExpiryRequirements_IsAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -309,12 +370,14 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.ResponseTime = DateTimeOffset.MaxValue;
 
             Assert.True(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsResponseCacheable_AtExpiry_NotAllowed()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -327,13 +390,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.ResponseTime = utcNow;
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationExpiresExceeded);
         }
 
         [Fact]
         public void IsResponseCacheable_MaxAgeOverridesExpiry_ToAllowed()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -345,13 +412,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.ResponseTime = utcNow + TimeSpan.FromSeconds(9);
 
             Assert.True(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsResponseCacheable_MaxAgeOverridesExpiry_ToNotAllowed()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -363,13 +432,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.ResponseTime = utcNow + TimeSpan.FromSeconds(10);
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMaxAgeExceeded);
         }
 
         [Fact]
         public void IsResponseCacheable_SharedMaxAgeOverridesMaxAge_ToAllowed()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -381,13 +454,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.ResponseTime = utcNow + TimeSpan.FromSeconds(11);
 
             Assert.True(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsResponseCacheable_SharedMaxAgeOverridesMaxAge_ToNotAllowed()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.HttpContext.Response.StatusCode = StatusCodes.Status200OK;
             context.TypedResponseHeaders.CacheControl = new CacheControlHeaderValue()
             {
@@ -399,25 +474,31 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.ResponseTime = utcNow + TimeSpan.FromSeconds(5);
 
             Assert.False(new ResponseCachePolicyProvider().IsResponseCacheable(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationSharedMaxAgeExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_NoCachedCacheControl_FallsbackToEmptyCacheControl()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.ResponseTime = DateTimeOffset.MaxValue;
             context.CachedEntryAge = TimeSpan.MaxValue;
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary());
 
             Assert.True(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsCachedEntryFresh_NoExpiryRequirements_IsFresh()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.ResponseTime = DateTimeOffset.MaxValue;
             context.CachedEntryAge = TimeSpan.MaxValue;
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
@@ -429,13 +510,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.True(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsCachedEntryFresh_AtExpiry_IsNotFresh()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.ResponseTime = utcNow;
             context.CachedEntryAge = TimeSpan.Zero;
             context.CachedResponseHeaders =  new ResponseHeaders(new HeaderDictionary())
@@ -448,13 +531,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationExpiresExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_MaxAgeOverridesExpiry_ToFresh()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedEntryAge = TimeSpan.FromSeconds(9);
             context.ResponseTime = utcNow + context.CachedEntryAge;
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
@@ -468,13 +555,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.True(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsCachedEntryFresh_MaxAgeOverridesExpiry_ToNotFresh()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedEntryAge = TimeSpan.FromSeconds(10);
             context.ResponseTime = utcNow + context.CachedEntryAge;
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
@@ -488,13 +577,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMaxAgeExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_SharedMaxAgeOverridesMaxAge_ToFresh()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedEntryAge = TimeSpan.FromSeconds(11);
             context.ResponseTime = utcNow + context.CachedEntryAge;
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
@@ -509,13 +602,15 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.True(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            Assert.Empty(sink.Writes);
         }
 
         [Fact]
         public void IsCachedEntryFresh_SharedMaxAgeOverridesMaxAge_ToNotFresh()
         {
             var utcNow = DateTimeOffset.UtcNow;
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.CachedEntryAge = TimeSpan.FromSeconds(5);
             context.ResponseTime = utcNow + context.CachedEntryAge;
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
@@ -530,12 +625,16 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             };
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationSharedMaxAgeExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_MinFreshReducesFreshness_ToNotFresh()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 MinFresh = TimeSpan.FromSeconds(2)
@@ -551,12 +650,17 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedEntryAge = TimeSpan.FromSeconds(3);
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMinFreshAdded,
+                LoggedMessage.ExpirationSharedMaxAgeExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_RequestMaxAgeRestrictAge_ToNotFresh()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 MaxAge = TimeSpan.FromSeconds(5)
@@ -571,17 +675,21 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedEntryAge = TimeSpan.FromSeconds(5);
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMaxAgeExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_MaxStaleOverridesFreshness_ToFresh()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 MaxAge = TimeSpan.FromSeconds(5),
                 MaxStale = true, // This value must be set to true in order to specify MaxStaleLimit
-                MaxStaleLimit = TimeSpan.FromSeconds(10)
+                MaxStaleLimit = TimeSpan.FromSeconds(2)
             };
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
             {
@@ -593,17 +701,21 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedEntryAge = TimeSpan.FromSeconds(6);
 
             Assert.True(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMaxStaleSatisfied);
         }
 
         [Fact]
         public void IsCachedEntryFresh_MaxStaleOverridesFreshness_ButStillNotFresh()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 MaxAge = TimeSpan.FromSeconds(5),
                 MaxStale = true, // This value must be set to true in order to specify MaxStaleLimit
-                MaxStaleLimit = TimeSpan.FromSeconds(6)
+                MaxStaleLimit = TimeSpan.FromSeconds(1)
             };
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
             {
@@ -615,17 +727,21 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedEntryAge = TimeSpan.FromSeconds(6);
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMaxAgeExceeded);
         }
 
         [Fact]
         public void IsCachedEntryFresh_MustRevalidateOverridesRequestMaxStale_ToNotFresh()
         {
-            var context = TestUtils.CreateTestContext();
+            var sink = new TestSink();
+            var context = TestUtils.CreateTestContext(sink);
             context.TypedRequestHeaders.CacheControl = new CacheControlHeaderValue()
             {
                 MaxAge = TimeSpan.FromSeconds(5),
                 MaxStale = true, // This value must be set to true in order to specify MaxStaleLimit
-                MaxStaleLimit = TimeSpan.FromSeconds(10)
+                MaxStaleLimit = TimeSpan.FromSeconds(2)
             };
             context.CachedResponseHeaders = new ResponseHeaders(new HeaderDictionary())
             {
@@ -638,6 +754,9 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             context.CachedEntryAge = TimeSpan.FromSeconds(6);
 
             Assert.False(new ResponseCachePolicyProvider().IsCachedEntryFresh(context));
+            TestUtils.AssertLoggedMessages(
+                sink.Writes,
+                LoggedMessage.ExpirationMustRevalidate);
         }
     }
 }

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

@@ -12,10 +12,13 @@ using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.ResponseCaching.Internal;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Internal;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.ObjectPool;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 using Microsoft.Net.Http.Headers;
+using Xunit;
 
 namespace Microsoft.AspNetCore.ResponseCaching.Tests
 {
@@ -86,6 +89,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
         internal static ResponseCacheMiddleware CreateTestMiddleware(
             IResponseCacheStore store = null,
             ResponseCacheOptions options = null,
+            TestSink testSink = null,
             IResponseCacheKeyProvider keyProvider = null,
             IResponseCachePolicyProvider policyProvider = null)
         {
@@ -109,6 +113,7 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
             return new ResponseCacheMiddleware(
                 httpContext => TaskCache.CompletedTask,
                 Options.Create(options),
+                testSink == null ? (ILoggerFactory)NullLoggerFactory.Instance : new TestLoggerFactory(testSink, true),
                 policyProvider,
                 store,
                 keyProvider);
@@ -116,11 +121,70 @@ namespace Microsoft.AspNetCore.ResponseCaching.Tests
 
         internal static ResponseCacheContext CreateTestContext()
         {
-            return new ResponseCacheContext(new DefaultHttpContext())
+            return new ResponseCacheContext(new DefaultHttpContext(), NullLogger.Instance)
             {
                 ResponseTime = DateTimeOffset.UtcNow
             };
         }
+
+        internal static ResponseCacheContext CreateTestContext(ITestSink testSink)
+        {
+            return new ResponseCacheContext(new DefaultHttpContext(), new TestLogger("ResponseCachingTests", testSink, true))
+            {
+                ResponseTime = DateTimeOffset.UtcNow
+            };
+        }
+
+        internal static void AssertLoggedMessages(List<WriteContext> messages, params LoggedMessage[] expectedMessages)
+        {
+            Assert.Equal(messages.Count, expectedMessages.Length);
+            for (var i = 0; i < messages.Count; i++)
+            {
+                Assert.Equal(expectedMessages[i].EventId, messages[i].EventId);
+                Assert.Equal(expectedMessages[i].LogLevel, messages[i].LogLevel);
+            }
+        }
+    }
+
+    internal class LoggedMessage
+    {
+        internal static LoggedMessage RequestMethodNotCacheable => new LoggedMessage(1, LogLevel.Debug);
+        internal static LoggedMessage RequestWithAuthorizationNotCacheable => new LoggedMessage(2, LogLevel.Debug);
+        internal static LoggedMessage RequestWithNoCacheNotCacheable => new LoggedMessage(3, LogLevel.Debug);
+        internal static LoggedMessage RequestWithPragmaNoCacheNotCacheable => new LoggedMessage(4, LogLevel.Debug);
+        internal static LoggedMessage ExpirationMinFreshAdded => new LoggedMessage(5, LogLevel.Debug);
+        internal static LoggedMessage ExpirationSharedMaxAgeExceeded => new LoggedMessage(6, LogLevel.Debug);
+        internal static LoggedMessage ExpirationMustRevalidate => new LoggedMessage(7, LogLevel.Debug);
+        internal static LoggedMessage ExpirationMaxStaleSatisfied => new LoggedMessage(8, LogLevel.Debug);
+        internal static LoggedMessage ExpirationMaxAgeExceeded => new LoggedMessage(9, LogLevel.Debug);
+        internal static LoggedMessage ExpirationExpiresExceeded => new LoggedMessage(10, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithoutPublicNotCacheable => new LoggedMessage(11, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithNoStoreNotCacheable => new LoggedMessage(12, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithNoCacheNotCacheable => new LoggedMessage(13, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithSetCookieNotCacheable => new LoggedMessage(14, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithVaryStarNotCacheable => new LoggedMessage(15, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithPrivateNotCacheable => new LoggedMessage(16, LogLevel.Debug);
+        internal static LoggedMessage ResponseWithUnsuccessfulStatusCodeNotCacheable => new LoggedMessage(17, LogLevel.Debug);
+        internal static LoggedMessage NotModifiedIfNoneMatchStar => new LoggedMessage(18, LogLevel.Debug);
+        internal static LoggedMessage NotModifiedIfNoneMatchMatched => new LoggedMessage(19, LogLevel.Debug);
+        internal static LoggedMessage NotModifiedIfUnmodifiedSinceSatisfied => new LoggedMessage(20, LogLevel.Debug);
+        internal static LoggedMessage NotModifiedServed => new LoggedMessage(21, LogLevel.Information);
+        internal static LoggedMessage CachedResponseServed => new LoggedMessage(22, LogLevel.Information);
+        internal static LoggedMessage GatewayTimeoutServed => new LoggedMessage(23, LogLevel.Information);
+        internal static LoggedMessage NoResponseServed => new LoggedMessage(24, LogLevel.Information);
+        internal static LoggedMessage VaryByRulesUpdated => new LoggedMessage(25, LogLevel.Debug);
+        internal static LoggedMessage ResponseCached => new LoggedMessage(26, LogLevel.Information);
+        internal static LoggedMessage ResponseNotCached => new LoggedMessage(27, LogLevel.Information);
+        internal static LoggedMessage ResponseContentLengthMismatchNotCached => new LoggedMessage(28, LogLevel.Warning);
+
+        private LoggedMessage(int evenId, LogLevel logLevel)
+        {
+            EventId = evenId;
+            LogLevel = logLevel;
+        }
+
+        internal int EventId { get; }
+        internal LogLevel LogLevel { get; }
     }
 
     internal class DummySendFileFeature : IHttpSendFileFeature

test/Microsoft.AspNetCore.ResponseCaching.Tests/project.json

@@ -7,6 +7,7 @@
     "dotnet-test-xunit": "2.2.0-*",
     "Microsoft.AspNetCore.ResponseCaching": "0.1.0-*",
     "Microsoft.AspNetCore.TestHost": "1.1.0-*",
+    "Microsoft.Extensions.Logging.Testing": "1.1.0-*",
     "xunit": "2.2.0-*"
   },
   "frameworks": {