From 67a0b52919a73ae7f5c5383bffc2c63d78dcdffb Mon Sep 17 00:00:00 2001 From: Oleg Kalnichevski Date: Wed, 15 Nov 2023 13:37:26 +0100 Subject: [PATCH] Better debug logging in the caching protocol handlers --- .../http/impl/cache/AsyncCachingExec.java | 177 +++++++++++----- .../impl/cache/CacheControlHeaderParser.java | 2 +- .../impl/cache/CacheableRequestPolicy.java | 12 +- .../CachedResponseSuitabilityChecker.java | 9 + .../client5/http/impl/cache/CachingExec.java | 195 +++++++++++------- .../http/impl/cache/CachingExecBase.java | 12 -- .../http/impl/cache/RequestCacheControl.java | 41 +++- .../http/impl/cache/ResponseCacheControl.java | 58 ++++-- .../cache/TestCacheableRequestPolicy.java | 18 +- .../http/impl/cache/TestCachingExecChain.java | 6 +- 10 files changed, 344 insertions(+), 186 deletions(-) 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 570136bb7..0d7261a01 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 @@ -46,10 +46,8 @@ import org.apache.hc.client5.http.async.AsyncExecChainHandler; import org.apache.hc.client5.http.async.methods.SimpleBody; import org.apache.hc.client5.http.async.methods.SimpleHttpResponse; import org.apache.hc.client5.http.cache.CacheResponseStatus; -import org.apache.hc.client5.http.cache.HttpAsyncCacheStorage; import org.apache.hc.client5.http.cache.HttpCacheContext; import org.apache.hc.client5.http.cache.HttpCacheEntry; -import org.apache.hc.client5.http.cache.ResourceFactory; import org.apache.hc.client5.http.cache.ResourceIOException; import org.apache.hc.client5.http.impl.ExecSupport; import org.apache.hc.client5.http.protocol.HttpClientContext; @@ -69,6 +67,7 @@ import org.apache.hc.core5.http.HttpRequest; import org.apache.hc.core5.http.HttpResponse; import org.apache.hc.core5.http.HttpStatus; import org.apache.hc.core5.http.impl.BasicEntityDetails; +import org.apache.hc.core5.http.message.RequestLine; import org.apache.hc.core5.http.nio.AsyncDataConsumer; import org.apache.hc.core5.http.nio.AsyncEntityProducer; import org.apache.hc.core5.http.nio.CapacityChannel; @@ -117,15 +116,6 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler config); } - AsyncCachingExec( - final ResourceFactory resourceFactory, - final HttpAsyncCacheStorage storage, - final ScheduledExecutorService executorService, - final SchedulingStrategy schedulingStrategy, - final CacheConfig config) { - this(new BasicHttpAsyncCache(resourceFactory, storage), executorService, schedulingStrategy, config); - } - private void triggerResponse( final SimpleHttpResponse cacheResponse, final AsyncExecChain.Scope scope, @@ -245,9 +235,14 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback) throws HttpException, IOException { + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; final CancellableDependency operation = scope.cancellableDependency; + if (LOG.isDebugEnabled()) { + LOG.debug("{} request via cache: {}", exchangeId, new RequestLine(request)); + } + context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MISS); if (clientRequestsOurOptions(request)) { @@ -258,10 +253,10 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final RequestCacheControl requestCacheControl = CacheControlHeaderParser.INSTANCE.parse(request); if (LOG.isDebugEnabled()) { - LOG.debug("Request cache control: {}", requestCacheControl); + LOG.debug("{} request cache control: {}", exchangeId, requestCacheControl); } - if (cacheableRequestPolicy.isServableFromCache(requestCacheControl, request)) { + if (cacheableRequestPolicy.canBeServedFromCache(requestCacheControl, request)) { operation.setDependency(responseCache.match(target, request, new FutureCallback() { @Override @@ -269,12 +264,11 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final CacheHit hit = result != null ? result.hit : null; final CacheHit root = result != null ? result.root : null; if (hit == null) { - LOG.debug("Cache miss"); handleCacheMiss(requestCacheControl, root, target, request, entityProducer, scope, chain, asyncExecCallback); } else { final ResponseCacheControl responseCacheControl = CacheControlHeaderParser.INSTANCE.parse(hit.entry); if (LOG.isDebugEnabled()) { - LOG.debug("Response cache control: {}", responseCacheControl); + LOG.debug("{} response cache control: {}", exchangeId, responseCacheControl); } handleCacheHit(requestCacheControl, responseCacheControl, hit, target, request, entityProducer, scope, chain, asyncExecCallback); } @@ -293,7 +287,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler })); } else { - LOG.debug("Request is not servable from cache"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} request cannot be served from cache", exchangeId); + } callBackend(target, request, entityProducer, scope, chain, asyncExecCallback); } } @@ -318,7 +314,11 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain.Scope scope, final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback) { - LOG.debug("Calling the backend"); + final String exchangeId = scope.exchangeId; + + if (LOG.isDebugEnabled()) { + LOG.debug("{} calling the backend", exchangeId); + } final Instant requestDate = getCurrentDate(); final AtomicReference callbackRef = new AtomicReference<>(); chainProceed(request, entityProducer, scope, chain, new AsyncExecCallback() { @@ -368,6 +368,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler class CachingAsyncDataConsumer implements AsyncDataConsumer { + private final String exchangeId; private final AsyncExecCallback fallback; private final HttpResponse backendResponse; private final EntityDetails entityDetails; @@ -376,9 +377,11 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler private final AtomicReference dataConsumerRef; CachingAsyncDataConsumer( + final String exchangeId, final AsyncExecCallback fallback, final HttpResponse backendResponse, final EntityDetails entityDetails) { + this.exchangeId = exchangeId; this.fallback = fallback; this.backendResponse = backendResponse; this.entityDetails = entityDetails; @@ -409,7 +412,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler } } if (buffer.length() > cacheConfig.getMaxObjectSize()) { - LOG.debug("Backend response content length exceeds maximum"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response content length exceeds maximum", exchangeId); + } // Over the max limit. Stop buffering and forward the response // along with all the data buffered so far to the caller. bufferRef.set(null); @@ -480,6 +485,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler public AsyncDataConsumer handleResponse( final HttpResponse backendResponse, final EntityDetails entityDetails) throws HttpException, IOException { + final String exchangeId = scope.exchangeId; responseCache.evictInvalidatedEntries(target, request, backendResponse, new FutureCallback() { @Override @@ -488,7 +494,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler @Override public void failed(final Exception ex) { - LOG.warn("Unable to flush invalidated entries from cache", ex); + if (LOG.isDebugEnabled()) { + LOG.debug("{} unable to flush invalidated entries from cache", exchangeId, ex); + } } @Override @@ -497,21 +505,27 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler }); if (isResponseTooBig(entityDetails)) { - LOG.debug("Backend response is known to be too big"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response is known to be too big", exchangeId); + } return asyncExecCallback.handleResponse(backendResponse, entityDetails); } final ResponseCacheControl responseCacheControl = CacheControlHeaderParser.INSTANCE.parse(backendResponse); final boolean cacheable = responseCachingPolicy.isResponseCacheable(responseCacheControl, request, backendResponse); if (cacheable) { - cachingConsumerRef.set(new CachingAsyncDataConsumer(asyncExecCallback, backendResponse, entityDetails)); + cachingConsumerRef.set(new CachingAsyncDataConsumer(exchangeId, asyncExecCallback, backendResponse, entityDetails)); storeRequestIfModifiedSinceFor304Response(request, backendResponse); } else { - LOG.debug("Backend response is not cacheable"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response is not cacheable", exchangeId); + } } final CachingAsyncDataConsumer cachingDataConsumer = cachingConsumerRef.get(); if (cachingDataConsumer != null) { - LOG.debug("Caching backend response"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} caching backend response", exchangeId); + } return cachingDataConsumer; } return asyncExecCallback.handleResponse(backendResponse, entityDetails); @@ -523,6 +537,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler } void triggerNewCacheEntryResponse(final HttpResponse backendResponse, final Instant responseDate, final ByteArrayBuffer buffer) { + final String exchangeId = scope.exchangeId; final CancellableDependency operation = scope.cancellableDependency; operation.setDependency(responseCache.store( target, @@ -535,7 +550,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler @Override public void completed(final CacheHit hit) { - LOG.debug("Backend response successfully cached"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response successfully cached", exchangeId); + } try { final SimpleHttpResponse cacheResponse = responseGenerator.generateResponse(request, hit.entry); triggerResponse(cacheResponse, scope, asyncExecCallback); @@ -560,6 +577,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler @Override public void completed() { + final String exchangeId = scope.exchangeId; final CachingAsyncDataConsumer cachingDataConsumer = cachingConsumerRef.getAndSet(null); if (cachingDataConsumer != null && !cachingDataConsumer.writtenThrough.get()) { final ByteArrayBuffer buffer = cachingDataConsumer.bufferRef.getAndSet(null); @@ -572,7 +590,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler public void completed(final CacheMatch result) { final CacheHit hit = result != null ? result.hit : null; if (HttpCacheEntry.isNewer(hit != null ? hit.entry : null, backendResponse)) { - LOG.debug("Backend already contains fresher cache entry"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend already contains fresher cache entry", exchangeId); + } try { final SimpleHttpResponse cacheResponse = responseGenerator.generateResponse(request, hit.entry); triggerResponse(cacheResponse, scope, asyncExecCallback); @@ -621,9 +641,12 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback) { final HttpClientContext context = scope.clientContext; + final String exchangeId = scope.exchangeId; + if (LOG.isDebugEnabled()) { - LOG.debug("Request {} {}: cache hit", request.getMethod(), request.getRequestUri()); + LOG.debug("{} cache hit: {}", exchangeId, new RequestLine(request)); } + context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_HIT); cacheHits.getAndIncrement(); @@ -631,15 +654,20 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final CacheSuitability cacheSuitability = suitabilityChecker.assessSuitability(requestCacheControl, responseCacheControl, request, hit.entry, now); if (LOG.isDebugEnabled()) { - LOG.debug("Request {} {}: {}", request.getMethod(), request.getRequestUri(), cacheSuitability); + LOG.debug("{} cache suitability: {}", exchangeId, cacheSuitability); } if (cacheSuitability == CacheSuitability.FRESH || cacheSuitability == CacheSuitability.FRESH_ENOUGH) { - LOG.debug("Cache hit is suitable"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache hit is fresh enough", exchangeId); + } try { final SimpleHttpResponse cacheResponse = generateCachedResponse(request, hit.entry, now); triggerResponse(cacheResponse, scope, asyncExecCallback); } catch (final ResourceIOException ex) { - if (!mayCallBackend(requestCacheControl)) { + if (requestCacheControl.isOnlyIfCached()) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} request marked only-if-cached", exchangeId); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); final SimpleHttpResponse cacheResponse = generateGatewayTimeout(); triggerResponse(cacheResponse, scope, asyncExecCallback); @@ -653,31 +681,43 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler } } } else { - if (!mayCallBackend(requestCacheControl)) { - LOG.debug("Cache entry not is not fresh and only-if-cached requested"); + if (requestCacheControl.isOnlyIfCached()) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache entry not is not fresh and only-if-cached requested", exchangeId); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); final SimpleHttpResponse cacheResponse = generateGatewayTimeout(); triggerResponse(cacheResponse, scope, asyncExecCallback); } else if (cacheSuitability == CacheSuitability.MISMATCH) { - LOG.debug("Cache entry does not match the request; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache entry does not match the request; calling backend", exchangeId); + } callBackend(target, request, entityProducer, scope, chain, asyncExecCallback); } else if (entityProducer != null && !entityProducer.isRepeatable()) { - LOG.debug("Request is not repeatable; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} request is not repeatable; calling backend", exchangeId); + } callBackend(target, request, entityProducer, scope, chain, asyncExecCallback); } else if (hit.entry.getStatus() == HttpStatus.SC_NOT_MODIFIED && !suitabilityChecker.isConditional(request)) { - LOG.debug("Non-modified cache entry does not match the non-conditional request; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} non-modified cache entry does not match the non-conditional request; calling backend", exchangeId); + } callBackend(target, request, entityProducer, scope, chain, asyncExecCallback); } else if (cacheSuitability == CacheSuitability.REVALIDATION_REQUIRED) { - LOG.debug("Revalidation required; revalidating cache entry"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} revalidation required; revalidating cache entry", exchangeId); + } revalidateCacheEntryWithoutFallback(responseCacheControl, hit, target, request, entityProducer, scope, chain, asyncExecCallback); } else if (cacheSuitability == CacheSuitability.STALE_WHILE_REVALIDATED) { if (cacheRevalidator != null) { - LOG.debug("Serving stale with asynchronous revalidation"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} serving stale with asynchronous revalidation", exchangeId); + } try { - final String exchangeId = ExecSupport.getNextExchangeId(); - context.setExchangeId(exchangeId); + final String revalidationExchangeId = ExecSupport.getNextExchangeId(); + context.setExchangeId(revalidationExchangeId); final AsyncExecChain.Scope fork = new AsyncExecChain.Scope( - exchangeId, + revalidationExchangeId, scope.route, scope.originalRequest, new ComplexFuture<>(null), @@ -685,6 +725,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler scope.execRuntime.fork(), scope.scheduler, scope.execCount); + if (LOG.isDebugEnabled()) { + LOG.debug("{} starting asynchronous revalidation exchange {}", exchangeId, revalidationExchangeId); + } cacheRevalidator.revalidateCacheEntry( hit.getEntryKey(), asyncExecCallback, @@ -696,14 +739,20 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler asyncExecCallback.failed(ex); } } else { - LOG.debug("Revalidating stale cache entry (asynchronous revalidation disabled)"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} revalidating stale cache entry (asynchronous revalidation disabled)", exchangeId); + } revalidateCacheEntryWithFallback(requestCacheControl, responseCacheControl, hit, target, request, entityProducer, scope, chain, asyncExecCallback); } } else if (cacheSuitability == CacheSuitability.STALE) { - LOG.debug("Revalidating stale cache entry"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} revalidating stale cache entry", exchangeId); + } revalidateCacheEntryWithFallback(requestCacheControl, responseCacheControl, hit, target, request, entityProducer, scope, chain, asyncExecCallback); } else { - LOG.debug("Cache entry not usable; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache entry not usable; calling backend", exchangeId); + } callBackend(target, request, entityProducer, scope, chain, asyncExecCallback); } } @@ -880,6 +929,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain.Scope scope, final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback) { + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; revalidateCacheEntry(responseCacheControl, hit, target, request, entityProducer, scope, chain, new AsyncExecCallback() { @@ -905,7 +955,9 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler @Override public void failed(final Exception cause) { if (!committed.get() && cause instanceof IOException) { - LOG.debug(cause.getMessage(), cause); + if (LOG.isDebugEnabled()) { + LOG.debug("{} I/O error while revalidating cache entry", exchangeId, cause); + } final SimpleHttpResponse cacheResponse = generateGatewayTimeout(); context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); triggerResponse(cacheResponse, scope, asyncExecCallback); @@ -927,6 +979,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain.Scope scope, final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback) { + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; revalidateCacheEntry(responseCacheControl, hit, target, request, entityProducer, scope, chain, new AsyncExecCallback() { @@ -938,7 +991,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler if (staleIfErrorAppliesTo(status) && suitabilityChecker.isSuitableIfError(requestCacheControl, responseCacheControl, hit.entry, getCurrentDate())) { if (LOG.isDebugEnabled()) { - LOG.debug("Serving stale response due to {} status and stale-if-error enabled", status); + LOG.debug("{} serving stale response due to {} status and stale-if-error enabled", exchangeId, status); } return null; } else { @@ -972,11 +1025,15 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler public void failed(final Exception cause) { final HttpResponse response = committed.get(); if (response == null) { - LOG.debug(cause.getMessage(), cause); + if (LOG.isDebugEnabled()) { + LOG.debug("{} I/O error while revalidating cache entry", exchangeId, cause); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); if (cause instanceof IOException && suitabilityChecker.isSuitableIfError(requestCacheControl, responseCacheControl, hit.entry, getCurrentDate())) { - LOG.debug("Serving stale response due to IOException and stale-if-error enabled"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} serving stale response due to IOException and stale-if-error enabled", exchangeId); + } try { final SimpleHttpResponse cacheResponse = unvalidatedCacheHit(request, hit.entry); triggerResponse(cacheResponse, scope, asyncExecCallback); @@ -1003,13 +1060,18 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain.Scope scope, final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback) { - cacheMisses.getAndIncrement(); + final String exchangeId = scope.exchangeId; + if (LOG.isDebugEnabled()) { - LOG.debug("Request {} {}: cache miss", request.getMethod(), request.getRequestUri()); + LOG.debug("{} cache miss: {}", exchangeId, new RequestLine(request)); } + cacheMisses.getAndIncrement(); final CancellableDependency operation = scope.cancellableDependency; - if (!mayCallBackend(requestCacheControl)) { + if (requestCacheControl.isOnlyIfCached()) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} request marked only-if-cached", exchangeId); + } final HttpClientContext context = scope.clientContext; context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); final SimpleHttpResponse cacheResponse = generateGatewayTimeout(); @@ -1054,6 +1116,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final AsyncExecChain chain, final AsyncExecCallback asyncExecCallback, final Collection variants) { + final String exchangeId = scope.exchangeId; final CancellableDependency operation = scope.cancellableDependency; final Map variantMap = new HashMap<>(); for (final CacheHit variant : variants) { @@ -1127,7 +1190,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler final CacheHit hit = result != null ? result.hit : null; if (hit != null) { if (LOG.isDebugEnabled()) { - LOG.debug("Existing cache entry found, updating cache entry"); + LOG.debug("{} existing cache entry found, updating cache entry", exchangeId); } responseCache.update( hit, @@ -1142,7 +1205,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler public void completed(final CacheHit updated) { try { if (LOG.isDebugEnabled()) { - LOG.debug("Cache entry updated, generating response from updated entry"); + LOG.debug("{} cache entry updated, generating response from updated entry", exchangeId); } final SimpleHttpResponse cacheResponse = responseGenerator.generateResponse(request, updated.entry); triggerResponse(cacheResponse, scope, asyncExecCallback); @@ -1153,7 +1216,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler @Override public void failed(final Exception cause) { if (LOG.isDebugEnabled()) { - LOG.debug("Request failed: {}", cause.getMessage()); + LOG.debug("{} request failed: {}", exchangeId, cause.getMessage()); } asyncExecCallback.failed(cause); } @@ -1161,7 +1224,7 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler @Override public void cancelled() { if (LOG.isDebugEnabled()) { - LOG.debug("Cache entry updated aborted"); + LOG.debug("{} cache entry updated aborted", exchangeId); } asyncExecCallback.failed(new InterruptedIOException()); } @@ -1187,13 +1250,17 @@ class AsyncCachingExec extends CachingExecBase implements AsyncExecChainHandler } else { final Header resultEtagHeader = backendResponse.getFirstHeader(HttpHeaders.ETAG); if (resultEtagHeader == null) { - LOG.warn("304 response did not contain ETag"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} 304 response did not contain ETag", exchangeId); + } callback = new AsyncExecCallbackWrapper(() -> callBackend(target, request, entityProducer, scope, chain, asyncExecCallback), asyncExecCallback::failed); } else { final String resultEtag = resultEtagHeader.getValue(); final CacheHit match = variantMap.get(resultEtag); if (match == null) { - LOG.debug("304 response did not contain ETag matching one sent in If-None-Match"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} 304 response did not contain ETag matching one sent in If-None-Match", exchangeId); + } callback = new AsyncExecCallbackWrapper(() -> callBackend(target, request, entityProducer, scope, chain, asyncExecCallback), asyncExecCallback::failed); } else { if (HttpCacheEntry.isNewer(match.entry, backendResponse)) { diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheControlHeaderParser.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheControlHeaderParser.java index a03e9310b..f6c0d773b 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheControlHeaderParser.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheControlHeaderParser.java @@ -252,7 +252,7 @@ class CacheControlHeaderParser { private static long parseSeconds(final String name, final String value) { final long delta = CacheSupport.deltaSeconds(value); if (delta == -1 && LOG.isDebugEnabled()) { - LOG.debug("Directive {} was malformed: {}", name, value); + LOG.debug("Directive {} is malformed: {}", name, value); } return delta; } 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 79495feb2..7ea900f49 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 @@ -47,31 +47,31 @@ class CacheableRequestPolicy { * an HttpRequest * @return boolean Is it possible to serve this request from cache */ - public boolean isServableFromCache(final RequestCacheControl cacheControl, final HttpRequest request) { + public boolean canBeServedFromCache(final RequestCacheControl cacheControl, final HttpRequest request) { final String method = request.getMethod(); final ProtocolVersion pv = request.getVersion() != null ? request.getVersion() : HttpVersion.DEFAULT; if (HttpVersion.HTTP_1_1.compareToVersion(pv) != 0) { - LOG.debug("non-HTTP/1.1 request is not serveable from cache"); + LOG.debug("non-HTTP/1.1 request cannot be served from cache"); return false; } if (!Method.GET.isSame(method) && !Method.HEAD.isSame(method)) { if (LOG.isDebugEnabled()) { - LOG.debug("{} request is not serveable from cache", method); + LOG.debug("{} request cannot be served from cache", method); } return false; } if (cacheControl.isNoStore()) { - LOG.debug("Request with no-store is not serveable from cache"); + LOG.debug("Request with no-store cannot be served from cache"); return false; } if (cacheControl.isNoCache()) { - LOG.debug("Request with no-cache is not serveable from cache"); + LOG.debug("Request with no-cache cannot be served from cache"); return false; } - LOG.debug("Request is serveable from cache"); + LOG.debug("Request can be served 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 a81a59716..4e354cafc 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 @@ -131,7 +131,13 @@ class CachedResponseSuitabilityChecker { } final TimeValue currentAge = validityStrategy.getCurrentAge(entry, now); + if (LOG.isDebugEnabled()) { + LOG.debug("Cache entry current age: {}", currentAge); + } final TimeValue freshnessLifetime = validityStrategy.getFreshnessLifetime(responseCacheControl, entry); + if (LOG.isDebugEnabled()) { + LOG.debug("Cache entry freshness lifetime: {}", freshnessLifetime); + } final boolean fresh = currentAge.compareTo(freshnessLifetime) < 0; @@ -162,6 +168,9 @@ class CachedResponseSuitabilityChecker { if (requestCacheControl.getMaxStale() >= 0) { final long stale = currentAge.compareTo(freshnessLifetime) > 0 ? currentAge.toSeconds() - freshnessLifetime.toSeconds() : 0; + if (LOG.isDebugEnabled()) { + LOG.debug("Cache entry staleness: {} SECONDS", stale); + } if (stale >= requestCacheControl.getMaxStale()) { LOG.debug("Response from cache is not suitable due to the request max-stale requirement"); return CacheSuitability.REVALIDATION_REQUIRED; 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 6b21bb501..60e9f99af 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 @@ -33,7 +33,6 @@ import java.util.HashMap; import java.util.Iterator; import java.util.List; import java.util.Map; -import java.util.concurrent.ScheduledExecutorService; import org.apache.hc.client5.http.HttpRoute; import org.apache.hc.client5.http.async.methods.SimpleBody; @@ -47,7 +46,6 @@ import org.apache.hc.client5.http.classic.ExecChain; import org.apache.hc.client5.http.classic.ExecChainHandler; import org.apache.hc.client5.http.impl.ExecSupport; import org.apache.hc.client5.http.protocol.HttpClientContext; -import org.apache.hc.client5.http.schedule.SchedulingStrategy; import org.apache.hc.core5.http.ClassicHttpRequest; import org.apache.hc.core5.http.ClassicHttpResponse; import org.apache.hc.core5.http.ContentType; @@ -64,6 +62,7 @@ import org.apache.hc.core5.http.io.entity.EntityUtils; import org.apache.hc.core5.http.io.entity.StringEntity; import org.apache.hc.core5.http.io.support.ClassicRequestBuilder; import org.apache.hc.core5.http.message.BasicClassicHttpResponse; +import org.apache.hc.core5.http.message.RequestLine; import org.apache.hc.core5.http.protocol.HttpCoreContext; import org.apache.hc.core5.net.URIAuthority; import org.apache.hc.core5.util.Args; @@ -115,32 +114,6 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { ClassicRequestBuilder.copy(classicHttpRequest).build()); } - CachingExec( - final HttpCache responseCache, - final CacheValidityPolicy validityPolicy, - final ResponseCachingPolicy responseCachingPolicy, - final CachedHttpResponseGenerator responseGenerator, - final CacheableRequestPolicy cacheableRequestPolicy, - final CachedResponseSuitabilityChecker suitabilityChecker, - final DefaultCacheRevalidator cacheRevalidator, - final ConditionalRequestBuilder conditionalRequestBuilder, - final CacheConfig config) { - super(validityPolicy, responseCachingPolicy, responseGenerator, cacheableRequestPolicy, suitabilityChecker, config); - this.responseCache = responseCache; - this.cacheRevalidator = cacheRevalidator; - this.conditionalRequestBuilder = conditionalRequestBuilder; - } - - CachingExec( - final HttpCache cache, - final ScheduledExecutorService executorService, - final SchedulingStrategy schedulingStrategy, - final CacheConfig config) { - this(cache, - executorService != null ? new DefaultCacheRevalidator(executorService, schedulingStrategy) : null, - config); - } - @Override public ClassicHttpResponse execute( final ClassicHttpRequest request, @@ -168,35 +141,40 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ClassicHttpRequest request, final ExecChain.Scope scope, final ExecChain chain) throws IOException, HttpException { - + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; + if (LOG.isDebugEnabled()) { + LOG.debug("{} request via cache: {}", exchangeId, new RequestLine(request)); + } + context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MISS); if (clientRequestsOurOptions(request)) { context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); return new BasicClassicHttpResponse(HttpStatus.SC_NOT_IMPLEMENTED); } - final CacheMatch result = responseCache.match(target, request); - final CacheHit hit = result != null ? result.hit : null; - final CacheHit root = result != null ? result.root : null; - final RequestCacheControl requestCacheControl = CacheControlHeaderParser.INSTANCE.parse(request); if (LOG.isDebugEnabled()) { LOG.debug("Request cache control: {}", requestCacheControl); } - if (!cacheableRequestPolicy.isServableFromCache(requestCacheControl, request)) { - LOG.debug("Request is not servable from cache"); + if (!cacheableRequestPolicy.canBeServedFromCache(requestCacheControl, request)) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} request cannot be served from cache", exchangeId); + } return callBackend(target, request, scope, chain); } + final CacheMatch result = responseCache.match(target, request); + final CacheHit hit = result != null ? result.hit : null; + final CacheHit root = result != null ? result.root : null; + if (hit == null) { - LOG.debug("Cache miss"); return handleCacheMiss(requestCacheControl, root, target, request, scope, chain); } else { final ResponseCacheControl responseCacheControl = CacheControlHeaderParser.INSTANCE.parse(hit.entry); if (LOG.isDebugEnabled()) { - LOG.debug("Response cache control: {}", responseCacheControl); + LOG.debug("{} response cache control: {}", exchangeId, responseCacheControl); } return handleCacheHit(requestCacheControl, responseCacheControl, hit, target, request, scope, chain); } @@ -231,12 +209,15 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ExecChain.Scope scope, final ExecChain chain) throws IOException, HttpException { + final String exchangeId = scope.exchangeId; final Instant requestDate = getCurrentDate(); - LOG.debug("Calling the backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} calling the backend", exchangeId); + } final ClassicHttpResponse backendResponse = chain.proceed(request, scope); try { - return handleBackendResponse(target, request, requestDate, getCurrentDate(), backendResponse); + return handleBackendResponse(exchangeId, target, request, requestDate, getCurrentDate(), backendResponse); } catch (final IOException | RuntimeException ex) { backendResponse.close(); throw ex; @@ -251,10 +232,13 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ClassicHttpRequest request, final ExecChain.Scope scope, final ExecChain chain) throws IOException, HttpException { + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; + if (LOG.isDebugEnabled()) { - LOG.debug("Request {} {}: cache hit", request.getMethod(), request.getRequestUri()); + LOG.debug("{} cache hit: {}", exchangeId, new RequestLine(request)); } + context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_HIT); cacheHits.getAndIncrement(); @@ -262,14 +246,19 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final CacheSuitability cacheSuitability = suitabilityChecker.assessSuitability(requestCacheControl, responseCacheControl, request, hit.entry, now); if (LOG.isDebugEnabled()) { - LOG.debug("Request {} {}: {}", request.getMethod(), request.getRequestUri(), cacheSuitability); + LOG.debug("{} cache suitability: {}", exchangeId, cacheSuitability); } if (cacheSuitability == CacheSuitability.FRESH || cacheSuitability == CacheSuitability.FRESH_ENOUGH) { - LOG.debug("Cache hit is suitable"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache hit is fresh enough", exchangeId); + } try { return convert(generateCachedResponse(request, hit.entry, now)); } catch (final ResourceIOException ex) { - if (!mayCallBackend(requestCacheControl)) { + if (requestCacheControl.isOnlyIfCached()) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} request marked only-if-cached", exchangeId); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); return convert(generateGatewayTimeout()); } @@ -277,47 +266,68 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { return chain.proceed(request, scope); } } else { - if (!mayCallBackend(requestCacheControl)) { - LOG.debug("Cache entry not is not fresh and only-if-cached requested"); + if (requestCacheControl.isOnlyIfCached()) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache entry not is not fresh and only-if-cached requested", exchangeId); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); return convert(generateGatewayTimeout()); } else if (cacheSuitability == CacheSuitability.MISMATCH) { - LOG.debug("Cache entry does not match the request; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache entry does not match the request; calling backend", exchangeId); + } return callBackend(target, request, scope, chain); } else if (request.getEntity() != null && !request.getEntity().isRepeatable()) { - LOG.debug("Request is not repeatable; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} request is not repeatable; calling backend", exchangeId); + } return callBackend(target, request, scope, chain); } else if (hit.entry.getStatus() == HttpStatus.SC_NOT_MODIFIED && !suitabilityChecker.isConditional(request)) { - LOG.debug("Non-modified cache entry does not match the non-conditional request; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} non-modified cache entry does not match the non-conditional request; calling backend", exchangeId); + } return callBackend(target, request, scope, chain); } else if (cacheSuitability == CacheSuitability.REVALIDATION_REQUIRED) { - LOG.debug("Revalidation required; revalidating cache entry"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} revalidation required; revalidating cache entry", exchangeId); + } return revalidateCacheEntryWithoutFallback(responseCacheControl, hit, target, request, scope, chain); } else if (cacheSuitability == CacheSuitability.STALE_WHILE_REVALIDATED) { if (cacheRevalidator != null) { - LOG.debug("Serving stale with asynchronous revalidation"); - final String exchangeId = ExecSupport.getNextExchangeId(); - context.setExchangeId(exchangeId); + if (LOG.isDebugEnabled()) { + LOG.debug("{} serving stale with asynchronous revalidation", exchangeId); + } + final String revalidationExchangeId = ExecSupport.getNextExchangeId(); + context.setExchangeId(revalidationExchangeId); final ExecChain.Scope fork = new ExecChain.Scope( - exchangeId, + revalidationExchangeId, scope.route, scope.originalRequest, scope.execRuntime.fork(null), HttpClientContext.create()); + if (LOG.isDebugEnabled()) { + LOG.debug("{} starting asynchronous revalidation exchange {}", exchangeId, revalidationExchangeId); + } cacheRevalidator.revalidateCacheEntry( hit.getEntryKey(), () -> revalidateCacheEntry(responseCacheControl, hit, target, request, fork, chain)); context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); return convert(unvalidatedCacheHit(request, hit.entry)); } else { - LOG.debug("Revalidating stale cache entry (asynchronous revalidation disabled)"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} revalidating stale cache entry (asynchronous revalidation disabled)", exchangeId); + } return revalidateCacheEntryWithFallback(requestCacheControl, responseCacheControl, hit, target, request, scope, chain); } } else if (cacheSuitability == CacheSuitability.STALE) { - LOG.debug("Revalidating stale cache entry"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} revalidating stale cache entry", exchangeId); + } return revalidateCacheEntryWithFallback(requestCacheControl, responseCacheControl, hit, target, request, scope, chain); } else { - LOG.debug("Cache entry not usable; calling backend"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} cache entry not usable; calling backend", exchangeId); + } return callBackend(target, request, scope, chain); } } @@ -357,7 +367,7 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final CacheHit updated = responseCache.update(hit, target, request, backendResponse, requestDate, responseDate); return convert(generateCachedResponse(request, updated.entry, responseDate)); } - return handleBackendResponse(target, conditionalRequest, requestDate, responseDate, backendResponse); + return handleBackendResponse(scope.exchangeId, target, conditionalRequest, requestDate, responseDate, backendResponse); } catch (final IOException | RuntimeException ex) { backendResponse.close(); throw ex; @@ -371,11 +381,14 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ClassicHttpRequest request, final ExecChain.Scope scope, final ExecChain chain) throws HttpException { + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; try { return revalidateCacheEntry(responseCacheControl, hit, target, request, scope, chain); } catch (final IOException ex) { - LOG.debug(ex.getMessage(), ex); + if (LOG.isDebugEnabled()) { + LOG.debug("{} I/O error while revalidating cache entry", exchangeId, ex); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); return convert(generateGatewayTimeout()); } @@ -389,15 +402,20 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ClassicHttpRequest request, final ExecChain.Scope scope, final ExecChain chain) throws HttpException, IOException { + final String exchangeId = scope.exchangeId; final HttpClientContext context = scope.clientContext; final ClassicHttpResponse response; try { response = revalidateCacheEntry(responseCacheControl, hit, target, request, scope, chain); } catch (final IOException ex) { - LOG.debug(ex.getMessage(), ex); + if (LOG.isDebugEnabled()) { + LOG.debug("{} I/O error while revalidating cache entry", exchangeId, ex); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); if (suitabilityChecker.isSuitableIfError(requestCacheControl, responseCacheControl, hit.entry, getCurrentDate())) { - LOG.debug("Serving stale response due to IOException and stale-if-error enabled"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} serving stale response due to IOException and stale-if-error enabled", exchangeId); + } return convert(unvalidatedCacheHit(request, hit.entry)); } else { return convert(generateGatewayTimeout()); @@ -407,7 +425,7 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { if (staleIfErrorAppliesTo(status) && suitabilityChecker.isSuitableIfError(requestCacheControl, responseCacheControl, hit.entry, getCurrentDate())) { if (LOG.isDebugEnabled()) { - LOG.debug("Serving stale response due to {} status and stale-if-error enabled", status); + LOG.debug("{} serving stale response due to {} status and stale-if-error enabled", exchangeId, status); } EntityUtils.consume(response.getEntity()); context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); @@ -417,6 +435,7 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { } ClassicHttpResponse handleBackendResponse( + final String exchangeId, final HttpHost target, final ClassicHttpRequest request, final Instant requestDate, @@ -425,26 +444,33 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { responseCache.evictInvalidatedEntries(target, request, backendResponse); if (isResponseTooBig(backendResponse.getEntity())) { - LOG.debug("Backend response is known to be too big"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response is known to be too big", exchangeId); + } return backendResponse; } final ResponseCacheControl responseCacheControl = CacheControlHeaderParser.INSTANCE.parse(backendResponse); final boolean cacheable = responseCachingPolicy.isResponseCacheable(responseCacheControl, request, backendResponse); if (cacheable) { storeRequestIfModifiedSinceFor304Response(request, backendResponse); - return cacheAndReturnResponse(target, request, backendResponse, requestDate, responseDate); + return cacheAndReturnResponse(exchangeId, target, request, backendResponse, requestDate, responseDate); + } + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response is not cacheable", exchangeId); } - LOG.debug("Backend response is not cacheable"); return backendResponse; } ClassicHttpResponse cacheAndReturnResponse( + final String exchangeId, final HttpHost target, final HttpRequest request, final ClassicHttpResponse backendResponse, final Instant requestSent, final Instant responseReceived) throws IOException { - LOG.debug("Caching backend response"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} caching backend response", exchangeId); + } // handle 304 Not Modified responses if (backendResponse.getCode() == HttpStatus.SC_NOT_MODIFIED) { @@ -474,7 +500,9 @@ 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"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response content length exceeds maximum", exchangeId); + } backendResponse.setEntity(new CombinedEntity(entity, buf)); return backendResponse; } @@ -489,14 +517,20 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final CacheMatch result = responseCache.match(target ,request); hit = result != null ? result.hit : null; if (HttpCacheEntry.isNewer(hit != null ? hit.entry : null, backendResponse)) { - LOG.debug("Backend already contains fresher cache entry"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend already contains fresher cache entry", exchangeId); + } } else { hit = responseCache.store(target, request, backendResponse, buf, requestSent, responseReceived); - LOG.debug("Backend response successfully cached"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response successfully cached", exchangeId); + } } } else { hit = responseCache.store(target, request, backendResponse, buf, requestSent, responseReceived); - LOG.debug("Backend response successfully cached (freshness check skipped)"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} backend response successfully cached (freshness check skipped)", exchangeId); + } } return convert(responseGenerator.generateResponse(request, hit.entry)); } @@ -508,13 +542,18 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ClassicHttpRequest request, final ExecChain.Scope scope, final ExecChain chain) throws IOException, HttpException { - cacheMisses.getAndIncrement(); + final String exchangeId = scope.exchangeId; + if (LOG.isDebugEnabled()) { - LOG.debug("Request {} {}: cache miss", request.getMethod(), request.getRequestUri()); + LOG.debug("{} cache miss: {}", exchangeId, new RequestLine(request)); } + cacheMisses.getAndIncrement(); final HttpClientContext context = scope.clientContext; - if (!mayCallBackend(requestCacheControl)) { + if (requestCacheControl.isOnlyIfCached()) { + if (LOG.isDebugEnabled()) { + LOG.debug("{} request marked only-if-cached", exchangeId); + } context.setAttribute(HttpCacheContext.CACHE_RESPONSE_STATUS, CacheResponseStatus.CACHE_MODULE_RESPONSE); return convert(generateGatewayTimeout()); } @@ -534,6 +573,8 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final ExecChain.Scope scope, final ExecChain chain, final List variants) throws IOException, HttpException { + final String exchangeId = scope.exchangeId; + final Map variantMap = new HashMap<>(); for (final CacheHit variant : variants) { final Header header = variant.entry.getFirstHeader(HttpHeaders.ETAG); @@ -550,7 +591,7 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final Instant responseDate = getCurrentDate(); if (backendResponse.getCode() != HttpStatus.SC_NOT_MODIFIED) { - return handleBackendResponse(target, request, requestDate, responseDate, backendResponse); + return handleBackendResponse(exchangeId, target, request, requestDate, responseDate, backendResponse); } else { // 304 response are not expected to have an enclosed content body, but still backendResponse.close(); @@ -558,14 +599,18 @@ class CachingExec extends CachingExecBase implements ExecChainHandler { final Header resultEtagHeader = backendResponse.getFirstHeader(HttpHeaders.ETAG); if (resultEtagHeader == null) { - LOG.warn("304 response did not contain ETag"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} 304 response did not contain ETag", exchangeId); + } return callBackend(target, request, scope, chain); } final String resultEtag = resultEtagHeader.getValue(); final CacheHit match = variantMap.get(resultEtag); if (match == null) { - LOG.debug("304 response did not contain ETag matching one sent in If-None-Match"); + if (LOG.isDebugEnabled()) { + LOG.debug("{} 304 response did not contain ETag matching one sent in If-None-Match", exchangeId); + } return callBackend(target, request, scope, chain); } 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 4596e0223..c2facf4ab 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 @@ -40,8 +40,6 @@ import org.apache.hc.core5.http.HttpRequest; import org.apache.hc.core5.http.HttpResponse; import org.apache.hc.core5.http.HttpStatus; import org.apache.hc.core5.http.Method; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public class CachingExecBase { @@ -56,8 +54,6 @@ public class CachingExecBase { final CachedResponseSuitabilityChecker suitabilityChecker; final CacheConfig cacheConfig; - private static final Logger LOG = LoggerFactory.getLogger(CachingExecBase.class); - CachingExecBase( final CacheValidityPolicy validityPolicy, final ResponseCachingPolicy responseCachingPolicy, @@ -132,14 +128,6 @@ public class CachingExecBase { return responseGenerator.generateResponse(request, entry); } - boolean mayCallBackend(final RequestCacheControl requestCacheControl) { - if (requestCacheControl.isOnlyIfCached()) { - LOG.debug("Request marked only-if-cached"); - return false; - } - return true; - } - Instant getCurrentDate() { return Instant.now(); } diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/RequestCacheControl.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/RequestCacheControl.java index 1df87ac40..ef4d1bf8d 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/RequestCacheControl.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/RequestCacheControl.java @@ -137,16 +137,37 @@ final class RequestCacheControl implements CacheControl { @Override public String toString() { - return "RequestCacheControl{" + - "maxAge=" + maxAge + - ", maxStale=" + maxStale + - ", minFresh=" + minFresh + - ", noCache=" + noCache + - ", noStore=" + noStore + - ", onlyIfCached=" + onlyIfCached + - ", staleIfError=" + staleIfError + - ", noTransform=" + noTransform + - '}'; + final StringBuilder buf = new StringBuilder(); + buf.append("["); + if (maxAge >= 0) { + buf.append("max-age=").append(maxAge).append(","); + } + if (maxStale >= 0) { + buf.append("max-stale=").append(maxStale).append(","); + } + if (minFresh >= 0) { + buf.append("max-fresh=").append(minFresh).append(","); + } + if (noCache) { + buf.append("no-cache").append(","); + } + if (noStore) { + buf.append("no-store").append(","); + } + if (onlyIfCached) { + buf.append("only-if-cached").append(","); + } + if (staleIfError >= 0) { + buf.append("stale-if-error").append(staleIfError).append(","); + } + if (noTransform) { + buf.append("no-transform").append(","); + } + if (buf.charAt(buf.length() - 1) == ',') { + buf.setLength(buf.length() - 1); + } + buf.append("]"); + return buf.toString(); } static Builder builder() { diff --git a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCacheControl.java b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCacheControl.java index 4e548bd4d..cda5c5802 100644 --- a/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCacheControl.java +++ b/httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCacheControl.java @@ -294,21 +294,49 @@ final class ResponseCacheControl implements CacheControl { @Override public String toString() { - return "CacheControl{" + - "maxAge=" + maxAge + - ", sharedMaxAge=" + sharedMaxAge + - ", noCache=" + noCache + - ", noStore=" + noStore + - ", cachePrivate=" + cachePrivate + - ", mustRevalidate=" + mustRevalidate + - ", proxyRevalidate=" + proxyRevalidate + - ", cachePublic=" + cachePublic + - ", staleWhileRevalidate=" + staleWhileRevalidate + - ", staleIfError=" + staleIfError + - ", noCacheFields=" + noCacheFields + - ", mustUnderstand=" + mustUnderstand + - ", immutable=" + immutable + - '}'; + final StringBuilder buf = new StringBuilder(); + buf.append("["); + if (maxAge >= 0) { + buf.append("max-age=").append(maxAge).append(","); + } + if (sharedMaxAge >= 0) { + buf.append("shared-max-age=").append(sharedMaxAge).append(","); + } + if (noCache) { + buf.append("no-cache").append(","); + } + if (noStore) { + buf.append("no-store").append(","); + } + if (cachePrivate) { + buf.append("private").append(","); + } + if (cachePublic) { + buf.append("public").append(","); + } + if (mustRevalidate) { + buf.append("must-revalidate").append(","); + } + if (proxyRevalidate) { + buf.append("proxy-revalidate").append(","); + } + if (staleWhileRevalidate >= 0) { + buf.append("state-while-revalidate=").append(staleWhileRevalidate).append(","); + } + if (staleIfError >= 0) { + buf.append("stale-if-error").append(staleIfError).append(","); + } + if (mustUnderstand) { + buf.append("must-understand").append(","); + } + if (immutable) { + buf.append("immutable").append(","); + } + if (buf.charAt(buf.length() - 1) == ',') { + buf.setLength(buf.length() - 1); + } + buf.append("]"); + return buf.toString(); } static Builder builder() { diff --git a/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCacheableRequestPolicy.java b/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCacheableRequestPolicy.java index 2d68671b4..b4b04190e 100644 --- a/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCacheableRequestPolicy.java +++ b/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCacheableRequestPolicy.java @@ -45,7 +45,7 @@ public class TestCacheableRequestPolicy { final BasicHttpRequest request = new BasicHttpRequest("GET", "someUri"); final RequestCacheControl cacheControl = RequestCacheControl.builder().build(); - Assertions.assertTrue(policy.isServableFromCache(cacheControl, request)); + Assertions.assertTrue(policy.canBeServedFromCache(cacheControl, request)); } @Test @@ -55,14 +55,14 @@ public class TestCacheableRequestPolicy { .setNoCache(true) .build(); - Assertions.assertFalse(policy.isServableFromCache(cacheControl, request)); + Assertions.assertFalse(policy.canBeServedFromCache(cacheControl, request)); final RequestCacheControl cacheControl2 = RequestCacheControl.builder() .setNoStore(true) .setMaxAge(20) .build(); - Assertions.assertFalse(policy.isServableFromCache(cacheControl2, request)); + Assertions.assertFalse(policy.canBeServedFromCache(cacheControl2, request)); } @Test @@ -70,13 +70,13 @@ public class TestCacheableRequestPolicy { final BasicHttpRequest request = new BasicHttpRequest("HEAD", "someUri"); final RequestCacheControl cacheControl = RequestCacheControl.builder().build(); - Assertions.assertTrue(policy.isServableFromCache(cacheControl, request)); + Assertions.assertTrue(policy.canBeServedFromCache(cacheControl, request)); final RequestCacheControl cacheControl2 = RequestCacheControl.builder() .setMaxAge(20) .build(); - Assertions.assertTrue(policy.isServableFromCache(cacheControl2, request)); + Assertions.assertTrue(policy.canBeServedFromCache(cacheControl2, request)); } @Test @@ -86,7 +86,7 @@ public class TestCacheableRequestPolicy { .setNoCache(true) .build(); - Assertions.assertFalse(policy.isServableFromCache(cacheControl, request)); + Assertions.assertFalse(policy.canBeServedFromCache(cacheControl, request)); request.addHeader("Cache-Control", "no-store"); request.addHeader("Cache-Control", "max-age=20"); @@ -95,7 +95,7 @@ public class TestCacheableRequestPolicy { .setMaxAge(20) .build(); - Assertions.assertFalse(policy.isServableFromCache(cacheControl2, request)); + Assertions.assertFalse(policy.canBeServedFromCache(cacheControl2, request)); } @Test @@ -104,11 +104,11 @@ public class TestCacheableRequestPolicy { final RequestCacheControl cacheControl = RequestCacheControl.builder() .build(); - Assertions.assertFalse(policy.isServableFromCache(cacheControl, request)); + Assertions.assertFalse(policy.canBeServedFromCache(cacheControl, request)); final BasicHttpRequest request2 = new BasicHttpRequest("huh", "someUri"); - Assertions.assertFalse(policy.isServableFromCache(cacheControl, request2)); + Assertions.assertFalse(policy.canBeServedFromCache(cacheControl, request2)); } diff --git a/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCachingExecChain.java b/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCachingExecChain.java index 961e6615e..b1616c331 100644 --- a/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCachingExecChain.java +++ b/httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCachingExecChain.java @@ -900,7 +900,7 @@ public class TestCachingExecChain { originResponse.setHeader("Date", DateUtils.formatStandardDate(responseGenerated)); originResponse.setHeader("ETag", "\"etag\""); - impl.cacheAndReturnResponse(host, request, originResponse, requestSent, responseReceived); + impl.cacheAndReturnResponse("exchange-id", host, request, originResponse, requestSent, responseReceived); Mockito.verify(cache, Mockito.never()).store( Mockito.any(), Mockito.any(), Mockito.any(), Mockito.any(), Mockito.any(), Mockito.any()); @@ -936,7 +936,7 @@ public class TestCachingExecChain { Mockito.eq(requestSent), Mockito.eq(responseReceived))).thenReturn(new CacheHit("key", httpCacheEntry)); - impl.cacheAndReturnResponse(host, request, originResponse, requestSent, responseReceived); + impl.cacheAndReturnResponse("exchange-id", host, request, originResponse, requestSent, responseReceived); Mockito.verify(mockCache).store( Mockito.any(), @@ -1274,7 +1274,7 @@ public class TestCachingExecChain { .thenReturn(new CacheHit("key", cacheEntry)); // Call cacheAndReturnResponse with 304 Not Modified response - final ClassicHttpResponse cachedResponse = impl.cacheAndReturnResponse(host, request, backendResponse, requestSent, responseReceived); + final ClassicHttpResponse cachedResponse = impl.cacheAndReturnResponse("exchange-id", host, request, backendResponse, requestSent, responseReceived); // Verify cache entry is updated Mockito.verify(mockCache).update(