Tweaked logging in caching components

git-svn-id: https://svn.apache.org/repos/asf/httpcomponents/httpclient/trunk@942073 13f79535-47bb-0310-9956-ffa450edef68
This commit is contained in:
Oleg Kalnichevski 2010-05-07 13:53:13 +00:00
parent fd2e7a79a9
commit f749748401
6 changed files with 95 additions and 65 deletions

View File

@ -395,4 +395,10 @@ public class CacheEntry implements Serializable {
return Collections.unmodifiableSet(this.variantURIs);
}
@Override
public String toString() {
return "[request date=" + requestDate + "; response date=" + responseDate
+ "; status=" + status + "]";
}
}

View File

@ -48,7 +48,7 @@ public class CacheInvalidator {
private final HttpCache<CacheEntry> cache;
private final URIExtractor uriExtractor;
private final Log LOG = LogFactory.getLog(CacheInvalidator.class);
private final Log log = LogFactory.getLog(getClass());
/**
*
@ -68,17 +68,15 @@ public class CacheInvalidator {
* @param req The HttpRequest to that host
*/
public void flushInvalidatedCacheEntries(HttpHost host, HttpRequest req) {
LOG.debug("CacheInvalidator: flushInvalidatedCacheEntries, BEGIN");
if (requestShouldNotBeCached(req)) {
LOG.debug("CacheInvalidator: flushInvalidatedCacheEntries, Request should not be cached");
log.debug("Request should not be cached");
try {
String theUri = uriExtractor.getURI(host, req);
CacheEntry parent = cache.getEntry(theUri);
LOG.debug("CacheInvalidator: flushInvalidatedCacheEntries: " + parent);
log.debug("parent entry: " + parent);
if (parent != null) {
for (String variantURI : parent.getVariantURIs()) {
@ -86,9 +84,9 @@ public class CacheInvalidator {
}
cache.removeEntry(theUri);
}
} catch (HttpCacheOperationException coe) {
LOG.warn("Cache: Was unable to REMOVE an entry from the cache based on the uri provided.", coe);
// TODO: track failed state
} catch (HttpCacheOperationException ex) {
log.debug("Was unable to REMOVE an entry from the cache based on the uri provided",
ex);
}
}
}

View File

@ -42,7 +42,7 @@ import org.apache.http.annotation.Immutable;
@Immutable
public class CacheableRequestPolicy {
private final Log LOG = LogFactory.getLog(CacheableRequestPolicy.class);
private final Log log = LogFactory.getLog(getClass());
/**
* Determines if an HttpRequest can be served from the cache.
@ -56,17 +56,17 @@ public class CacheableRequestPolicy {
ProtocolVersion pv = request.getRequestLine().getProtocolVersion();
if (CachingHttpClient.HTTP_1_1.compareToVersion(pv) != 0) {
LOG.debug("CacheableRequestPolicy: Request WAS NOT serveable from Cache.");
log.debug("Request was not serveable from cache");
return false;
}
if (!method.equals(HeaderConstants.GET_METHOD)) {
LOG.debug("CacheableRequestPolicy: Request WAS NOT serveable from Cache.");
log.debug("Request was not serveable from cache");
return false;
}
if (request.getHeaders(HeaderConstants.PRAGMA).length > 0) {
LOG.debug("CacheableRequestPolicy: Request WAS NOT serveable from Cache.");
log.debug("Request was not serveable from cache");
return false;
}
@ -75,19 +75,19 @@ public class CacheableRequestPolicy {
for (HeaderElement cacheControlElement : cacheControl.getElements()) {
if (HeaderConstants.CACHE_CONTROL_NO_STORE.equalsIgnoreCase(cacheControlElement
.getName())) {
LOG.debug("CacheableRequestPolicy: Request WAS NOT serveable from Cache.");
log.debug("Request was not serveable from Cache");
return false;
}
if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equalsIgnoreCase(cacheControlElement
.getName())) {
LOG.debug("CacheableRequestPolicy: Request WAS NOT serveable from Cache.");
log.debug("Request was not serveable from cache");
return false;
}
}
}
LOG.debug("CacheableRequestPolicy: Request WAS serveable from Cache.");
log.debug("Request was serveable from cache");
return true;
}

View File

@ -43,7 +43,7 @@ import org.apache.http.annotation.Immutable;
@Immutable
public class CachedResponseSuitabilityChecker {
private final Log LOG = LogFactory.getLog(CachedResponseSuitabilityChecker.class);
private final Log log = LogFactory.getLog(getClass());
/**
* @param host
@ -56,29 +56,29 @@ public class CachedResponseSuitabilityChecker {
*/
public boolean canCachedResponseBeUsed(HttpHost host, HttpRequest request, CacheEntry entry) {
if (!entry.isResponseFresh()) {
LOG.debug("CachedResponseSuitabilityChecker: Cache Entry was NOT fresh enough");
log.debug("Cache entry was not fresh enough");
return false;
}
if (!entry.contentLengthHeaderMatchesActualLength()) {
LOG.debug("CachedResponseSuitabilityChecker: Cache Entry Content Length and header information DO NOT match.");
log.debug("Cache entry Content-Length and header information do not match");
return false;
}
if (entry.modifiedSince(request)) {
LOG.debug("CachedResponseSuitabilityChecker: Cache Entry modified times didn't line up. Cache Entry should NOT be used.");
log.debug("Cache entry modified times didn't line up. Cache Entry should not be used");
return false;
}
for (Header ccHdr : request.getHeaders(HeaderConstants.CACHE_CONTROL)) {
for (HeaderElement elt : ccHdr.getElements()) {
if (HeaderConstants.CACHE_CONTROL_NO_CACHE.equals(elt.getName())) {
LOG.debug("CachedResponseSuitabilityChecker: 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.debug("CachedResponseSuitabilityChecker: Response contained NO SORE directive, cache was NOT suitable.");
log.debug("Response contained NO SORE directive, cache was not suitable");
return false;
}
@ -86,12 +86,12 @@ public class CachedResponseSuitabilityChecker {
try {
int maxage = Integer.parseInt(elt.getValue());
if (entry.getCurrentAgeSecs() > maxage) {
LOG.debug("CachedResponseSuitabilityChecker: 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 (NumberFormatException nfe) {
} catch (NumberFormatException ex) {
// err conservatively
LOG.debug("CachedResponseSuitabilityChecker: Response from cache was NOT suitable. "+nfe);
log.debug("Response from cache was malformed: " + ex.getMessage());
return false;
}
}
@ -100,12 +100,12 @@ public class CachedResponseSuitabilityChecker {
try {
int maxstale = Integer.parseInt(elt.getValue());
if (entry.getFreshnessLifetimeSecs() > maxstale) {
LOG.debug("CachedResponseSuitabilityChecker: 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 (NumberFormatException nfe) {
} catch (NumberFormatException ex) {
// err conservatively
LOG.debug("CachedResponseSuitabilityChecker: Response from cache was NOT suitable. "+nfe);
log.debug("Response from cache was malformed: " + ex.getMessage());
return false;
}
}
@ -114,19 +114,20 @@ public class CachedResponseSuitabilityChecker {
try {
int minfresh = Integer.parseInt(elt.getValue());
if (entry.getFreshnessLifetimeSecs() < minfresh) {
LOG.debug("CachedResponseSuitabilityChecker: Response from cache was NOT suitable due to min fresh freshness requirement");
log.debug("Response from cache was not suitable due to min fresh " +
"freshness requirement");
return false;
}
} catch (NumberFormatException nfe) {
} catch (NumberFormatException ex) {
// err conservatively
LOG.debug("CachedResponseSuitabilityChecker: Response from cache was NOT suitable. " + nfe);
log.debug("Response from cache was malformed: " + ex.getMessage());
return false;
}
}
}
}
LOG.debug("CachedResponseSuitabilityChecker: Response from cache was suitable.");
log.debug("Response from cache was suitable");
return true;
}
}

View File

@ -91,7 +91,7 @@ public class CachingHttpClient implements HttpClient {
private final ResponseProtocolCompliance responseCompliance;
private final RequestProtocolCompliance requestCompliance;
private final Log LOG = LogFactory.getLog(CachingHttpClient.class);
private final Log log = LogFactory.getLog(getClass());
public CachingHttpClient() {
this.backend = new DefaultHttpClient();
@ -330,8 +330,8 @@ public class CachingHttpClient implements HttpClient {
CacheEntry entry = null;
try {
entry = responseCache.getEntry(uri);
} catch (HttpCacheOperationException probablyIgnore) {
LOG.warn("Cache: Was unable to get an entry from the cache based on the uri provided.", probablyIgnore);
} catch (HttpCacheOperationException ex) {
log.debug("Was unable to get an entry from the cache based on the uri provided", ex);
}
if (entry == null || !entry.hasVariants())
@ -340,7 +340,7 @@ public class CachingHttpClient implements HttpClient {
String variantUri = uriExtractor.getVariantURI(target, request, entry);
try {
return responseCache.getEntry(variantUri);
} catch (HttpCacheOperationException probablyIgnore) {
} catch (HttpCacheOperationException ex) {
return null;
}
}
@ -384,11 +384,19 @@ public class CachingHttpClient implements HttpClient {
CacheEntry entry = getCacheEntry(target, request);
if (entry == null) {
cacheMisses.getAndIncrement();
LOG.debug("CLIENT: Cache Miss.");
if (log.isDebugEnabled()) {
RequestLine rl = request.getRequestLine();
log.debug("Cache miss [host: " + target + "; uri: " + rl.getUri() + "]");
}
return callBackend(target, request, context);
}
LOG.debug("CLIENT: Cache HIT.");
if (log.isDebugEnabled()) {
RequestLine rl = request.getRequestLine();
log.debug("Cache hit [host: " + target + "; uri: " + rl.getUri() + "]");
}
cacheHits.getAndIncrement();
if (suitabilityChecker.canCachedResponseBeUsed(target, request, entry)) {
@ -396,14 +404,14 @@ public class CachingHttpClient implements HttpClient {
}
if (entry.isRevalidatable()) {
LOG.debug("CLIENT: Revalidate the entry.");
log.debug("Revalidating the cache entry");
try {
return revalidateCacheEntry(target, request, context, entry);
} catch (IOException ioex) {
HttpResponse response = responseGenerator.generateResponse(entry);
response.addHeader(HeaderConstants.WARNING, "111 Revalidation Failed - " + ioex.getMessage());
LOG.debug("111 revalidation failed due to exception: " + ioex);
log.debug("111 revalidation failed due to exception: " + ioex);
return response;
} catch (ProtocolException e) {
throw new ClientProtocolException(e);
@ -433,7 +441,7 @@ public class CachingHttpClient implements HttpClient {
Date requestDate = getCurrentDate();
try {
LOG.debug("CLIENT: Calling the backend.");
log.debug("Calling the backend");
HttpResponse backendResponse = backend.execute(target, request, context);
return handleBackendResponse(target, request, requestDate, getCurrentDate(),
backendResponse);
@ -447,8 +455,11 @@ public class CachingHttpClient implements HttpClient {
}
protected HttpResponse revalidateCacheEntry(HttpHost target, HttpRequest request,
HttpContext context, CacheEntry cacheEntry) throws IOException, ProtocolException {
protected HttpResponse revalidateCacheEntry(
HttpHost target,
HttpRequest request,
HttpContext context,
CacheEntry cacheEntry) throws IOException, ProtocolException {
HttpRequest conditionalRequest = conditionalRequestBuilder.buildConditionalRequest(request, cacheEntry);
Date requestDate = getCurrentDate();
@ -472,10 +483,12 @@ public class CachingHttpClient implements HttpClient {
if (entry.hasVariants()) {
try {
String uri = uriExtractor.getURI(target, request);
HttpCacheUpdateCallback<CacheEntry> callback = storeVariantEntry(target, request, entry);
HttpCacheUpdateCallback<CacheEntry> callback = storeVariantEntry(
target, request, entry);
responseCache.updateCacheEntry(uri, callback);
} catch (HttpCacheOperationException probablyIgnore) {
LOG.warn("Cache: Was unable to PUT/UPDATE an entry into the cache based on the uri provided.", probablyIgnore);
} catch (HttpCacheOperationException ex) {
log.debug("Was unable to PUT/UPDATE an entry into the cache based on the uri provided",
ex);
}
} else {
storeNonVariantEntry(target, request, entry);
@ -486,13 +499,15 @@ public class CachingHttpClient implements HttpClient {
String uri = uriExtractor.getURI(target, req);
try {
responseCache.putEntry(uri, entry);
} catch (HttpCacheOperationException probablyIgnore) {
LOG.warn("Cache: Was unable to PUT an entry into the cache based on the uri provided.", probablyIgnore);
} catch (HttpCacheOperationException ex) {
log.debug("Was unable to PUT an entry into the cache based on the uri provided", ex);
}
}
protected HttpCacheUpdateCallback<CacheEntry> storeVariantEntry(final HttpHost target, final HttpRequest req,
final CacheEntry entry) {
protected HttpCacheUpdateCallback<CacheEntry> storeVariantEntry(
final HttpHost target,
final HttpRequest req,
final CacheEntry entry) {
return new HttpCacheUpdateCallback<CacheEntry>() {
public CacheEntry getUpdatedEntry(CacheEntry existing) throws HttpCacheOperationException {
@ -502,7 +517,11 @@ public class CachingHttpClient implements HttpClient {
};
}
protected CacheEntry doGetUpdatedParentEntry(CacheEntry existing, HttpHost target, HttpRequest req, CacheEntry entry) throws HttpCacheOperationException {
protected CacheEntry doGetUpdatedParentEntry(
CacheEntry existing,
HttpHost target,
HttpRequest req,
CacheEntry entry) throws HttpCacheOperationException {
String variantURI = uriExtractor.getVariantURI(target, req, entry);
responseCache.putEntry(variantURI, entry);
@ -514,10 +533,14 @@ public class CachingHttpClient implements HttpClient {
}
}
protected HttpResponse handleBackendResponse(HttpHost target, HttpRequest request,
Date requestDate, Date responseDate, HttpResponse backendResponse) throws IOException {
protected HttpResponse handleBackendResponse(
HttpHost target,
HttpRequest request,
Date requestDate,
Date responseDate,
HttpResponse backendResponse) throws IOException {
LOG.debug("CLIENT: Handling Backend response.");
log.debug("Handling Backend response");
responseCompliance.ensureProtocolCompliance(request, backendResponse);
boolean cacheable = responseCachingPolicy.isResponseCacheable(request, backendResponse);
@ -530,8 +553,11 @@ public class CachingHttpClient implements HttpClient {
return responseReader.getReconstructedResponse();
}
CacheEntry entry = cacheEntryGenerator.generateEntry(requestDate, responseDate,
backendResponse, responseReader.getResponseBytes());
CacheEntry entry = cacheEntryGenerator.generateEntry(
requestDate,
responseDate,
backendResponse,
responseReader.getResponseBytes());
storeInCache(target, request, entry);
return responseGenerator.generateResponse(entry);
}
@ -539,9 +565,8 @@ public class CachingHttpClient implements HttpClient {
String uri = uriExtractor.getURI(target, request);
try {
responseCache.removeEntry(uri);
} catch (HttpCacheOperationException coe) {
LOG.warn("Cache: Was unable to remove an entry from the cache based on the uri provided.", coe);
// TODO: track failed state
} catch (HttpCacheOperationException ex) {
log.debug("Was unable to remove an entry from the cache based on the uri provided", ex);
}
return backendResponse;
}

View File

@ -46,7 +46,7 @@ import org.apache.http.impl.cookie.DateUtils;
public class ResponseCachingPolicy {
private final int maxObjectSizeBytes;
private final Log LOG = LogFactory.getLog(ResponseCachingPolicy.class);
private final Log log = LogFactory.getLog(getClass());
/**
*
@ -67,7 +67,7 @@ public class ResponseCachingPolicy {
boolean cacheable = false;
if (!HeaderConstants.GET_METHOD.equals(httpMethod)) {
LOG.debug("ResponseCachingPolicy: response was not cacheable.");
log.debug("Response was not cacheable.");
return false;
}
@ -79,18 +79,18 @@ public class ResponseCachingPolicy {
case HttpStatus.SC_GONE:
// these response codes MAY be cached
cacheable = true;
LOG.debug("ResponseCachingPolicy: response WAS cacheable.");
log.debug("Response was cacheable");
break;
case HttpStatus.SC_PARTIAL_CONTENT:
// we don't implement Range requests and hence are not
// allowed to cache partial content
LOG.debug("ResponseCachingPolicy: response was not cacheable (Partial Content).");
log.debug("Response was not cacheable (Partial Content)");
return cacheable;
default:
// If the status code is not one of the recognized
// available codes in HttpStatus Don't Cache
LOG.debug("ResponseCachingPolicy: response was not cacheable (Unknown Status code).");
log.debug("Response was not cacheable (Unknown Status code)");
return cacheable;
}
@ -175,12 +175,12 @@ public class ResponseCachingPolicy {
*/
public boolean isResponseCacheable(HttpRequest request, HttpResponse response) {
if (requestProtocolGreaterThanAccepted(request)) {
LOG.debug("ResponseCachingPolicy: response was not cacheable.");
log.debug("Response was not cacheable.");
return false;
}
if (request.getRequestLine().getUri().contains("?") && !isExplicitlyCacheable(response)) {
LOG.debug("ResponseCachingPolicy: response was not cacheable.");
log.debug("Response was not cacheable.");
return false;
}