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

Revised HTTP cache debug logging

This commit is contained in:
Oleg Kalnichevski 2017-10-15 13:44:51 +02:00
parent 30320fe2f4
commit 74ed4dfebf
7 changed files with 99 additions and 78 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -238,7 +238,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH
final AsyncExecChain.Scope scope,
final AsyncExecChain chain,
final InternalCallback asyncExecCallback) throws HttpException, IOException {
log.trace("Calling the backend");
log.debug("Calling the backend");
final Date requestDate = getCurrentDate();
chain.proceed(request, entityProducer, scope, new AsyncExecCallback() {
@ -253,7 +253,6 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH
final Date responseDate = getCurrentDate();
backendResponse.addHeader("Via", generateViaHeader(backendResponse));
log.trace("Handling Backend response");
responseCompliance.ensureProtocolCompliance(scope.originalRequest, request, backendResponse);
final boolean cacheable = asyncExecCallback.cacheResponse(backendResponse)
@ -265,6 +264,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH
bufferRef.set(new ByteArrayBuffer(1024));
}
} else {
log.debug("Backend response is not cacheable");
try {
responseCache.flushCacheEntriesFor(target, request);
} catch (final IOException ioe) {
@ -272,10 +272,12 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH
}
}
if (bufferRef.get() != null) {
log.debug("Caching backend response");
if (entityDetails == null) {
scope.execRuntime.releaseConnection();
final HttpCacheEntry entry = responseCache.createCacheEntry(
target, request, backendResponse, null, requestDate, responseDate);
log.debug("Backend response successfully cached");
responseRef.set(responseGenerator.generateResponse(request, entry));
return null;
} else {
@ -303,6 +305,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH
}
}
if (buffer.length() > cacheConfig.getMaxObjectSize()) {
log.debug("Backend response content length exceeds maximum");
// Over the max limit. Stop buffering and forward the response
// along with all the data buffered so far to the caller.
bufferRef.set(null);
@ -339,6 +342,7 @@ public class AsyncCachingExec extends CachingExecBase implements AsyncExecChainH
if (buffer != null) {
final HttpCacheEntry entry = responseCache.createCacheEntry(
target, request, backendResponse, buffer, requestDate, responseDate);
log.debug("Backend response successfully cached");
responseRef.set(responseGenerator.generateResponse(request, entry));
}
}

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

@ -64,13 +64,13 @@ class CacheInvalidator implements HttpCacheInvalidator {
* Create a new {@link CacheInvalidator} for a given {@link HttpCache} and
* {@link CacheKeyGenerator}.
*
* @param uriExtractor Provides identifiers for the keys to store cache entries
* @param cacheKeyGenerator Provides identifiers for the keys to store cache entries
* @param storage the cache to store items away in
*/
public CacheInvalidator(
final CacheKeyGenerator uriExtractor,
final CacheKeyGenerator cacheKeyGenerator,
final HttpCacheStorage storage) {
this.cacheKeyGenerator = uriExtractor;
this.cacheKeyGenerator = cacheKeyGenerator;
this.storage = storage;
}
@ -83,18 +83,20 @@ class CacheInvalidator implements HttpCacheInvalidator {
*/
@Override
public void flushInvalidatedCacheEntries(final HttpHost host, final HttpRequest req) {
final String theUri = cacheKeyGenerator.generateKey(host, req);
final HttpCacheEntry parent = getEntry(theUri);
final String key = cacheKeyGenerator.generateKey(host, req);
final HttpCacheEntry parent = getEntry(key);
if (requestShouldNotBeCached(req) || shouldInvalidateHeadCacheEntry(req, parent)) {
log.debug("Invalidating parent cache entry: " + parent);
if (log.isDebugEnabled()) {
log.debug("Invalidating parent cache entry: " + parent);
}
if (parent != null) {
for (final String variantURI : parent.getVariantMap().values()) {
flushEntry(variantURI);
}
flushEntry(theUri);
flushEntry(key);
}
final URL reqURL = getAbsoluteURL(theUri);
final URL reqURL = getAbsoluteURL(key);
if (reqURL == null) {
log.error("Couldn't transform request into valid URL");
return;

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

@ -61,37 +61,34 @@ class CacheableRequestPolicy {
final ProtocolVersion pv = request.getVersion() != null ? request.getVersion() : HttpVersion.DEFAULT;
if (HttpVersion.HTTP_1_1.compareToVersion(pv) != 0) {
log.trace("non-HTTP/1.1 request was not serveable from cache");
log.debug("non-HTTP/1.1 request is not serveable from cache");
return false;
}
if (!(method.equals(HeaderConstants.GET_METHOD) || method
.equals(HeaderConstants.HEAD_METHOD))) {
log.trace("non-GET or non-HEAD request was not serveable from cache");
if (!method.equals(HeaderConstants.GET_METHOD) && !method.equals(HeaderConstants.HEAD_METHOD)) {
log.debug(method + " request is not serveable from cache");
return false;
}
if (request.getHeaders(HeaderConstants.PRAGMA).length > 0) {
log.trace("request with Pragma header was not serveable from cache");
if (request.containsHeaders(HeaderConstants.PRAGMA) > 0) {
log.debug("request with Pragma header is not serveable from cache");
return false;
}
final Iterator<HeaderElement> it = MessageSupport.iterate(request, HeaderConstants.CACHE_CONTROL);
while (it.hasNext()) {
final HeaderElement cacheControlElement = it.next();
if (HeaderConstants.CACHE_CONTROL_NO_STORE.equalsIgnoreCase(cacheControlElement
.getName())) {
log.trace("Request with no-store was not serveable from cache");
if (HeaderConstants.CACHE_CONTROL_NO_STORE.equalsIgnoreCase(cacheControlElement.getName())) {
log.debug("Request with no-store is not serveable from cache");
return false;
}
if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equalsIgnoreCase(cacheControlElement
.getName())) {
log.trace("Request with no-cache was not serveable from cache");
if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equalsIgnoreCase(cacheControlElement.getName())) {
log.debug("Request with no-cache is not serveable from cache");
return false;
}
}
log.trace("Request was serveable from cache");
log.debug("Request is serveable from cache");
return true;
}

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

@ -146,7 +146,7 @@ class CachedResponseSuitabilityChecker {
*/
public boolean canCachedResponseBeUsed(final HttpHost host, final HttpRequest request, final HttpCacheEntry entry, final Date now) {
if (!isFreshEnough(entry, request, now)) {
log.trace("Cache entry was not fresh enough");
log.debug("Cache entry is not fresh enough");
return false;
}
@ -156,15 +156,17 @@ class CachedResponseSuitabilityChecker {
}
if (hasUnsupportedConditionalHeaders(request)) {
log.debug("Request contained conditional headers we don't handle");
log.debug("Request contains unsupported conditional headers");
return false;
}
if (!isConditional(request) && entry.getStatus() == HttpStatus.SC_NOT_MODIFIED) {
log.debug("Unconditional request and non-modified cached response");
return false;
}
if (isConditional(request) && !allConditionalsMatch(request, entry, now)) {
log.debug("Conditional request and with mismatched conditions");
return false;
}
@ -177,12 +179,12 @@ class CachedResponseSuitabilityChecker {
while (it.hasNext()) {
final HeaderElement elt = it.next();
if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equals(elt.getName())) {
log.trace("Response contained NO CACHE directive, cache was not suitable");
log.debug("Response contained NO CACHE directive, cache was not suitable");
return false;
}
if (HeaderConstants.CACHE_CONTROL_NO_STORE.equals(elt.getName())) {
log.trace("Response contained NO STORE directive, cache was not suitable");
log.debug("Response contained NO STORE directive, cache was not suitable");
return false;
}
@ -190,7 +192,7 @@ class CachedResponseSuitabilityChecker {
try {
final int maxage = Integer.parseInt(elt.getValue());
if (validityStrategy.getCurrentAgeSecs(entry, now) > maxage) {
log.trace("Response from cache was NOT suitable due to max age");
log.debug("Response from cache was NOT suitable due to max age");
return false;
}
} catch (final NumberFormatException ex) {
@ -204,7 +206,7 @@ class CachedResponseSuitabilityChecker {
try {
final int maxstale = Integer.parseInt(elt.getValue());
if (validityStrategy.getFreshnessLifetimeSecs(entry) > maxstale) {
log.trace("Response from cache was not suitable due to Max stale freshness");
log.debug("Response from cache was not suitable due to Max stale freshness");
return false;
}
} catch (final NumberFormatException ex) {
@ -223,7 +225,7 @@ class CachedResponseSuitabilityChecker {
final long age = validityStrategy.getCurrentAgeSecs(entry, now);
final long freshness = validityStrategy.getFreshnessLifetimeSecs(entry);
if (freshness - age < minfresh) {
log.trace("Response from cache was not suitable due to min fresh " +
log.debug("Response from cache was not suitable due to min fresh " +
"freshness requirement");
return false;
}
@ -235,7 +237,7 @@ class CachedResponseSuitabilityChecker {
}
}
log.trace("Response from cache was suitable");
log.debug("Response from cache was suitable");
return true;
}

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

@ -213,7 +213,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler {
final Date requestDate = getCurrentDate();
log.trace("Calling the backend");
log.debug("Calling the backend");
final ClassicHttpResponse backendResponse = chain.proceed(request, scope);
try {
backendResponse.addHeader("Via", generateViaHeader(backendResponse));
@ -337,7 +337,6 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler {
final Date responseDate,
final ClassicHttpResponse backendResponse) throws IOException {
log.trace("Handling Backend response");
responseCompliance.ensureProtocolCompliance(scope.originalRequest, request, backendResponse);
final boolean cacheable = responseCachingPolicy.isResponseCacheable(request, backendResponse);
@ -347,6 +346,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler {
return cacheAndReturnResponse(target, request, backendResponse, requestDate, responseDate);
}
if (!cacheable) {
log.debug("Backend response is not cacheable");
try {
responseCache.flushCacheEntriesFor(target, request);
} catch (final IOException ioe) {
@ -362,6 +362,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler {
final ClassicHttpResponse backendResponse,
final Date requestSent,
final Date responseReceived) throws IOException {
log.debug("Caching backend response");
final ByteArrayBuffer buf;
final HttpEntity entity = backendResponse.getEntity();
if (entity != null) {
@ -374,6 +375,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler {
buf.append(tmp, 0, l);
total += l;
if (total > cacheConfig.getMaxObjectSize()) {
log.debug("Backend response content length exceeds maximum");
backendResponse.setEntity(new CombinedEntity(entity, buf));
return backendResponse;
}
@ -383,6 +385,7 @@ public class CachingExec extends CachingExecBase implements ExecChainHandler {
}
backendResponse.close();
final HttpCacheEntry entry = responseCache.createCacheEntry(target, request, backendResponse, buf, requestSent, responseReceived);
log.debug("Backend response successfully cached");
return convert(responseGenerator.generateResponse(request, entry));
}

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

@ -177,21 +177,21 @@ public class CachingExecBase {
void recordCacheMiss(final HttpHost target, final HttpRequest request) {
cacheMisses.getAndIncrement();
if (log.isTraceEnabled()) {
log.trace("Cache miss [host: " + target + "; uri: " + request.getRequestUri() + "]");
log.debug("Cache miss [host: " + target + "; uri: " + request.getRequestUri() + "]");
}
}
void recordCacheHit(final HttpHost target, final HttpRequest request) {
cacheHits.getAndIncrement();
if (log.isTraceEnabled()) {
log.trace("Cache hit [host: " + target + "; uri: " + request.getRequestUri() + "]");
log.debug("Cache hit [host: " + target + "; uri: " + request.getRequestUri() + "]");
}
}
void recordCacheFailure(final HttpHost target, final HttpRequest request) {
cacheMisses.getAndIncrement();
if (log.isTraceEnabled()) {
log.trace("Cache failure [host: " + target + "; uri: " + request.getRequestUri() + "]");
log.debug("Cache failure [host: " + target + "; uri: " + request.getRequestUri() + "]");
}
}
@ -266,7 +266,7 @@ public class CachingExecBase {
while (it.hasNext()) {
final HeaderElement elt = it.next();
if ("only-if-cached".equals(elt.getName())) {
log.trace("Request marked only-if-cached");
log.debug("Request marked only-if-cached");
return false;
}
}

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

@ -60,17 +60,20 @@ class ResponseCachingPolicy {
private static final String[] AUTH_CACHEABLE_PARAMS = {
"s-maxage", HeaderConstants.CACHE_CONTROL_MUST_REVALIDATE, HeaderConstants.PUBLIC
};
private final static Set<Integer> CACHEABLE_STATUS_CODES =
new HashSet<>(Arrays.asList(HttpStatus.SC_OK,
HttpStatus.SC_NON_AUTHORITATIVE_INFORMATION,
HttpStatus.SC_MULTIPLE_CHOICES,
HttpStatus.SC_MOVED_PERMANENTLY,
HttpStatus.SC_GONE));
private final Logger log = LogManager.getLogger(getClass());
private final long maxObjectSizeBytes;
private final boolean sharedCache;
private final boolean neverCache1_0ResponsesWithQueryString;
private final Logger log = LogManager.getLogger(getClass());
private static final Set<Integer> cacheableStatuses =
new HashSet<>(Arrays.asList(HttpStatus.SC_OK,
HttpStatus.SC_NON_AUTHORITATIVE_INFORMATION,
HttpStatus.SC_MULTIPLE_CHOICES,
HttpStatus.SC_MOVED_PERMANENTLY,
HttpStatus.SC_GONE));
private final Set<Integer> uncacheableStatuses;
private final Set<Integer> uncacheableStatusCodes;
/**
* Define a cache policy that limits the size of things that should be stored
@ -91,11 +94,9 @@ class ResponseCachingPolicy {
this.sharedCache = sharedCache;
this.neverCache1_0ResponsesWithQueryString = neverCache1_0ResponsesWithQueryString;
if (allow303Caching) {
uncacheableStatuses = new HashSet<>(
Arrays.asList(HttpStatus.SC_PARTIAL_CONTENT));
uncacheableStatusCodes = new HashSet<>(Arrays.asList(HttpStatus.SC_PARTIAL_CONTENT));
} else {
uncacheableStatuses = new HashSet<>(Arrays.asList(
HttpStatus.SC_PARTIAL_CONTENT, HttpStatus.SC_SEE_OTHER));
uncacheableStatusCodes = new HashSet<>(Arrays.asList(HttpStatus.SC_PARTIAL_CONTENT, HttpStatus.SC_SEE_OTHER));
}
}
@ -109,21 +110,28 @@ class ResponseCachingPolicy {
public boolean isResponseCacheable(final String httpMethod, final HttpResponse response) {
boolean cacheable = false;
if (!(HeaderConstants.GET_METHOD.equals(httpMethod) ||
HeaderConstants.HEAD_METHOD.equals(httpMethod))) {
log.debug("Response was not cacheable.");
if (!HeaderConstants.GET_METHOD.equals(httpMethod) && !HeaderConstants.HEAD_METHOD.equals(httpMethod)) {
if (log.isDebugEnabled()) {
log.debug(httpMethod + " method response is not cacheable");
}
return false;
}
final int status = response.getCode();
if (cacheableStatuses.contains(status)) {
if (CACHEABLE_STATUS_CODES.contains(status)) {
// these response codes MAY be cached
cacheable = true;
} else if (uncacheableStatuses.contains(status)) {
} else if (uncacheableStatusCodes.contains(status)) {
if (log.isDebugEnabled()) {
log.debug(status + " response is not cacheable");
}
return false;
} else if (unknownStatusCode(status)) {
// a response with an unknown status code MUST NOT be
// cached
if (log.isDebugEnabled()) {
log.debug(status + " response is unknown");
}
return false;
}
@ -131,30 +139,32 @@ class ResponseCachingPolicy {
if (contentLength != null) {
final long contentLengthValue = Long.parseLong(contentLength.getValue());
if (contentLengthValue > this.maxObjectSizeBytes) {
if (log.isDebugEnabled()) {
log.debug("Response content length exceeds " + this.maxObjectSizeBytes);
}
return false;
}
}
final Header[] ageHeaders = response.getHeaders(HeaderConstants.AGE);
if (ageHeaders.length > 1) {
if (response.containsHeaders(HeaderConstants.AGE) > 1) {
log.debug("Multiple Age headers");
return false;
}
final Header[] expiresHeaders = response.getHeaders(HeaderConstants.EXPIRES);
if (expiresHeaders.length > 1) {
if (response.containsHeaders(HeaderConstants.EXPIRES) > 1) {
log.debug("Multiple Expires headers");
return false;
}
final Header[] dateHeaders = response.getHeaders(HttpHeaders.DATE);
if (dateHeaders.length != 1) {
if (response.containsHeaders(HttpHeaders.DATE) > 1) {
log.debug("Multiple Date headers");
return false;
}
final Date date = DateUtils.parseDate(dateHeaders[0].getValue());
final Header h = response.getFirstHeader(HttpHeaders.DATE);
final Date date = h != null ? DateUtils.parseDate(h.getValue()) : null;
if (date == null) {
log.debug("Invalid / missing Date header");
return false;
}
@ -162,15 +172,19 @@ class ResponseCachingPolicy {
while (it.hasNext()) {
final HeaderElement elem = it.next();
if ("*".equals(elem.getName())) {
if (log.isDebugEnabled()) {
log.debug("Vary * found");
}
return false;
}
}
if (isExplicitlyNonCacheable(response)) {
log.debug("Response is explicitly non-cacheable");
return false;
}
return (cacheable || isExplicitlyCacheable(response));
return cacheable || isExplicitlyCacheable(response);
}
private boolean unknownStatusCode(final int status) {
@ -239,34 +253,39 @@ class ResponseCachingPolicy {
* @return {@code true} if response is cacheable
*/
public boolean isResponseCacheable(final HttpRequest request, final HttpResponse response) {
if (requestProtocolGreaterThanAccepted(request)) {
log.debug("Response was not cacheable.");
final ProtocolVersion version = request.getVersion() != null ? request.getVersion() : HttpVersion.DEFAULT;
if (version.compareToVersion(HttpVersion.HTTP_1_1) > 0) {
if (log.isDebugEnabled()) {
log.debug("Protocol version " + version + " is non-cacheable");
}
return false;
}
final String[] uncacheableRequestDirectives = { HeaderConstants.CACHE_CONTROL_NO_STORE };
if (hasCacheControlParameterFrom(request,uncacheableRequestDirectives)) {
log.debug("Response is explcitily non-cacheable per cache control directive");
return false;
}
if (request.getRequestUri().contains("?")) {
if (neverCache1_0ResponsesWithQueryString && from1_0Origin(response)) {
log.debug("Response was not cacheable as it had a query string.");
log.debug("Response is not cacheable as it had a query string");
return false;
} else if (!isExplicitlyCacheable(response)) {
log.debug("Response was not cacheable as it is missing explicit caching headers.");
log.debug("Response is not cacheable as it is missing explicit caching headers");
return false;
}
}
if (expiresHeaderLessOrEqualToDateHeaderAndNoCacheControl(response)) {
log.debug("Expires header less or equal to Date header and no cache control directives");
return false;
}
if (sharedCache) {
final Header[] authNHeaders = request.getHeaders(HeaderConstants.AUTHORIZATION);
if (authNHeaders != null && authNHeaders.length > 0
if (request.containsHeaders(HeaderConstants.AUTHORIZATION) > 0
&& !hasCacheControlParameterFrom(response, AUTH_CACHEABLE_PARAMS)) {
log.debug("Request contains private credentials");
return false;
}
}
@ -275,8 +294,7 @@ class ResponseCachingPolicy {
return isResponseCacheable(method, response);
}
private boolean expiresHeaderLessOrEqualToDateHeaderAndNoCacheControl(
final HttpResponse response) {
private boolean expiresHeaderLessOrEqualToDateHeaderAndNoCacheControl(final HttpResponse response) {
if (response.getFirstHeader(HeaderConstants.CACHE_CONTROL) != null) {
return false;
}
@ -308,9 +326,4 @@ class ResponseCachingPolicy {
return HttpVersion.HTTP_1_0.equals(version);
}
private boolean requestProtocolGreaterThanAccepted(final HttpRequest req) {
final ProtocolVersion version = req.getVersion() != null ? req.getVersion() : HttpVersion.DEFAULT;
return version.compareToVersion(HttpVersion.HTTP_1_1) > 0;
}
}