diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/AsyncCachingExec.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/AsyncCachingExec.java index 104ca7593..36aedaa5e 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/AsyncCachingExec.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/AsyncCachingExec.java @@ -238,7 +238,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH final AsyncExecChain.Scope scope, final AsyncExecChain chain, final InternalCallback asyncExecCallback) throws HttpException, IOException { - log.trace("Calling the backend"); + log.debug("Calling the backend"); final Date requestDate = getCurrentDate(); chain.proceed(request, entityProducer, scope, new AsyncExecCallback() { @@ -253,7 +253,6 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH final Date responseDate = getCurrentDate(); backendResponse.addHeader("Via", generateViaHeader(backendResponse)); - log.trace("Handling Backend response"); responseCompliance.ensureProtocolCompliance(scope.originalRequest, request, backendResponse); final boolean cacheable = asyncExecCallback.cacheResponse(backendResponse) @@ -265,6 +264,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH bufferRef.set(new ByteArrayBuffer(1024)); } } else { + log.debug("Backend response is not cacheable"); try { responseCache.flushCacheEntriesFor(target, request); } catch (final IOException ioe) { @@ -272,10 +272,12 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH } } if (bufferRef.get() != null) { + log.debug("Caching backend response"); if (entityDetails == null) { scope.execRuntime.releaseConnection(); final HttpCacheEntry entry = responseCache.createCacheEntry( target, request, backendResponse, null, requestDate, responseDate); + log.debug("Backend response successfully cached"); responseRef.set(responseGenerator.generateResponse(request, entry)); return null; } else { @@ -303,6 +305,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH } } if (buffer.length() > cacheConfig.getMaxObjectSize()) { + log.debug("Backend response content length exceeds maximum"); // Over the max limit. Stop buffering and forward the response // along with all the data buffered so far to the caller. bufferRef.set(null); @@ -339,6 +342,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH if (buffer != null) { final HttpCacheEntry entry = responseCache.createCacheEntry( target, request, backendResponse, buffer, requestDate, responseDate); + log.debug("Backend response successfully cached"); responseRef.set(responseGenerator.generateResponse(request, entry)); } } diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheInvalidator.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheInvalidator.java index 9ba1fc46b..09638c9cb 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheInvalidator.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheInvalidator.java @@ -64,13 +64,13 @@ class CacheInvalidator implements HttpCacheInvalidator { * Create a new {@link CacheInvalidator} for a given {@link HttpCache} and * {@link CacheKeyGenerator}. * - * @param uriExtractor Provides identifiers for the keys to store cache entries + * @param cacheKeyGenerator Provides identifiers for the keys to store cache entries * @param storage the cache to store items away in */ public CacheInvalidator( - final CacheKeyGenerator uriExtractor, + final CacheKeyGenerator cacheKeyGenerator, final HttpCacheStorage storage) { - this.cacheKeyGenerator = uriExtractor; + this.cacheKeyGenerator = cacheKeyGenerator; this.storage = storage; } @@ -83,18 +83,20 @@ class CacheInvalidator implements HttpCacheInvalidator { */ @Override public void flushInvalidatedCacheEntries(final HttpHost host, final HttpRequest req) { - final String theUri = cacheKeyGenerator.generateKey(host, req); - final HttpCacheEntry parent = getEntry(theUri); + final String key = cacheKeyGenerator.generateKey(host, req); + final HttpCacheEntry parent = getEntry(key); if (requestShouldNotBeCached(req) || shouldInvalidateHeadCacheEntry(req, parent)) { - log.debug("Invalidating parent cache entry: " + parent); + if (log.isDebugEnabled()) { + log.debug("Invalidating parent cache entry: " + parent); + } if (parent != null) { for (final String variantURI : parent.getVariantMap().values()) { flushEntry(variantURI); } - flushEntry(theUri); + flushEntry(key); } - final URL reqURL = getAbsoluteURL(theUri); + final URL reqURL = getAbsoluteURL(key); if (reqURL == null) { log.error("Couldn't transform request into valid URL"); return; diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheableRequestPolicy.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheableRequestPolicy.java index b22c54e58..e1d0a6986 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheableRequestPolicy.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheableRequestPolicy.java @@ -61,37 +61,34 @@ class CacheableRequestPolicy { final ProtocolVersion pv = request.getVersion() != null ? request.getVersion() : HttpVersion.DEFAULT; if (HttpVersion.HTTP_1_1.compareToVersion(pv) != 0) { - log.trace("non-HTTP/1.1 request was not serveable from cache"); + log.debug("non-HTTP/1.1 request is not serveable from cache"); return false; } - if (!(method.equals(HeaderConstants.GET_METHOD) || method - .equals(HeaderConstants.HEAD_METHOD))) { - log.trace("non-GET or non-HEAD request was not serveable from cache"); + if (!method.equals(HeaderConstants.GET_METHOD) && !method.equals(HeaderConstants.HEAD_METHOD)) { + log.debug(method + " request is not serveable from cache"); return false; } - if (request.getHeaders(HeaderConstants.PRAGMA).length > 0) { - log.trace("request with Pragma header was not serveable from cache"); + if (request.containsHeaders(HeaderConstants.PRAGMA) > 0) { + log.debug("request with Pragma header is not serveable from cache"); return false; } final Iterator it = MessageSupport.iterate(request, HeaderConstants.CACHE_CONTROL); while (it.hasNext()) { final HeaderElement cacheControlElement = it.next(); - if (HeaderConstants.CACHE_CONTROL_NO_STORE.equalsIgnoreCase(cacheControlElement - .getName())) { - log.trace("Request with no-store was not serveable from cache"); + if (HeaderConstants.CACHE_CONTROL_NO_STORE.equalsIgnoreCase(cacheControlElement.getName())) { + log.debug("Request with no-store is not serveable from cache"); return false; } - if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equalsIgnoreCase(cacheControlElement - .getName())) { - log.trace("Request with no-cache was not serveable from cache"); + if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equalsIgnoreCase(cacheControlElement.getName())) { + log.debug("Request with no-cache is not serveable from cache"); return false; } } - log.trace("Request was serveable from cache"); + log.debug("Request is serveable from cache"); return true; } diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachedResponseSuitabilityChecker.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachedResponseSuitabilityChecker.java index f5dff51de..4754f04a9 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachedResponseSuitabilityChecker.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachedResponseSuitabilityChecker.java @@ -146,7 +146,7 @@ class CachedResponseSuitabilityChecker { */ public boolean canCachedResponseBeUsed(final HttpHost host, final HttpRequest request, final HttpCacheEntry entry, final Date now) { if (!isFreshEnough(entry, request, now)) { - log.trace("Cache entry was not fresh enough"); + log.debug("Cache entry is not fresh enough"); return false; } @@ -156,15 +156,17 @@ class CachedResponseSuitabilityChecker { } if (hasUnsupportedConditionalHeaders(request)) { - log.debug("Request contained conditional headers we don't handle"); + log.debug("Request contains unsupported conditional headers"); return false; } if (!isConditional(request) && entry.getStatus() == HttpStatus.SC_NOT_MODIFIED) { + log.debug("Unconditional request and non-modified cached response"); return false; } if (isConditional(request) && !allConditionalsMatch(request, entry, now)) { + log.debug("Conditional request and with mismatched conditions"); return false; } @@ -177,12 +179,12 @@ class CachedResponseSuitabilityChecker { while (it.hasNext()) { final HeaderElement elt = it.next(); if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equals(elt.getName())) { - log.trace("Response contained NO CACHE directive, cache was not suitable"); + log.debug("Response contained NO CACHE directive, cache was not suitable"); return false; } if (HeaderConstants.CACHE_CONTROL_NO_STORE.equals(elt.getName())) { - log.trace("Response contained NO STORE directive, cache was not suitable"); + log.debug("Response contained NO STORE directive, cache was not suitable"); return false; } @@ -190,7 +192,7 @@ class CachedResponseSuitabilityChecker { try { final int maxage = Integer.parseInt(elt.getValue()); if (validityStrategy.getCurrentAgeSecs(entry, now) > maxage) { - log.trace("Response from cache was NOT suitable due to max age"); + log.debug("Response from cache was NOT suitable due to max age"); return false; } } catch (final NumberFormatException ex) { @@ -204,7 +206,7 @@ class CachedResponseSuitabilityChecker { try { final int maxstale = Integer.parseInt(elt.getValue()); if (validityStrategy.getFreshnessLifetimeSecs(entry) > maxstale) { - log.trace("Response from cache was not suitable due to Max stale freshness"); + log.debug("Response from cache was not suitable due to Max stale freshness"); return false; } } catch (final NumberFormatException ex) { @@ -223,7 +225,7 @@ class CachedResponseSuitabilityChecker { final long age = validityStrategy.getCurrentAgeSecs(entry, now); final long freshness = validityStrategy.getFreshnessLifetimeSecs(entry); if (freshness - age < minfresh) { - log.trace("Response from cache was not suitable due to min fresh " + + log.debug("Response from cache was not suitable due to min fresh " + "freshness requirement"); return false; } @@ -235,7 +237,7 @@ class CachedResponseSuitabilityChecker { } } - log.trace("Response from cache was suitable"); + log.debug("Response from cache was suitable"); return true; } diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExec.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExec.java index e4b59e471..d5e06c5c8 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExec.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExec.java @@ -213,7 +213,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler { final Date requestDate = getCurrentDate(); - log.trace("Calling the backend"); + log.debug("Calling the backend"); final ClassicHttpResponse backendResponse = chain.proceed(request, scope); try { backendResponse.addHeader("Via", generateViaHeader(backendResponse)); @@ -337,7 +337,6 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler { final Date responseDate, final ClassicHttpResponse backendResponse) throws IOException { - log.trace("Handling Backend response"); responseCompliance.ensureProtocolCompliance(scope.originalRequest, request, backendResponse); final boolean cacheable = responseCachingPolicy.isResponseCacheable(request, backendResponse); @@ -347,6 +346,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler { return cacheAndReturnResponse(target, request, backendResponse, requestDate, responseDate); } if (!cacheable) { + log.debug("Backend response is not cacheable"); try { responseCache.flushCacheEntriesFor(target, request); } catch (final IOException ioe) { @@ -362,6 +362,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler { final ClassicHttpResponse backendResponse, final Date requestSent, final Date responseReceived) throws IOException { + log.debug("Caching backend response"); final ByteArrayBuffer buf; final HttpEntity entity = backendResponse.getEntity(); if (entity != null) { @@ -374,6 +375,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler { buf.append(tmp, 0, l); total += l; if (total > cacheConfig.getMaxObjectSize()) { + log.debug("Backend response content length exceeds maximum"); backendResponse.setEntity(new CombinedEntity(entity, buf)); return backendResponse; } @@ -383,6 +385,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler { } backendResponse.close(); final HttpCacheEntry entry = responseCache.createCacheEntry(target, request, backendResponse, buf, requestSent, responseReceived); + log.debug("Backend response successfully cached"); return convert(responseGenerator.generateResponse(request, entry)); } diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExecBase.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExecBase.java index 1ab84d666..d823513f0 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExecBase.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExecBase.java @@ -177,21 +177,21 @@ public class CachingExecBase { void recordCacheMiss(final HttpHost target, final HttpRequest request) { cacheMisses.getAndIncrement(); if (log.isTraceEnabled()) { - log.trace("Cache miss [host: " + target + "; uri: " + request.getRequestUri() + "]"); + log.debug("Cache miss [host: " + target + "; uri: " + request.getRequestUri() + "]"); } } void recordCacheHit(final HttpHost target, final HttpRequest request) { cacheHits.getAndIncrement(); if (log.isTraceEnabled()) { - log.trace("Cache hit [host: " + target + "; uri: " + request.getRequestUri() + "]"); + log.debug("Cache hit [host: " + target + "; uri: " + request.getRequestUri() + "]"); } } void recordCacheFailure(final HttpHost target, final HttpRequest request) { cacheMisses.getAndIncrement(); if (log.isTraceEnabled()) { - log.trace("Cache failure [host: " + target + "; uri: " + request.getRequestUri() + "]"); + log.debug("Cache failure [host: " + target + "; uri: " + request.getRequestUri() + "]"); } } @@ -266,7 +266,7 @@ public class CachingExecBase { while (it.hasNext()) { final HeaderElement elt = it.next(); if ("only-if-cached".equals(elt.getName())) { - log.trace("Request marked only-if-cached"); + log.debug("Request marked only-if-cached"); return false; } } diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCachingPolicy.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCachingPolicy.java index 3c4fff92c..37d8a977b 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCachingPolicy.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCachingPolicy.java @@ -60,17 +60,20 @@ class ResponseCachingPolicy { private static final String[] AUTH_CACHEABLE_PARAMS = { "s-maxage", HeaderConstants.CACHE_CONTROL_MUST_REVALIDATE, HeaderConstants.PUBLIC }; + + private final static Set CACHEABLE_STATUS_CODES = + new HashSet<>(Arrays.asList(HttpStatus.SC_OK, + HttpStatus.SC_NON_AUTHORITATIVE_INFORMATION, + HttpStatus.SC_MULTIPLE_CHOICES, + HttpStatus.SC_MOVED_PERMANENTLY, + HttpStatus.SC_GONE)); + + private final Logger log = LogManager.getLogger(getClass()); + private final long maxObjectSizeBytes; private final boolean sharedCache; private final boolean neverCache1_0ResponsesWithQueryString; - private final Logger log = LogManager.getLogger(getClass()); - private static final Set cacheableStatuses = - new HashSet<>(Arrays.asList(HttpStatus.SC_OK, - HttpStatus.SC_NON_AUTHORITATIVE_INFORMATION, - HttpStatus.SC_MULTIPLE_CHOICES, - HttpStatus.SC_MOVED_PERMANENTLY, - HttpStatus.SC_GONE)); - private final Set uncacheableStatuses; + private final Set uncacheableStatusCodes; /** * Define a cache policy that limits the size of things that should be stored @@ -91,11 +94,9 @@ class ResponseCachingPolicy { this.sharedCache = sharedCache; this.neverCache1_0ResponsesWithQueryString = neverCache1_0ResponsesWithQueryString; if (allow303Caching) { - uncacheableStatuses = new HashSet<>( - Arrays.asList(HttpStatus.SC_PARTIAL_CONTENT)); + uncacheableStatusCodes = new HashSet<>(Arrays.asList(HttpStatus.SC_PARTIAL_CONTENT)); } else { - uncacheableStatuses = new HashSet<>(Arrays.asList( - HttpStatus.SC_PARTIAL_CONTENT, HttpStatus.SC_SEE_OTHER)); + uncacheableStatusCodes = new HashSet<>(Arrays.asList(HttpStatus.SC_PARTIAL_CONTENT, HttpStatus.SC_SEE_OTHER)); } } @@ -109,21 +110,28 @@ class ResponseCachingPolicy { public boolean isResponseCacheable(final String httpMethod, final HttpResponse response) { boolean cacheable = false; - if (!(HeaderConstants.GET_METHOD.equals(httpMethod) || - HeaderConstants.HEAD_METHOD.equals(httpMethod))) { - log.debug("Response was not cacheable."); + if (!HeaderConstants.GET_METHOD.equals(httpMethod) && !HeaderConstants.HEAD_METHOD.equals(httpMethod)) { + if (log.isDebugEnabled()) { + log.debug(httpMethod + " method response is not cacheable"); + } return false; } final int status = response.getCode(); - if (cacheableStatuses.contains(status)) { + if (CACHEABLE_STATUS_CODES.contains(status)) { // these response codes MAY be cached cacheable = true; - } else if (uncacheableStatuses.contains(status)) { + } else if (uncacheableStatusCodes.contains(status)) { + if (log.isDebugEnabled()) { + log.debug(status + " response is not cacheable"); + } return false; } else if (unknownStatusCode(status)) { // a response with an unknown status code MUST NOT be // cached + if (log.isDebugEnabled()) { + log.debug(status + " response is unknown"); + } return false; } @@ -131,30 +139,32 @@ class ResponseCachingPolicy { if (contentLength != null) { final long contentLengthValue = Long.parseLong(contentLength.getValue()); if (contentLengthValue > this.maxObjectSizeBytes) { + if (log.isDebugEnabled()) { + log.debug("Response content length exceeds " + this.maxObjectSizeBytes); + } return false; } } - final Header[] ageHeaders = response.getHeaders(HeaderConstants.AGE); - - if (ageHeaders.length > 1) { + if (response.containsHeaders(HeaderConstants.AGE) > 1) { + log.debug("Multiple Age headers"); return false; } - final Header[] expiresHeaders = response.getHeaders(HeaderConstants.EXPIRES); - - if (expiresHeaders.length > 1) { + if (response.containsHeaders(HeaderConstants.EXPIRES) > 1) { + log.debug("Multiple Expires headers"); return false; } - final Header[] dateHeaders = response.getHeaders(HttpHeaders.DATE); - - if (dateHeaders.length != 1) { + if (response.containsHeaders(HttpHeaders.DATE) > 1) { + log.debug("Multiple Date headers"); return false; } - final Date date = DateUtils.parseDate(dateHeaders[0].getValue()); + final Header h = response.getFirstHeader(HttpHeaders.DATE); + final Date date = h != null ? DateUtils.parseDate(h.getValue()) : null; if (date == null) { + log.debug("Invalid / missing Date header"); return false; } @@ -162,15 +172,19 @@ class ResponseCachingPolicy { while (it.hasNext()) { final HeaderElement elem = it.next(); if ("*".equals(elem.getName())) { + if (log.isDebugEnabled()) { + log.debug("Vary * found"); + } return false; } } if (isExplicitlyNonCacheable(response)) { + log.debug("Response is explicitly non-cacheable"); return false; } - return (cacheable || isExplicitlyCacheable(response)); + return cacheable || isExplicitlyCacheable(response); } private boolean unknownStatusCode(final int status) { @@ -239,34 +253,39 @@ class ResponseCachingPolicy { * @return {@code true} if response is cacheable */ public boolean isResponseCacheable(final HttpRequest request, final HttpResponse response) { - if (requestProtocolGreaterThanAccepted(request)) { - log.debug("Response was not cacheable."); + final ProtocolVersion version = request.getVersion() != null ? request.getVersion() : HttpVersion.DEFAULT; + if (version.compareToVersion(HttpVersion.HTTP_1_1) > 0) { + if (log.isDebugEnabled()) { + log.debug("Protocol version " + version + " is non-cacheable"); + } return false; } final String[] uncacheableRequestDirectives = { HeaderConstants.CACHE_CONTROL_NO_STORE }; if (hasCacheControlParameterFrom(request,uncacheableRequestDirectives)) { + log.debug("Response is explcitily non-cacheable per cache control directive"); return false; } if (request.getRequestUri().contains("?")) { if (neverCache1_0ResponsesWithQueryString && from1_0Origin(response)) { - log.debug("Response was not cacheable as it had a query string."); + log.debug("Response is not cacheable as it had a query string"); return false; } else if (!isExplicitlyCacheable(response)) { - log.debug("Response was not cacheable as it is missing explicit caching headers."); + log.debug("Response is not cacheable as it is missing explicit caching headers"); return false; } } if (expiresHeaderLessOrEqualToDateHeaderAndNoCacheControl(response)) { + log.debug("Expires header less or equal to Date header and no cache control directives"); return false; } if (sharedCache) { - final Header[] authNHeaders = request.getHeaders(HeaderConstants.AUTHORIZATION); - if (authNHeaders != null && authNHeaders.length > 0 + if (request.containsHeaders(HeaderConstants.AUTHORIZATION) > 0 && !hasCacheControlParameterFrom(response, AUTH_CACHEABLE_PARAMS)) { + log.debug("Request contains private credentials"); return false; } } @@ -275,8 +294,7 @@ class ResponseCachingPolicy { return isResponseCacheable(method, response); } - private boolean expiresHeaderLessOrEqualToDateHeaderAndNoCacheControl( - final HttpResponse response) { + private boolean expiresHeaderLessOrEqualToDateHeaderAndNoCacheControl(final HttpResponse response) { if (response.getFirstHeader(HeaderConstants.CACHE_CONTROL) != null) { return false; } @@ -308,9 +326,4 @@ class ResponseCachingPolicy { return HttpVersion.HTTP_1_0.equals(version); } - private boolean requestProtocolGreaterThanAccepted(final HttpRequest req) { - final ProtocolVersion version = req.getVersion() != null ? req.getVersion() : HttpVersion.DEFAULT; - return version.compareToVersion(HttpVersion.HTTP_1_1) > 0; - } - }