Apache
/
httpcomponents-client
mirror of https://github.com/apache/httpcomponents-client.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Better debug logging in the caching protocol handlers

This commit is contained in:
Oleg Kalnichevski 2023-11-15 13:37:26 +01:00
parent 628a963a3a
commit 67a0b52919
10 changed files with 344 additions and 186 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

177
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/AsyncCachingExec.java vendored
View File

@ -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<CacheMatch>() {
@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<AsyncExecCallback> 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<AsyncDataConsumer> 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<Boolean>() {
@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<CacheHit> variants) {
final String exchangeId = scope.exchangeId;
final CancellableDependency operation = scope.cancellableDependency;
final Map<String, CacheHit> 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)) {

2
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheControlHeaderParser.java vendored
View File

@ -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;
}

12
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CacheableRequestPolicy.java vendored
View File

@ -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;
}

9
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachedResponseSuitabilityChecker.java vendored
View File

@ -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;

195
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExec.java vendored
View File

@ -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<ClassicHttpRequest> 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<CacheHit> variants) throws IOException, HttpException {
final String exchangeId = scope.exchangeId;
final Map<String, CacheHit> 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);
}

12
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/CachingExecBase.java vendored
View File

@ -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();
}

41
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/RequestCacheControl.java vendored
View File

@ -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() {

58
httpclient5-cache/src/main/java/org/apache/hc/client5/http/impl/cache/ResponseCacheControl.java vendored
View File

@ -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() {

18
httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCacheableRequestPolicy.java vendored
View File

@ -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));
}

6
httpclient5-cache/src/test/java/org/apache/hc/client5/http/impl/cache/TestCachingExecChain.java vendored
View File

@ -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(