diff --git a/src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs b/src/Microsoft.AspNetCore.ResponseCaching/Internal/LoggerExtensions.cs new file mode 100644 index 0000000000..b90073179e --- /dev/null +++ b/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 +{ + /// + /// Defines *all* the logger messages produced by response caching + /// + internal static class LoggerExtensions + { + private static Action _logRequestMethodNotCacheable; + private static Action _logRequestWithAuthorizationNotCacheable; + private static Action _logRequestWithNoCacheNotCacheable; + private static Action _logRequestWithPragmaNoCacheNotCacheable; + private static Action _logExpirationMinFreshAdded; + private static Action _logExpirationSharedMaxAgeExceeded; + private static Action _logExpirationMustRevalidate; + private static Action _logExpirationMaxStaleSatisfied; + private static Action _logExpirationMaxAgeExceeded; + private static Action _logExpirationExpiresExceeded; + private static Action _logResponseWithoutPublicNotCacheable; + private static Action _logResponseWithNoStoreNotCacheable; + private static Action _logResponseWithNoCacheNotCacheable; + private static Action _logResponseWithSetCookieNotCacheable; + private static Action _logResponseWithVaryStarNotCacheable; + private static Action _logResponseWithPrivateNotCacheable; + private static Action _logResponseWithUnsuccessfulStatusCodeNotCacheable; + private static Action _logNotModifiedIfNoneMatchStar; + private static Action _logNotModifiedIfNoneMatchMatched; + private static Action _logNotModifiedIfUnmodifiedSinceSatisfied; + private static Action _logNotModifiedServed; + private static Action _logCachedResponseServed; + private static Action _logGatewayTimeoutServed; + private static Action _logNoResponseServed; + private static Action _logVaryByRulesUpdated; + private static Action _logResponseCached; + private static Action _logResponseNotCached; + private static Action _logResponseContentLengthMismatchNotCached; + + static LoggerExtensions() + { + _logRequestMethodNotCacheable = LoggerMessage.Define( + 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( + logLevel: LogLevel.Debug, + eventId: 5, + formatString: "Adding a minimum freshness requirement of {Duration} specified by the 'min-fresh' cache directive."); + _logExpirationSharedMaxAgeExceeded = LoggerMessage.Define( + 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( + 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( + 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( + 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( + 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( + 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( + logLevel: LogLevel.Debug, + eventId: 19, + formatString: $"The ETag {{ETag}} in the '{HeaderNames.IfNoneMatch}' header matched the ETag of a cached entry."); + _logNotModifiedIfUnmodifiedSinceSatisfied = LoggerMessage.Define( + 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( + 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); + } + } +} diff --git a/src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCacheContext.cs b/src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCacheContext.cs index c11ff159f3..5d0f4cc17c 100644 --- a/src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCacheContext.cs +++ b/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( - HttpContext httpContext) + internal ResponseCacheContext(HttpContext httpContext, ILogger logger) { 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; } diff --git a/src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCachePolicyProvider.cs b/src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCachePolicyProvider.cs index ab331ff311..cc7f174a07 100644 --- a/src/Microsoft.AspNetCore.ResponseCaching/Internal/ResponseCachePolicyProvider.cs +++ b/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; } } diff --git a/src/Microsoft.AspNetCore.ResponseCaching/ResponseCacheMiddleware.cs b/src/Microsoft.AspNetCore.ResponseCaching/ResponseCacheMiddleware.cs index 425a291db5..c7939b82c8 100644 --- a/src/Microsoft.AspNetCore.ResponseCaching/ResponseCacheMiddleware.cs +++ b/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 _onStartingCallback; public ResponseCacheMiddleware( RequestDelegate next, IOptions 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(); _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; + } } } diff --git a/src/Microsoft.AspNetCore.ResponseCaching/project.json b/src/Microsoft.AspNetCore.ResponseCaching/project.json index 82a82a25d2..5adf0b7360 100644 --- a/src/Microsoft.AspNetCore.ResponseCaching/project.json +++ b/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" diff --git a/test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCacheMiddlewareTests.cs b/test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCacheMiddlewareTests.cs index 0f7eec6e82..9e251dc9b1 100644 --- a/test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCacheMiddlewareTests.cs +++ b/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(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(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(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(new[] { new EntityTagHeaderValue("\"E1\"") }); - Assert.False(ResponseCacheMiddleware.ConditionalRequestSatisfied(context)); + Assert.False(ResponseCacheMiddleware.ContentIsNotModified(context)); + Assert.Empty(sink.Writes); } public static TheoryData 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(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(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] diff --git a/test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCachePolicyProviderTests.cs b/test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCachePolicyProviderTests.cs index d9a914fda2..2aefdb287e 100644 --- a/test/Microsoft.AspNetCore.ResponseCaching.Tests/ResponseCachePolicyProviderTests.cs +++ b/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 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); } } } diff --git a/test/Microsoft.AspNetCore.ResponseCaching.Tests/TestUtils.cs b/test/Microsoft.AspNetCore.ResponseCaching.Tests/TestUtils.cs index f21912ad77..9b59d61cb6 100644 --- a/test/Microsoft.AspNetCore.ResponseCaching.Tests/TestUtils.cs +++ b/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 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 diff --git a/test/Microsoft.AspNetCore.ResponseCaching.Tests/project.json b/test/Microsoft.AspNetCore.ResponseCaching.Tests/project.json index 16096df8ea..7eefd0a959 100644 --- a/test/Microsoft.AspNetCore.ResponseCaching.Tests/project.json +++ b/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": {