Improved context and wire logging

This commit is contained in:
Oleg Kalnichevski 2020-12-20 14:00:19 +01:00
parent a0b4dbb34b
commit 8285223560
37 changed files with 297 additions and 190 deletions

View File

@ -80,11 +80,14 @@ public class DefaultAuthenticationStrategy implements AuthenticationStrategy {
Args.notNull(challenges, "Map of auth challenges");
Args.notNull(context, "HTTP context");
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
final List<AuthScheme> options = new ArrayList<>();
final Lookup<AuthSchemeFactory> registry = clientContext.getAuthSchemeRegistry();
if (registry == null) {
LOG.debug("Auth scheme registry not set in the context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Auth scheme registry not set in the context", exchangeId);
}
return options;
}
final RequestConfig config = clientContext.getRequestConfig();
@ -94,7 +97,9 @@ public class DefaultAuthenticationStrategy implements AuthenticationStrategy {
authPrefs = DEFAULT_SCHEME_PRIORITY;
}
if (LOG.isDebugEnabled()) {
LOG.debug("Authentication schemes in the order of preference: {}", authPrefs);
if (LOG.isDebugEnabled()) {
LOG.debug("{} Authentication schemes in the order of preference: {}", exchangeId, authPrefs);
}
}
for (final String schemeName: authPrefs) {
@ -103,7 +108,7 @@ public class DefaultAuthenticationStrategy implements AuthenticationStrategy {
final AuthSchemeFactory authSchemeFactory = registry.lookup(schemeName);
if (authSchemeFactory == null) {
if (LOG.isWarnEnabled()) {
LOG.warn("Authentication scheme {} not supported", schemeName);
LOG.warn("{} Authentication scheme {} not supported", exchangeId, schemeName);
// Try again
}
continue;
@ -112,7 +117,7 @@ public class DefaultAuthenticationStrategy implements AuthenticationStrategy {
options.add(authScheme);
} else {
if (LOG.isDebugEnabled()) {
LOG.debug("Challenge for {} authentication scheme not available", schemeName);
LOG.debug("{}, Challenge for {} authentication scheme not available", exchangeId, schemeName);
}
}
}

View File

@ -129,7 +129,7 @@ public final class AsyncConnectExec implements AsyncExecChainHandler {
if (!execRuntime.isEndpointAcquired()) {
final Object userToken = clientContext.getUserToken();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: acquiring connection with route {}", exchangeId, route);
LOG.debug("{} acquiring connection with route {}", exchangeId, route);
}
cancellableDependency.setDependency(execRuntime.acquireEndpoint(
exchangeId, route, userToken, clientContext, new FutureCallback<AsyncExecRuntime>() {
@ -198,7 +198,7 @@ public final class AsyncConnectExec implements AsyncExecChainHandler {
public void completed(final AsyncExecRuntime execRuntime) {
tracker.connectTarget(route.isSecure());
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connected to target", exchangeId);
LOG.debug("{} connected to target", exchangeId);
}
proceedToNextHop(state, request, entityProducer, scope, chain, asyncExecCallback);
}
@ -224,7 +224,7 @@ public final class AsyncConnectExec implements AsyncExecChainHandler {
final HttpHost proxy = route.getProxyHost();
tracker.connectProxy(proxy, route.isSecure() && !route.isTunnelled());
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connected to proxy", exchangeId);
LOG.debug("{} connected to proxy", exchangeId);
}
proceedToNextHop(state, request, entityProducer, scope, chain, asyncExecCallback);
}
@ -264,7 +264,7 @@ public final class AsyncConnectExec implements AsyncExecChainHandler {
@Override
public void completed() {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: tunnel to target created", exchangeId);
LOG.debug("{} tunnel to target created", exchangeId);
}
tracker.tunnelTarget(false);
proceedToNextHop(state, request, entityProducer, scope, chain, asyncExecCallback);
@ -292,7 +292,7 @@ public final class AsyncConnectExec implements AsyncExecChainHandler {
case HttpRouteDirector.LAYER_PROTOCOL:
execRuntime.upgradeTls(clientContext);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: upgraded to TLS", exchangeId);
LOG.debug("{} upgraded to TLS", exchangeId);
}
tracker.layerProtocol(route.isSecure());
break;
@ -304,7 +304,7 @@ public final class AsyncConnectExec implements AsyncExecChainHandler {
case HttpRouteDirector.COMPLETE:
if (LOG.isDebugEnabled()) {
LOG.debug("{}: route fully established", exchangeId);
LOG.debug("{} route fully established", exchangeId);
}
try {
chain.proceed(request, entityProducer, scope, asyncExecCallback);

View File

@ -102,7 +102,7 @@ public final class AsyncHttpRequestRetryExec implements AsyncExecChainHandler {
final HttpClientContext clientContext = scope.clientContext;
if (entityProducer != null && !entityProducer.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot retry non-repeatable request", exchangeId);
LOG.debug("{} cannot retry non-repeatable request", exchangeId);
}
return asyncExecCallback.handleResponse(response, entityDetails);
}
@ -140,11 +140,11 @@ public final class AsyncHttpRequestRetryExec implements AsyncExecChainHandler {
final HttpClientContext clientContext = scope.clientContext;
if (entityProducer != null && !entityProducer.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot retry non-repeatable request", exchangeId);
LOG.debug("{} cannot retry non-repeatable request", exchangeId);
}
} else if (retryStrategy.retryRequest(request, (IOException) cause, state.execCount, clientContext)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: {}", exchangeId, cause.getMessage(), cause);
LOG.debug("{} {}", exchangeId, cause.getMessage(), cause);
}
if (LOG.isInfoEnabled()) {
LOG.info("Recoverable I/O exception ({}) caught when processing request to {}",

View File

@ -168,13 +168,13 @@ public final class AsyncProtocolExec implements AsyncExecChainHandler {
if (!request.containsHeader(HttpHeaders.AUTHORIZATION)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: target auth state: {}", exchangeId, targetAuthExchange.getState());
LOG.debug("{} target auth state: {}", exchangeId, targetAuthExchange.getState());
}
authenticator.addAuthResponse(target, ChallengeType.TARGET, request, targetAuthExchange, clientContext);
}
if (!request.containsHeader(HttpHeaders.PROXY_AUTHORIZATION) && !route.isTunnelled()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: proxy auth state: {}", exchangeId, proxyAuthExchange.getState());
LOG.debug("{} proxy auth state: {}", exchangeId, proxyAuthExchange.getState());
}
authenticator.addAuthResponse(proxy, ChallengeType.PROXY, request, proxyAuthExchange, clientContext);
}
@ -213,14 +213,14 @@ public final class AsyncProtocolExec implements AsyncExecChainHandler {
if (proxyAuthExchange.getState() == AuthExchange.State.SUCCESS
&& proxyAuthExchange.isConnectionBased()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting proxy auth state", exchangeId);
LOG.debug("{} resetting proxy auth state", exchangeId);
}
proxyAuthExchange.reset();
}
if (targetAuthExchange.getState() == AuthExchange.State.SUCCESS
&& targetAuthExchange.isConnectionBased()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting target auth state", exchangeId);
LOG.debug("{} resetting target auth state", exchangeId);
}
targetAuthExchange.reset();
}
@ -229,7 +229,7 @@ public final class AsyncProtocolExec implements AsyncExecChainHandler {
if (challenged.get()) {
if (entityProducer != null && !entityProducer.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot retry non-repeatable request", exchangeId);
LOG.debug("{} cannot retry non-repeatable request", exchangeId);
}
asyncExecCallback.completed();
} else {

View File

@ -127,7 +127,7 @@ public final class AsyncRedirectExec implements AsyncExecChainHandler {
final URI redirectUri = redirectStrategy.getLocationURI(request, response, clientContext);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: redirect requested to location '{}'", exchangeId, redirectUri);
LOG.debug("{} redirect requested to location '{}'", exchangeId, redirectUri);
}
if (!config.isCircularRedirectsAllowed()) {
if (state.redirectLocations.contains(redirectUri)) {
@ -171,14 +171,14 @@ public final class AsyncRedirectExec implements AsyncExecChainHandler {
state.reroute = true;
final AuthExchange targetAuthExchange = clientContext.getAuthExchange(currentRoute.getTargetHost());
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting target auth state", exchangeId);
LOG.debug("{} resetting target auth state", exchangeId);
}
targetAuthExchange.reset();
if (currentRoute.getProxyHost() != null) {
final AuthExchange proxyAuthExchange = clientContext.getAuthExchange(currentRoute.getProxyHost());
if (proxyAuthExchange.isConnectionBased()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting proxy auth state", exchangeId);
LOG.debug("{} resetting proxy auth state", exchangeId);
}
proxyAuthExchange.reset();
}
@ -190,7 +190,7 @@ public final class AsyncRedirectExec implements AsyncExecChainHandler {
}
if (state.redirectURI != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: redirecting to '{}' via {}", exchangeId, state.redirectURI, currentRoute);
LOG.debug("{} redirecting to '{}' via {}", exchangeId, state.redirectURI, currentRoute);
}
return null;
}
@ -214,7 +214,7 @@ public final class AsyncRedirectExec implements AsyncExecChainHandler {
}
if (entityProducer != null && !entityProducer.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot redirect non-repeatable request", exchangeId);
LOG.debug("{} cannot redirect non-repeatable request", exchangeId);
}
asyncExecCallback.completed();
} else {

View File

@ -83,7 +83,7 @@ public class H2AsyncMainClientExec implements AsyncExecChainHandler {
final AsyncExecRuntime execRuntime = scope.execRuntime;
if (LOG.isDebugEnabled()) {
LOG.debug("{}: executing {}", exchangeId, new RequestLine(request));
LOG.debug("{} executing {}", exchangeId, new RequestLine(request));
}
final AsyncClientExchangeHandler internalExchangeHandler = new AsyncClientExchangeHandler() {

View File

@ -98,7 +98,7 @@ class HttpAsyncMainClientExec implements AsyncExecChainHandler {
final AsyncExecRuntime execRuntime = scope.execRuntime;
if (LOG.isDebugEnabled()) {
LOG.debug("{}: executing {}", exchangeId, new RequestLine(request));
LOG.debug("{} executing {}", exchangeId, new RequestLine(request));
}
final AtomicInteger messageCountDown = new AtomicInteger(2);

View File

@ -180,10 +180,11 @@ abstract class InternalAbstractHttpAsyncClient extends AbstractHttpAsyncClientBa
clientContext);
final String exchangeId = ExecSupport.getNextExchangeId();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: preparing request execution", exchangeId);
LOG.debug("{} preparing request execution", exchangeId);
}
final AsyncExecRuntime execRuntime = createAsyncExecRuntime(pushHandlerFactory);
clientContext.setExchangeId(exchangeId);
setupContext(clientContext);
final AsyncExecChain.Scope scope = new AsyncExecChain.Scope(exchangeId, route, request, future,
@ -290,7 +291,7 @@ abstract class InternalAbstractHttpAsyncClient extends AbstractHttpAsyncClientBa
@Override
public void completed() {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: message exchange successfully completed", exchangeId);
LOG.debug("{} message exchange successfully completed", exchangeId);
}
try {
execRuntime.releaseEndpoint();
@ -303,7 +304,7 @@ abstract class InternalAbstractHttpAsyncClient extends AbstractHttpAsyncClientBa
@Override
public void failed(final Exception cause) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: request failed: {}", exchangeId, cause.getMessage());
LOG.debug("{} request failed: {}", exchangeId, cause.getMessage());
}
try {
execRuntime.discardEndpoint();

View File

@ -89,7 +89,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout connectTimeout = requestConfig.getConnectTimeout();
if (log.isDebugEnabled()) {
log.debug("{}: acquiring endpoint ({})", id, connectTimeout);
log.debug("{} acquiring endpoint ({})", id, connectTimeout);
}
return Operations.cancellable(connPool.getSession(
target,
@ -101,7 +101,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
sessionRef.set(new Endpoint(target, ioSession));
reusable = true;
if (log.isDebugEnabled()) {
log.debug("{}: acquired endpoint", id);
log.debug("{} acquired endpoint", id);
}
callback.completed(InternalH2AsyncExecRuntime.this);
}
@ -125,7 +125,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
private void closeEndpoint(final Endpoint endpoint) {
endpoint.session.close(CloseMode.GRACEFUL);
if (log.isDebugEnabled()) {
log.debug("{}: endpoint closed", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint closed", ConnPoolSupport.getId(endpoint));
}
}
@ -186,7 +186,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout connectTimeout = requestConfig.getConnectTimeout();
if (log.isDebugEnabled()) {
log.debug("{}: connecting endpoint ({})", ConnPoolSupport.getId(endpoint), connectTimeout);
log.debug("{} connecting endpoint ({})", ConnPoolSupport.getId(endpoint), connectTimeout);
}
return Operations.cancellable(connPool.getSession(target, connectTimeout,
new FutureCallback<IOSession>() {
@ -196,7 +196,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
sessionRef.set(new Endpoint(target, ioSession));
reusable = true;
if (log.isDebugEnabled()) {
log.debug("{}: endpoint connected", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint connected", ConnPoolSupport.getId(endpoint));
}
callback.completed(InternalH2AsyncExecRuntime.this);
}
@ -229,7 +229,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
final IOSession session = endpoint.session;
if (session.isOpen()) {
if (log.isDebugEnabled()) {
log.debug("{}: start execution {}", ConnPoolSupport.getId(endpoint), id);
log.debug("{} start execution {}", ConnPoolSupport.getId(endpoint), id);
}
session.enqueue(
new RequestExecutionCommand(exchangeHandler, pushHandlerFactory, complexCancellable, context),
@ -245,7 +245,7 @@ class InternalH2AsyncExecRuntime implements AsyncExecRuntime {
sessionRef.set(new Endpoint(target, ioSession));
reusable = true;
if (log.isDebugEnabled()) {
log.debug("{}: start execution {}", ConnPoolSupport.getId(endpoint), id);
log.debug("{} start execution {}", ConnPoolSupport.getId(endpoint), id);
}
session.enqueue(
new RequestExecutionCommand(exchangeHandler, pushHandlerFactory, complexCancellable, context),

View File

@ -95,7 +95,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout connectionRequestTimeout = requestConfig.getConnectionRequestTimeout();
if (log.isDebugEnabled()) {
log.debug("{}: acquiring endpoint ({})", id, connectionRequestTimeout);
log.debug("{} acquiring endpoint ({})", id, connectionRequestTimeout);
}
return Operations.cancellable(manager.lease(
id,
@ -109,7 +109,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
endpointRef.set(connectionEndpoint);
reusable = connectionEndpoint.isConnected();
if (log.isDebugEnabled()) {
log.debug("{}: acquired endpoint {}", id, ConnPoolSupport.getId(connectionEndpoint));
log.debug("{} acquired endpoint {}", id, ConnPoolSupport.getId(connectionEndpoint));
}
callback.completed(InternalHttpAsyncExecRuntime.this);
}
@ -133,11 +133,11 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
try {
endpoint.close(CloseMode.IMMEDIATE);
if (log.isDebugEnabled()) {
log.debug("{}: endpoint closed", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint closed", ConnPoolSupport.getId(endpoint));
}
} finally {
if (log.isDebugEnabled()) {
log.debug("{}: discarding endpoint", ConnPoolSupport.getId(endpoint));
log.debug("{} discarding endpoint", ConnPoolSupport.getId(endpoint));
}
manager.release(endpoint, null, TimeValue.ZERO_MILLISECONDS);
}
@ -149,7 +149,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
if (endpoint != null) {
if (reusable) {
if (log.isDebugEnabled()) {
log.debug("{}: releasing valid endpoint", ConnPoolSupport.getId(endpoint));
log.debug("{} releasing valid endpoint", ConnPoolSupport.getId(endpoint));
}
manager.release(endpoint, state, validDuration);
} else {
@ -205,7 +205,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout connectTimeout = requestConfig.getConnectTimeout();
if (log.isDebugEnabled()) {
log.debug("{}: connecting endpoint ({})", ConnPoolSupport.getId(endpoint), connectTimeout);
log.debug("{} connecting endpoint ({})", ConnPoolSupport.getId(endpoint), connectTimeout);
}
return Operations.cancellable(manager.connect(
endpoint,
@ -218,7 +218,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
@Override
public void completed(final AsyncConnectionEndpoint endpoint) {
if (log.isDebugEnabled()) {
log.debug("{}: endpoint connected", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint connected", ConnPoolSupport.getId(endpoint));
}
callback.completed(InternalHttpAsyncExecRuntime.this);
}
@ -241,7 +241,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
public void upgradeTls(final HttpClientContext context) {
final AsyncConnectionEndpoint endpoint = ensureValid();
if (log.isDebugEnabled()) {
log.debug("{}: upgrading endpoint", ConnPoolSupport.getId(endpoint));
log.debug("{} upgrading endpoint", ConnPoolSupport.getId(endpoint));
}
manager.upgrade(endpoint, versionPolicy, context);
}
@ -252,7 +252,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
final AsyncConnectionEndpoint endpoint = ensureValid();
if (endpoint.isConnected()) {
if (log.isDebugEnabled()) {
log.debug("{}: start execution {}", ConnPoolSupport.getId(endpoint), id);
log.debug("{} start execution {}", ConnPoolSupport.getId(endpoint), id);
}
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout responseTimeout = requestConfig.getResponseTimeout();
@ -275,7 +275,7 @@ class InternalHttpAsyncExecRuntime implements AsyncExecRuntime {
@Override
public void completed(final AsyncExecRuntime runtime) {
if (log.isDebugEnabled()) {
log.debug("{}: start execution {}", ConnPoolSupport.getId(endpoint), id);
log.debug("{} start execution {}", ConnPoolSupport.getId(endpoint), id);
}
try {
endpoint.execute(id, exchangeHandler, pushHandlerFactory, context);

View File

@ -77,7 +77,8 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
final EntityDetails entityDetails,
final HttpContext context) throws HttpException, IOException {
if (log.isDebugEnabled()) {
log.debug("{}: send request {}, {}", exchangeId, new RequestLine(request), entityDetails != null ? "entity len " + entityDetails.getContentLength() : "null entity");
log.debug("{} send request {}, {}", exchangeId, new RequestLine(request),
entityDetails != null ? "entity len " + entityDetails.getContentLength() : "null entity");
}
channel.sendRequest(request, entityDetails, context);
}
@ -93,7 +94,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void produce(final DataStreamChannel channel) throws IOException {
if (log.isDebugEnabled()) {
log.debug("{}: produce request data", exchangeId);
log.debug("{} produce request data", exchangeId);
}
handler.produce(new DataStreamChannel() {
@ -105,7 +106,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public int write(final ByteBuffer src) throws IOException {
if (log.isDebugEnabled()) {
log.debug("{}: produce request data, len {} bytes", exchangeId, src.remaining());
log.debug("{} produce request data, len {} bytes", exchangeId, src.remaining());
}
return channel.write(src);
}
@ -113,7 +114,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void endStream() throws IOException {
if (log.isDebugEnabled()) {
log.debug("{}: end of request data", exchangeId);
log.debug("{} end of request data", exchangeId);
}
channel.endStream();
}
@ -121,7 +122,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void endStream(final List<? extends Header> trailers) throws IOException {
if (log.isDebugEnabled()) {
log.debug("{}: end of request data", exchangeId);
log.debug("{} end of request data", exchangeId);
}
channel.endStream(trailers);
}
@ -134,7 +135,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
final HttpResponse response,
final HttpContext context) throws HttpException, IOException {
if (log.isDebugEnabled()) {
log.debug("{}: information response {}", exchangeId, new StatusLine(response));
log.debug("{} information response {}", exchangeId, new StatusLine(response));
}
handler.consumeInformation(response, context);
}
@ -145,7 +146,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
final EntityDetails entityDetails,
final HttpContext context) throws HttpException, IOException {
if (log.isDebugEnabled()) {
log.debug("{}: consume response {}, {}", exchangeId, new StatusLine(response), entityDetails != null ? "entity len " + entityDetails.getContentLength() : " null entity");
log.debug("{} consume response {}, {}", exchangeId, new StatusLine(response), entityDetails != null ? "entity len " + entityDetails.getContentLength() : " null entity");
}
handler.consumeResponse(response, entityDetails, context);
}
@ -158,7 +159,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void update(final int increment) throws IOException {
if (log.isDebugEnabled()) {
log.debug("{}: capacity update {}", exchangeId, increment);
log.debug("{} capacity update {}", exchangeId, increment);
}
capacityChannel.update(increment);
}
@ -169,7 +170,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void consume(final ByteBuffer src) throws IOException {
if (log.isDebugEnabled()) {
log.debug("{}: consume response data, len {} bytes", exchangeId, src.remaining());
log.debug("{} consume response data, len {} bytes", exchangeId, src.remaining());
}
handler.consume(src);
}
@ -177,7 +178,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void streamEnd(final List<? extends Header> trailers) throws HttpException, IOException {
if (log.isDebugEnabled()) {
log.debug("{}: end of response data", exchangeId);
log.debug("{} end of response data", exchangeId);
}
handler.streamEnd(trailers);
}
@ -185,7 +186,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void failed(final Exception cause) {
if (log.isDebugEnabled()) {
log.debug("{}: execution failed: {}", exchangeId, cause.getMessage());
log.debug("{} execution failed: {}", exchangeId, cause.getMessage());
}
handler.failed(cause);
}
@ -193,7 +194,7 @@ final class LoggingAsyncClientExchangeHandler implements AsyncClientExchangeHand
@Override
public void cancel() {
if (log.isDebugEnabled()) {
log.debug("{}: execution cancelled", exchangeId);
log.debug("{} execution cancelled", exchangeId);
}
handler.cancel();
}

View File

@ -235,7 +235,7 @@ public final class MinimalH2AsyncClient extends AbstractMinimalHttpAsyncClientBa
};
if (LOG.isDebugEnabled()) {
final String exchangeId = ExecSupport.getNextExchangeId();
LOG.debug("{}: executing message exchange {}", ConnPoolSupport.getId(session), exchangeId);
LOG.debug("{} executing message exchange {}", exchangeId, ConnPoolSupport.getId(session));
session.enqueue(
new RequestExecutionCommand(
new LoggingAsyncClientExchangeHandler(LOG, exchangeId, internalExchangeHandler),

View File

@ -469,7 +469,7 @@ public final class MinimalHttpAsyncClient extends AbstractMinimalHttpAsyncClient
final String exchangeId = ExecSupport.getNextExchangeId();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: executing message exchange {}", ConnPoolSupport.getId(connectionEndpoint), exchangeId);
LOG.debug("{} executing message exchange {}", exchangeId, ConnPoolSupport.getId(connectionEndpoint));
connectionEndpoint.execute(
exchangeId,
new LoggingAsyncClientExchangeHandler(LOG, exchangeId, exchangeHandler),

View File

@ -49,6 +49,7 @@ import org.apache.hc.client5.http.auth.AuthenticationException;
import org.apache.hc.client5.http.auth.Credentials;
import org.apache.hc.client5.http.auth.CredentialsProvider;
import org.apache.hc.client5.http.auth.MalformedChallengeException;
import org.apache.hc.client5.http.protocol.HttpClientContext;
import org.apache.hc.client5.http.utils.ByteArrayBuilder;
import org.apache.hc.core5.http.HttpHost;
import org.apache.hc.core5.http.HttpRequest;
@ -154,7 +155,11 @@ public class BasicScheme implements AuthScheme, Serializable {
return true;
}
LOG.debug("No credentials found for auth scope [{}]", authScope);
if (LOG.isDebugEnabled()) {
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
LOG.debug("{} No credentials found for auth scope [{}]", exchangeId, authScope);
}
this.username = null;
this.password = null;
return false;

View File

@ -54,6 +54,7 @@ import org.apache.hc.client5.http.auth.Credentials;
import org.apache.hc.client5.http.auth.CredentialsProvider;
import org.apache.hc.client5.http.auth.MalformedChallengeException;
import org.apache.hc.client5.http.auth.StandardAuthScheme;
import org.apache.hc.client5.http.protocol.HttpClientContext;
import org.apache.hc.client5.http.utils.ByteArrayBuilder;
import org.apache.hc.core5.annotation.Internal;
import org.apache.hc.core5.http.ClassicHttpRequest;
@ -194,7 +195,11 @@ public class DigestScheme implements AuthScheme, Serializable {
return true;
}
LOG.debug("No credentials found for auth scope [{}]", authScope);
if (LOG.isDebugEnabled()) {
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
LOG.debug("{} No credentials found for auth scope [{}]", exchangeId, authScope);
}
this.username = null;
this.password = null;
return false;

View File

@ -44,6 +44,7 @@ import org.apache.hc.client5.http.auth.InvalidCredentialsException;
import org.apache.hc.client5.http.auth.KerberosConfig;
import org.apache.hc.client5.http.auth.KerberosCredentials;
import org.apache.hc.client5.http.auth.MalformedChallengeException;
import org.apache.hc.client5.http.protocol.HttpClientContext;
import org.apache.hc.core5.http.HttpHost;
import org.apache.hc.core5.http.HttpRequest;
import org.apache.hc.core5.http.protocol.HttpContext;
@ -115,7 +116,11 @@ public abstract class GGSSchemeBase implements AuthScheme {
token = Base64.decodeBase64(challenge.getBytes());
state = State.CHALLENGE_RECEIVED;
} else {
LOG.debug("Authentication already attempted");
if (LOG.isDebugEnabled()) {
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
LOG.debug("{} Authentication already attempted", exchangeId);
}
state = State.FAILED;
}
}
@ -220,7 +225,9 @@ public abstract class GGSSchemeBase implements AuthScheme {
final String serviceName = host.getSchemeName().toUpperCase(Locale.ROOT);
if (LOG.isDebugEnabled()) {
LOG.debug("init {}", authServer);
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
LOG.debug("{} init {}", exchangeId, authServer);
}
token = generateToken(token, serviceName, authServer);
state = State.TOKEN_GENERATED;
@ -245,7 +252,9 @@ public abstract class GGSSchemeBase implements AuthScheme {
final Base64 codec = new Base64(0);
final String tokenstr = new String(codec.encode(token));
if (LOG.isDebugEnabled()) {
LOG.debug("Sending response '{}' back to the auth server", tokenstr);
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
LOG.debug("{} Sending response '{}' back to the auth server", exchangeId, tokenstr);
}
return StandardAuthScheme.SPNEGO + " " + tokenstr;
default:

View File

@ -118,9 +118,12 @@ public final class HttpAuthenticator {
}
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
if (response.getCode() == challengeCode) {
log.debug("Authentication required");
if (log.isDebugEnabled()) {
log.debug("{} Authentication required", exchangeId);
}
if (authExchange.getState() == AuthExchange.State.SUCCESS) {
clearCache(host, clientContext);
}
@ -129,7 +132,9 @@ public final class HttpAuthenticator {
switch (authExchange.getState()) {
case CHALLENGED:
case HANDSHAKE:
log.debug("Authentication succeeded");
if (log.isDebugEnabled()) {
log.debug("{} Authentication succeeded", exchangeId);
}
authExchange.setState(AuthExchange.State.SUCCESS);
updateCache(host, authExchange.getAuthScheme(), clientContext);
break;
@ -162,11 +167,12 @@ public final class HttpAuthenticator {
final AuthExchange authExchange,
final HttpContext context) {
if (log.isDebugEnabled()) {
log.debug("{} requested authentication", host.toHostString());
}
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
if (log.isDebugEnabled()) {
log.debug("{} {} requested authentication", exchangeId, host.toHostString());
}
final Header[] headers = response.getHeaders(
challengeType == ChallengeType.PROXY ? HttpHeaders.PROXY_AUTHENTICATE : HttpHeaders.WWW_AUTHENTICATE);
@ -192,7 +198,7 @@ public final class HttpAuthenticator {
authChallenges = parser.parse(challengeType, buffer, cursor);
} catch (final ParseException ex) {
if (log.isWarnEnabled()) {
log.warn("Malformed challenge: {}", header.getValue());
log.warn("{} Malformed challenge: {}", exchangeId, header.getValue());
}
continue;
}
@ -204,7 +210,9 @@ public final class HttpAuthenticator {
}
}
if (challengeMap.isEmpty()) {
log.debug("Response contains no valid authentication challenges");
if (log.isDebugEnabled()) {
log.debug("{} Response contains no valid authentication challenges", exchangeId);
}
clearCache(host, clientContext);
authExchange.reset();
return false;
@ -225,19 +233,23 @@ public final class HttpAuthenticator {
final String schemeName = authScheme.getName();
final AuthChallenge challenge = challengeMap.get(schemeName.toLowerCase(Locale.ROOT));
if (challenge != null) {
log.debug("Authorization challenge processed");
if (log.isDebugEnabled()) {
log.debug("{} Authorization challenge processed", exchangeId);
}
try {
authScheme.processChallenge(challenge, context);
} catch (final MalformedChallengeException ex) {
if (log.isWarnEnabled()) {
log.warn(ex.getMessage());
log.warn("{} {}", exchangeId, ex.getMessage());
}
clearCache(host, clientContext);
authExchange.reset();
return false;
}
if (authScheme.isChallengeComplete()) {
log.debug("Authentication failed");
if (log.isDebugEnabled()) {
log.debug("{} Authentication failed", exchangeId);
}
clearCache(host, clientContext);
authExchange.reset();
authExchange.setState(AuthExchange.State.FAILURE);
@ -254,12 +266,16 @@ public final class HttpAuthenticator {
final List<AuthScheme> preferredSchemes = authStrategy.select(challengeType, challengeMap, context);
final CredentialsProvider credsProvider = clientContext.getCredentialsProvider();
if (credsProvider == null) {
log.debug("Credentials provider not set in the context");
if (log.isDebugEnabled()) {
log.debug("{} Credentials provider not set in the context", exchangeId);
}
return false;
}
final Queue<AuthScheme> authOptions = new LinkedList<>();
log.debug("Selecting authentication options");
if (log.isDebugEnabled()) {
log.debug("{} Selecting authentication options", exchangeId);
}
for (final AuthScheme authScheme: preferredSchemes) {
try {
final String schemeName = authScheme.getName();
@ -276,7 +292,7 @@ public final class HttpAuthenticator {
}
if (!authOptions.isEmpty()) {
if (log.isDebugEnabled()) {
log.debug("Selected authentication options: {}", authOptions);
log.debug("{} Selected authentication options: {}", exchangeId, authOptions);
}
authExchange.reset();
authExchange.setState(AuthExchange.State.CHALLENGED);
@ -302,6 +318,8 @@ public final class HttpAuthenticator {
final HttpRequest request,
final AuthExchange authExchange,
final HttpContext context) {
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
AuthScheme authScheme = authExchange.getAuthScheme();
switch (authExchange.getState()) {
case FAILURE:
@ -322,7 +340,8 @@ public final class HttpAuthenticator {
authScheme = authOptions.remove();
authExchange.select(authScheme);
if (log.isDebugEnabled()) {
log.debug("Generating response to an authentication challenge using {} scheme", authScheme.getName());
log.debug("{} Generating response to an authentication challenge using {} scheme",
exchangeId, authScheme.getName());
}
try {
final String authResponse = authScheme.generateAuthResponse(host, request, context);
@ -333,7 +352,7 @@ public final class HttpAuthenticator {
break;
} catch (final AuthenticationException ex) {
if (log.isWarnEnabled()) {
log.warn("{} authentication error: {}", authScheme, ex.getMessage());
log.warn("{} {} authentication error: {}", exchangeId, authScheme, ex.getMessage());
}
}
}
@ -351,7 +370,7 @@ public final class HttpAuthenticator {
request.addHeader(header);
} catch (final AuthenticationException ex) {
if (log.isErrorEnabled()) {
log.error("{} authentication error: {}", authScheme, ex.getMessage());
log.error("{} {} authentication error: {}", exchangeId, authScheme, ex.getMessage());
}
}
}
@ -366,7 +385,8 @@ public final class HttpAuthenticator {
clientContext.setAuthCache(authCache);
}
if (log.isDebugEnabled()) {
log.debug("Caching '{}' auth scheme for {}", authScheme.getName(), host);
final String exchangeId = clientContext.getExchangeId();
log.debug("{} Caching '{}' auth scheme for {}", exchangeId, authScheme.getName(), host);
}
authCache.put(host, authScheme);
}
@ -377,7 +397,8 @@ public final class HttpAuthenticator {
final AuthCache authCache = clientContext.getAuthCache();
if (authCache != null) {
if (log.isDebugEnabled()) {
log.debug("Clearing cached auth scheme for {}", host);
final String exchangeId = clientContext.getExchangeId();
log.debug("{} Clearing cached auth scheme for {}", exchangeId, host);
}
authCache.remove(host);
}

View File

@ -37,6 +37,7 @@ import org.apache.hc.client5.http.auth.Credentials;
import org.apache.hc.client5.http.auth.CredentialsProvider;
import org.apache.hc.client5.http.auth.MalformedChallengeException;
import org.apache.hc.client5.http.auth.NTCredentials;
import org.apache.hc.client5.http.protocol.HttpClientContext;
import org.apache.hc.core5.http.HttpHost;
import org.apache.hc.core5.http.HttpRequest;
import org.apache.hc.core5.http.protocol.HttpContext;
@ -138,7 +139,11 @@ public final class NTLMScheme implements AuthScheme {
return true;
}
LOG.debug("No credentials found for auth scope [{}]", authScope);
if (LOG.isDebugEnabled()) {
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
LOG.debug("{} No credentials found for auth scope [{}]", exchangeId, authScope);
}
return false;
}

View File

@ -113,14 +113,14 @@ public final class ConnectExec implements ExecChainHandler {
if (!execRuntime.isEndpointAcquired()) {
final Object userToken = context.getUserToken();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: acquiring connection with route {}", exchangeId, route);
LOG.debug("{} acquiring connection with route {}", exchangeId, route);
}
execRuntime.acquireEndpoint(exchangeId, route, userToken, context);
}
try {
if (!execRuntime.isEndpointConnected()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: opening connection {}", exchangeId, route);
LOG.debug("{} opening connection {}", exchangeId, route);
}
final RouteTracker tracker = new RouteTracker(route);
@ -143,7 +143,7 @@ public final class ConnectExec implements ExecChainHandler {
case HttpRouteDirector.TUNNEL_TARGET: {
final boolean secure = createTunnelToTarget(exchangeId, route, request, execRuntime, context);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: tunnel to target created.", exchangeId);
LOG.debug("{} tunnel to target created.", exchangeId);
}
tracker.tunnelTarget(secure);
} break;
@ -156,7 +156,7 @@ public final class ConnectExec implements ExecChainHandler {
final int hop = fact.getHopCount()-1; // the hop to establish
final boolean secure = createTunnelToProxy(route, hop, context);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: tunnel to proxy created.", exchangeId);
LOG.debug("{} tunnel to proxy created.", exchangeId);
}
tracker.tunnelProxy(route.getHopTarget(hop), secure);
} break;
@ -234,7 +234,7 @@ public final class ConnectExec implements ExecChainHandler {
// Retry request
if (this.reuseStrategy.keepAlive(request, response, context)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection kept alive", exchangeId);
LOG.debug("{} connection kept alive", exchangeId);
}
// Consume response content
final HttpEntity entity = response.getEntity();

View File

@ -98,13 +98,13 @@ public class HttpRequestRetryExec implements ExecChainHandler {
final HttpEntity requestEntity = request.getEntity();
if (requestEntity != null && !requestEntity.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot retry non-repeatable request", exchangeId);
LOG.debug("{} cannot retry non-repeatable request", exchangeId);
}
throw ex;
}
if (retryStrategy.retryRequest(request, ex, execCount, context)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: {}", exchangeId, ex.getMessage(), ex);
LOG.debug("{} {}", exchangeId, ex.getMessage(), ex);
}
if (LOG.isInfoEnabled()) {
LOG.info("Recoverable I/O exception ({}) caught when processing request to {}",
@ -127,7 +127,7 @@ public class HttpRequestRetryExec implements ExecChainHandler {
final HttpEntity entity = request.getEntity();
if (entity != null && !entity.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot retry non-repeatable request", exchangeId);
LOG.debug("{} cannot retry non-repeatable request", exchangeId);
}
return response;
}
@ -138,7 +138,7 @@ public class HttpRequestRetryExec implements ExecChainHandler {
if (TimeValue.isPositive(nextInterval)) {
try {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: wait for {}", exchangeId, nextInterval);
LOG.debug("{} wait for {}", exchangeId, nextInterval);
}
nextInterval.sleep();
} catch (final InterruptedException e) {

View File

@ -98,7 +98,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout connectionRequestTimeout = requestConfig.getConnectionRequestTimeout();
if (log.isDebugEnabled()) {
log.debug("{}: acquiring endpoint ({})", id, connectionRequestTimeout);
log.debug("{} acquiring endpoint ({})", id, connectionRequestTimeout);
}
final LeaseRequest connRequest = manager.lease(id, route, connectionRequestTimeout, object);
state = object;
@ -117,7 +117,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
cancellableDependency.setDependency(this);
}
if (log.isDebugEnabled()) {
log.debug("{}: acquired endpoint {}", id, ConnPoolSupport.getId(connectionEndpoint));
log.debug("{} acquired endpoint {}", id, ConnPoolSupport.getId(connectionEndpoint));
}
} catch(final TimeoutException ex) {
throw new ConnectionRequestTimeoutException(ex.getMessage());
@ -159,11 +159,11 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
final RequestConfig requestConfig = context.getRequestConfig();
final Timeout connectTimeout = requestConfig.getConnectTimeout();
if (log.isDebugEnabled()) {
log.debug("{}: connecting endpoint ({})", ConnPoolSupport.getId(endpoint), connectTimeout);
log.debug("{} connecting endpoint ({})", ConnPoolSupport.getId(endpoint), connectTimeout);
}
manager.connect(endpoint, connectTimeout, context);
if (log.isDebugEnabled()) {
log.debug("{}: endpoint connected", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint connected", ConnPoolSupport.getId(endpoint));
}
}
@ -181,7 +181,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
if (endpoint != null) {
endpoint.close();
if (log.isDebugEnabled()) {
log.debug("{}: endpoint closed", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint closed", ConnPoolSupport.getId(endpoint));
}
}
}
@ -190,7 +190,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
public void upgradeTls(final HttpClientContext context) throws IOException {
final ConnectionEndpoint endpoint = ensureValid();
if (log.isDebugEnabled()) {
log.debug("{}: upgrading endpoint", ConnPoolSupport.getId(endpoint));
log.debug("{} upgrading endpoint", ConnPoolSupport.getId(endpoint));
}
manager.upgrade(endpoint, context);
}
@ -210,7 +210,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
endpoint.setSocketTimeout(responseTimeout);
}
if (log.isDebugEnabled()) {
log.debug("{}: start execution {}", ConnPoolSupport.getId(endpoint), id);
log.debug("{} start execution {}", ConnPoolSupport.getId(endpoint), id);
}
return endpoint.execute(id, request, requestExecutor, context);
}
@ -236,11 +236,11 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
try {
endpoint.close(CloseMode.IMMEDIATE);
if (log.isDebugEnabled()) {
log.debug("{}: endpoint closed", ConnPoolSupport.getId(endpoint));
log.debug("{} endpoint closed", ConnPoolSupport.getId(endpoint));
}
} finally {
if (log.isDebugEnabled()) {
log.debug("{}: discarding endpoint", ConnPoolSupport.getId(endpoint));
log.debug("{} discarding endpoint", ConnPoolSupport.getId(endpoint));
}
manager.release(endpoint, null, TimeValue.ZERO_MILLISECONDS);
}
@ -252,7 +252,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
if (endpoint != null) {
if (reusable) {
if (log.isDebugEnabled()) {
log.debug("{}: releasing valid endpoint", ConnPoolSupport.getId(endpoint));
log.debug("{} releasing valid endpoint", ConnPoolSupport.getId(endpoint));
}
manager.release(endpoint, state, validDuration);
} else {
@ -275,7 +275,7 @@ class InternalExecRuntime implements ExecRuntime, Cancellable {
final ConnectionEndpoint endpoint = endpointRef.getAndSet(null);
if (endpoint != null) {
if (log.isDebugEnabled()) {
log.debug("{}: cancel", ConnPoolSupport.getId(endpoint));
log.debug("{} cancel", ConnPoolSupport.getId(endpoint));
}
discardEndpoint(endpoint);
}

View File

@ -169,7 +169,7 @@ class InternalHttpClient extends CloseableHttpClient implements Configurable {
final HttpRoute route = determineRoute(target, request, localcontext);
final String exchangeId = ExecSupport.getNextExchangeId();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: preparing request execution", exchangeId);
LOG.debug("{} preparing request execution", exchangeId);
}
final ExecRuntime execRuntime = new InternalExecRuntime(LOG, connManager, requestExecutor,

View File

@ -99,7 +99,7 @@ public final class MainClientExec implements ExecChainHandler {
final ExecRuntime execRuntime = scope.execRuntime;
if (LOG.isDebugEnabled()) {
LOG.debug("{}: executing {}", exchangeId, new RequestLine(request));
LOG.debug("{} executing {}", exchangeId, new RequestLine(request));
}
try {
RequestEntityProxy.enhance(request);
@ -123,7 +123,7 @@ public final class MainClientExec implements ExecChainHandler {
} else {
s = "indefinitely";
}
LOG.debug("{}: connection can be kept alive {}", exchangeId, s);
LOG.debug("{} connection can be kept alive {}", exchangeId, s);
}
execRuntime.markConnectionReusable(userToken, duration);
} else {

View File

@ -158,13 +158,13 @@ public final class ProtocolExec implements ExecChainHandler {
if (!request.containsHeader(HttpHeaders.AUTHORIZATION)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: target auth state: {}", exchangeId, targetAuthExchange.getState());
LOG.debug("{} target auth state: {}", exchangeId, targetAuthExchange.getState());
}
authenticator.addAuthResponse(target, ChallengeType.TARGET, request, targetAuthExchange, context);
}
if (!request.containsHeader(HttpHeaders.PROXY_AUTHORIZATION) && !route.isTunnelled()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: proxy auth state: {}", exchangeId, proxyAuthExchange.getState());
LOG.debug("{} proxy auth state: {}", exchangeId, proxyAuthExchange.getState());
}
authenticator.addAuthResponse(proxy, ChallengeType.PROXY, request, proxyAuthExchange, context);
}
@ -181,7 +181,7 @@ public final class ProtocolExec implements ExecChainHandler {
final HttpEntity requestEntity = request.getEntity();
if (requestEntity != null && !requestEntity.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: Cannot retry non-repeatable request", exchangeId);
LOG.debug("{} Cannot retry non-repeatable request", exchangeId);
}
return response;
}
@ -195,14 +195,14 @@ public final class ProtocolExec implements ExecChainHandler {
if (proxyAuthExchange.getState() == AuthExchange.State.SUCCESS
&& proxyAuthExchange.isConnectionBased()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting proxy auth state", exchangeId);
LOG.debug("{} resetting proxy auth state", exchangeId);
}
proxyAuthExchange.reset();
}
if (targetAuthExchange.getState() == AuthExchange.State.SUCCESS
&& targetAuthExchange.isConnectionBased()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting target auth state", exchangeId);
LOG.debug("{} resetting target auth state", exchangeId);
}
targetAuthExchange.reset();
}

View File

@ -119,7 +119,7 @@ public final class RedirectExec implements ExecChainHandler {
final HttpEntity requestEntity = request.getEntity();
if (requestEntity != null && !requestEntity.isRepeatable()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: cannot redirect non-repeatable request", exchangeId);
LOG.debug("{} cannot redirect non-repeatable request", exchangeId);
}
return response;
}
@ -130,7 +130,7 @@ public final class RedirectExec implements ExecChainHandler {
final URI redirectUri = this.redirectStrategy.getLocationURI(currentRequest, response, context);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: redirect requested to location '{}'", exchangeId, redirectUri);
LOG.debug("{} redirect requested to location '{}'", exchangeId, redirectUri);
}
if (!config.isCircularRedirectsAllowed()) {
if (redirectLocations.contains(redirectUri)) {
@ -171,18 +171,18 @@ public final class RedirectExec implements ExecChainHandler {
final HttpRoute newRoute = this.routePlanner.determineRoute(newTarget, context);
if (!LangUtils.equals(currentRoute, newRoute)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: new route required", exchangeId);
LOG.debug("{} new route required", exchangeId);
}
final AuthExchange targetAuthExchange = context.getAuthExchange(currentRoute.getTargetHost());
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting target auth state", exchangeId);
LOG.debug("{} resetting target auth state", exchangeId);
}
targetAuthExchange.reset();
if (currentRoute.getProxyHost() != null) {
final AuthExchange proxyAuthExchange = context.getAuthExchange(currentRoute.getProxyHost());
if (proxyAuthExchange.isConnectionBased()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resetting proxy auth state", exchangeId);
LOG.debug("{} resetting proxy auth state", exchangeId);
}
proxyAuthExchange.reset();
}
@ -197,7 +197,7 @@ public final class RedirectExec implements ExecChainHandler {
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: redirecting to '{}' via {}", exchangeId, redirectUri, currentRoute);
LOG.debug("{} redirecting to '{}' via {}", exchangeId, redirectUri, currentRoute);
}
currentRequest = redirect;
RequestEntityProxy.enhance(currentRequest);
@ -217,7 +217,7 @@ public final class RedirectExec implements ExecChainHandler {
EntityUtils.consume(response.getEntity());
} catch (final IOException ioex) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: I/O error while releasing connection", exchangeId, ioex);
LOG.debug("{} I/O error while releasing connection", exchangeId, ioex);
}
} finally {
response.close();

View File

@ -32,6 +32,7 @@ import java.util.Date;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.TimeoutException;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicLong;
import java.util.concurrent.atomic.AtomicReference;
import org.apache.hc.client5.http.DnsResolver;
@ -253,9 +254,10 @@ public class BasicHttpClientConnectionManager implements HttpClientConnectionMan
public synchronized void release(final ConnectionEndpoint endpoint, final Object state, final TimeValue keepAlive) {
Args.notNull(endpoint, "Managed endpoint");
final InternalConnectionEndpoint internalEndpoint = cast(endpoint);
final String id = internalEndpoint.id;
final ManagedHttpClientConnection conn = internalEndpoint.detach();
if (conn != null && LOG.isDebugEnabled()) {
LOG.debug("Releasing connection {}", conn);
LOG.debug("{} Releasing connection {}", id, conn);
}
if (this.closed.get()) {
return;
@ -271,7 +273,7 @@ public class BasicHttpClientConnectionManager implements HttpClientConnectionMan
this.conn = null;
this.expiry = Long.MAX_VALUE;
if (LOG.isDebugEnabled()) {
LOG.debug("Connection is not kept alive");
LOG.debug("{} Connection is not kept alive", id);
}
} else {
this.state = state;
@ -280,12 +282,12 @@ public class BasicHttpClientConnectionManager implements HttpClientConnectionMan
}
if (TimeValue.isPositive(keepAlive)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Connection can be kept alive for {}", keepAlive);
LOG.debug("{} Connection can be kept alive for {}", id, keepAlive);
}
this.expiry = this.updated + keepAlive.toMilliseconds();
} else {
if (LOG.isDebugEnabled()) {
LOG.debug("Connection can be kept alive indefinitely");
LOG.debug("{} Connection can be kept alive indefinitely", id);
}
this.expiry = Long.MAX_VALUE;
}
@ -358,14 +360,18 @@ public class BasicHttpClientConnectionManager implements HttpClientConnectionMan
}
}
private static final AtomicLong COUNT = new AtomicLong(0);
class InternalConnectionEndpoint extends ConnectionEndpoint {
private final HttpRoute route;
private final AtomicReference<ManagedHttpClientConnection> connRef;
private final String id;
public InternalConnectionEndpoint(final HttpRoute route, final ManagedHttpClientConnection conn) {
this.route = route;
this.connRef = new AtomicReference<>(conn);
this.id = String.format("ep-%010d", COUNT.getAndIncrement());
}
HttpRoute getRoute() {
@ -419,12 +425,15 @@ public class BasicHttpClientConnectionManager implements HttpClientConnectionMan
@Override
public ClassicHttpResponse execute(
final String id,
final String exchangeId,
final ClassicHttpRequest request,
final HttpRequestExecutor requestExecutor,
final HttpContext context) throws IOException, HttpException {
Args.notNull(request, "HTTP request");
Args.notNull(requestExecutor, "Request executor");
if (LOG.isDebugEnabled()) {
LOG.debug("{} executing exchange {}", id, exchangeId);
}
return requestExecutor.execute(request, getValidatedConnection(), context);
}

View File

@ -142,13 +142,13 @@ public class DefaultHttpClientConnectionOperator implements HttpClientConnection
final InetSocketAddress remoteAddress = new InetSocketAddress(address, port);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connecting to {}", ConnPoolSupport.getId(conn), remoteAddress);
LOG.debug("{} connecting to {}", ConnPoolSupport.getId(conn), remoteAddress);
}
try {
sock = sf.connectSocket(connectTimeout, sock, host, remoteAddress, localAddress, context);
conn.bind(sock);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection established {}", ConnPoolSupport.getId(conn), conn);
LOG.debug("{} connection established {}", ConnPoolSupport.getId(conn), conn);
}
return;
} catch (final IOException ex) {
@ -157,7 +157,7 @@ public class DefaultHttpClientConnectionOperator implements HttpClientConnection
}
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connect to {} timed out. Connection will be retried using another IP address", ConnPoolSupport.getId(conn), remoteAddress);
LOG.debug("{} connect to {} timed out. Connection will be retried using another IP address", ConnPoolSupport.getId(conn), remoteAddress);
}
}
}

View File

@ -153,7 +153,7 @@ final class DefaultManagedHttpClientConnection
public void close() throws IOException {
if (this.closed.compareAndSet(false, true)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: Close connection", this.id);
LOG.debug("{} Close connection", this.id);
}
super.close();
}
@ -162,7 +162,7 @@ final class DefaultManagedHttpClientConnection
@Override
public void setSocketTimeout(final Timeout timeout) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: set socket timeout to {}", this.id, timeout);
LOG.debug("{} set socket timeout to {}", this.id, timeout);
}
super.setSocketTimeout(timeout);
}
@ -171,7 +171,7 @@ final class DefaultManagedHttpClientConnection
public void close(final CloseMode closeMode) {
if (this.closed.compareAndSet(false, true)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: close connection {}", this.id, closeMode);
LOG.debug("{} close connection {}", this.id, closeMode);
}
super.close(closeMode);
}

View File

@ -255,7 +255,7 @@ public class PoolingHttpClientConnectionManager
final Object state) {
Args.notNull(route, "HTTP route");
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint lease request ({}) {}", id, requestTimeout, ConnPoolSupport.formatStats(route, state, pool));
LOG.debug("{} endpoint lease request ({}) {}", id, requestTimeout, ConnPoolSupport.formatStats(route, state, pool));
}
final Future<PoolEntry<HttpRoute, ManagedHttpClientConnection>> leaseFuture = this.pool.lease(route, state, requestTimeout, null);
return new LeaseRequest() {
@ -280,7 +280,7 @@ public class PoolingHttpClientConnectionManager
throw ex;
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint leased {}", id, ConnPoolSupport.formatStats(route, state, pool));
LOG.debug("{} endpoint leased {}", id, ConnPoolSupport.formatStats(route, state, pool));
}
try {
final TimeValue validateAfterInactivitySnapshot = validateAfterInactivity;
@ -296,7 +296,7 @@ public class PoolingHttpClientConnectionManager
}
if (stale) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection {} is stale", id, ConnPoolSupport.getId(conn));
LOG.debug("{} connection {} is stale", id, ConnPoolSupport.getId(conn));
}
poolEntry.discardConnection(CloseMode.IMMEDIATE);
}
@ -310,19 +310,19 @@ public class PoolingHttpClientConnectionManager
}
if (leaseFuture.isCancelled()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint lease cancelled", id);
LOG.debug("{} endpoint lease cancelled", id);
}
pool.release(poolEntry, false);
} else {
this.endpoint = new InternalConnectionEndpoint(poolEntry);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: acquired {}", id, ConnPoolSupport.getId(endpoint));
LOG.debug("{} acquired {}", id, ConnPoolSupport.getId(endpoint));
}
}
return this.endpoint;
} catch (final Exception ex) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint lease failed", id);
LOG.debug("{} endpoint lease failed", id);
}
pool.release(poolEntry, false);
throw new ExecutionException(ex.getMessage(), ex);
@ -346,7 +346,7 @@ public class PoolingHttpClientConnectionManager
return;
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: releasing endpoint", ConnPoolSupport.getId(endpoint));
LOG.debug("{} releasing endpoint", ConnPoolSupport.getId(endpoint));
}
final ManagedHttpClientConnection conn = entry.getConnection();
if (conn != null && keepAlive == null) {
@ -365,11 +365,11 @@ public class PoolingHttpClientConnectionManager
} else {
s = "indefinitely";
}
LOG.debug("{}: connection {} can be kept alive {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(conn), s);
LOG.debug("{} connection {} can be kept alive {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(conn), s);
}
} else {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection is not kept alive", ConnPoolSupport.getId(endpoint));
LOG.debug("{} connection is not kept alive", ConnPoolSupport.getId(endpoint));
}
}
} catch (final RuntimeException ex) {
@ -378,7 +378,7 @@ public class PoolingHttpClientConnectionManager
} finally {
this.pool.release(entry, reusable);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection released {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.formatStats(entry.getRoute(), entry.getState(), pool));
LOG.debug("{} connection released {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.formatStats(entry.getRoute(), entry.getState(), pool));
}
}
}
@ -402,7 +402,7 @@ public class PoolingHttpClientConnectionManager
host = route.getTargetHost();
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connecting endpoint to {} ({})", ConnPoolSupport.getId(endpoint), host, connectTimeout);
LOG.debug("{} connecting endpoint to {} ({})", ConnPoolSupport.getId(endpoint), host, connectTimeout);
}
final ManagedHttpClientConnection conn = poolEntry.getConnection();
final SocketConfig defaultSocketConfigSnapshot = defaultSocketConfig;
@ -414,7 +414,7 @@ public class PoolingHttpClientConnectionManager
defaultSocketConfigSnapshot != null ? defaultSocketConfigSnapshot : SocketConfig.DEFAULT,
context);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connected {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(conn));
LOG.debug("{} connected {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(conn));
}
}
@ -591,7 +591,7 @@ public class PoolingHttpClientConnectionManager
Args.notNull(requestExecutor, "Request executor");
final ManagedHttpClientConnection connection = getValidatedPoolEntry().getConnection();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: executing exchange {} over {}", id, exchangeId, ConnPoolSupport.getId(connection));
LOG.debug("{} executing exchange {} over {}", id, exchangeId, ConnPoolSupport.getId(connection));
}
return requestExecutor.execute(request, connection, context);
}

View File

@ -78,7 +78,7 @@ final class DefaultManagedAsyncClientConnection implements ManagedAsyncClientCon
public void close(final CloseMode closeMode) {
if (this.closed.compareAndSet(false, true)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: Shutdown connection {}", getId(), closeMode);
LOG.debug("{} Shutdown connection {}", getId(), closeMode);
}
ioSession.close(closeMode);
}
@ -88,7 +88,7 @@ final class DefaultManagedAsyncClientConnection implements ManagedAsyncClientCon
public void close() throws IOException {
if (this.closed.compareAndSet(false, true)) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: Close connection", getId());
LOG.debug("{} Close connection", getId());
}
ioSession.enqueue(new ShutdownCommand(CloseMode.GRACEFUL), Command.Priority.IMMEDIATE);
}
@ -146,7 +146,7 @@ final class DefaultManagedAsyncClientConnection implements ManagedAsyncClientCon
final SSLSessionVerifier verifier,
final Timeout handshakeTimeout) throws UnsupportedOperationException {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: start TLS", getId());
LOG.debug("{} start TLS", getId());
}
if (ioSession instanceof TransportSecurityLayer) {
((TransportSecurityLayer) ioSession).startTls(sslContext, endpoint, sslBufferMode, initializer, verifier,
@ -170,7 +170,7 @@ final class DefaultManagedAsyncClientConnection implements ManagedAsyncClientCon
@Override
public void submitCommand(final Command command, final Command.Priority priority) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: {} with {} priority", getId(), command.getClass().getSimpleName(), priority);
LOG.debug("{} {} with {} priority", getId(), command.getClass().getSimpleName(), priority);
}
ioSession.enqueue(command, Command.Priority.IMMEDIATE);
}

View File

@ -68,13 +68,13 @@ final class MultihomeIOSessionRequester {
if (remoteAddress != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connecting {} to {} ({})", remoteEndpoint, localAddress, remoteAddress, connectTimeout);
LOG.debug("{} connecting {} to {} ({})", remoteEndpoint, localAddress, remoteAddress, connectTimeout);
}
return connectionInitiator.connect(remoteEndpoint, remoteAddress, localAddress, connectTimeout, attachment, callback);
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resolving remote address", remoteEndpoint);
LOG.debug("{} resolving remote address", remoteEndpoint);
}
final ComplexFuture<IOSession> future = new ComplexFuture<>(callback);
@ -87,7 +87,7 @@ final class MultihomeIOSessionRequester {
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: resolved to {}", remoteEndpoint, Arrays.asList(remoteAddresses));
LOG.debug("{} resolved to {}", remoteEndpoint, Arrays.asList(remoteAddresses));
}
final Runnable runnable = new Runnable() {
@ -99,7 +99,7 @@ final class MultihomeIOSessionRequester {
final InetSocketAddress remoteAddress = new InetSocketAddress(remoteAddresses[index], remoteEndpoint.getPort());
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connecting {} to {} ({})", remoteEndpoint, localAddress, remoteAddress, connectTimeout);
LOG.debug("{} connecting {} to {} ({})", remoteEndpoint, localAddress, remoteAddress, connectTimeout);
}
final Future<IOSession> sessionFuture = connectionInitiator.connect(
@ -114,7 +114,7 @@ final class MultihomeIOSessionRequester {
public void completed(final IOSession session) {
if (LOG.isDebugEnabled()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connected {} {}->{}", remoteEndpoint, session.getId(), session.getLocalAddress(), session.getRemoteAddress());
LOG.debug("{} connected {} {}->{}", remoteEndpoint, session.getId(), session.getLocalAddress(), session.getRemoteAddress());
}
}
future.completed(session);
@ -124,7 +124,7 @@ final class MultihomeIOSessionRequester {
public void failed(final Exception cause) {
if (attempt.get() >= remoteAddresses.length) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection to {} failed ({}); terminating operation", remoteEndpoint, remoteAddress, cause.getClass());
LOG.debug("{} connection to {} failed ({}); terminating operation", remoteEndpoint, remoteAddress, cause.getClass());
}
if (cause instanceof IOException) {
future.failed(ConnectExceptionSupport.enhance((IOException) cause, remoteEndpoint, remoteAddresses));
@ -133,7 +133,7 @@ final class MultihomeIOSessionRequester {
}
} else {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection to {} failed ({}); retrying connection to the next address", remoteEndpoint, remoteAddress, cause.getClass());
LOG.debug("{} connection to {} failed ({}); retrying connection to the next address", remoteEndpoint, remoteAddress, cause.getClass());
}
executeNext();
}

View File

@ -219,7 +219,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
final Timeout requestTimeout,
final FutureCallback<AsyncConnectionEndpoint> callback) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint lease request ({}) {}", id, requestTimeout, ConnPoolSupport.formatStats(route, state, pool));
LOG.debug("{} endpoint lease request ({}) {}", id, requestTimeout, ConnPoolSupport.formatStats(route, state, pool));
}
final ComplexFuture<AsyncConnectionEndpoint> resultFuture = new ComplexFuture<>(callback);
final Future<PoolEntry<HttpRoute, ManagedAsyncClientConnection>> leaseFuture = pool.lease(
@ -231,11 +231,11 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
connection.activate();
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint leased {}", id, ConnPoolSupport.formatStats(route, state, pool));
LOG.debug("{} endpoint leased {}", id, ConnPoolSupport.formatStats(route, state, pool));
}
final AsyncConnectionEndpoint endpoint = new InternalConnectionEndpoint(poolEntry);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: acquired {}", id, ConnPoolSupport.getId(endpoint));
LOG.debug("{} acquired {}", id, ConnPoolSupport.getId(endpoint));
}
resultFuture.completed(endpoint);
}
@ -254,7 +254,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
public void execute(final Boolean result) {
if (result == null || !result) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection {} is stale", id, ConnPoolSupport.getId(connection));
LOG.debug("{} connection {} is stale", id, ConnPoolSupport.getId(connection));
}
poolEntry.discardConnection(CloseMode.IMMEDIATE);
}
@ -265,7 +265,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
} else {
if (!connection.isOpen()) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection {} is closed", id, ConnPoolSupport.getId(connection));
LOG.debug("{} connection {} is closed", id, ConnPoolSupport.getId(connection));
}
poolEntry.discardConnection(CloseMode.IMMEDIATE);
}
@ -279,7 +279,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
@Override
public void failed(final Exception ex) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint lease failed", id);
LOG.debug("{} endpoint lease failed", id);
}
resultFuture.failed(ex);
}
@ -287,7 +287,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
@Override
public void cancelled() {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: endpoint lease cancelled", id);
LOG.debug("{} endpoint lease cancelled", id);
}
resultFuture.cancel();
}
@ -307,7 +307,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
return;
}
if (LOG.isDebugEnabled()) {
LOG.debug("{}: releasing endpoint", ConnPoolSupport.getId(endpoint));
LOG.debug("{} releasing endpoint", ConnPoolSupport.getId(endpoint));
}
final ManagedAsyncClientConnection connection = entry.getConnection();
boolean reusable = connection != null && connection.isOpen();
@ -323,7 +323,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
} else {
s = "indefinitely";
}
LOG.debug("{}: connection {} can be kept alive {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(connection), s);
LOG.debug("{} connection {} can be kept alive {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(connection), s);
}
}
} catch (final RuntimeException ex) {
@ -332,7 +332,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
} finally {
pool.release(entry, reusable);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connection released {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.formatStats(entry.getRoute(), entry.getState(), pool));
LOG.debug("{} connection released {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.formatStats(entry.getRoute(), entry.getState(), pool));
}
}
}
@ -364,7 +364,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
}
final InetSocketAddress localAddress = route.getLocalSocketAddress();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connecting endpoint to {} ({})", ConnPoolSupport.getId(endpoint), host, connectTimeout);
LOG.debug("{} connecting endpoint to {} ({})", ConnPoolSupport.getId(endpoint), host, connectTimeout);
}
final Future<ManagedAsyncClientConnection> connectFuture = connectionOperator.connect(
connectionInitiator, host, localAddress, connectTimeout, attachment, new FutureCallback<ManagedAsyncClientConnection>() {
@ -373,7 +373,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
public void completed(final ManagedAsyncClientConnection connection) {
try {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: connected {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(connection));
LOG.debug("{} connected {}", ConnPoolSupport.getId(endpoint), ConnPoolSupport.getId(connection));
}
poolEntry.assignConnection(connection);
resultFuture.completed(internalEndpoint);
@ -409,7 +409,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
final ManagedAsyncClientConnection connection = poolEntry.getConnection();
connectionOperator.upgrade(poolEntry.getConnection(), route.getTargetHost(), attachment);
if (LOG.isDebugEnabled()) {
LOG.debug("{}: upgraded {}", ConnPoolSupport.getId(internalEndpoint), ConnPoolSupport.getId(connection));
LOG.debug("{} upgraded {}", ConnPoolSupport.getId(internalEndpoint), ConnPoolSupport.getId(connection));
}
}
@ -524,7 +524,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
final PoolEntry<HttpRoute, ManagedAsyncClientConnection> poolEntry = poolEntryRef.get();
if (poolEntry != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}: close {}", id, closeMode);
LOG.debug("{} close {}", id, closeMode);
}
poolEntry.discardConnection(closeMode);
}
@ -560,7 +560,7 @@ public class PoolingAsyncClientConnectionManager implements AsyncClientConnectio
final HttpContext context) {
final ManagedAsyncClientConnection connection = getValidatedPoolEntry().getConnection();
if (LOG.isDebugEnabled()) {
LOG.debug("{}: executing exchange {} over {}", id, exchangeId, ConnPoolSupport.getId(connection));
LOG.debug("{} executing exchange {} over {}", id, exchangeId, ConnPoolSupport.getId(connection));
}
connection.submitCommand(
new RequestExecutionCommand(exchangeHandler, pushHandlerFactory, context),

View File

@ -130,6 +130,12 @@ public class HttpClientContext extends HttpCoreContext {
*/
public static final String REQUEST_CONFIG = "http.request-config";
/**
* Attribute name of a {@link java.lang.String} object that represents the ID of the
* current message exchange.
*/
public static final String EXCHANGE_ID = "http.exchange-id";
public static HttpClientContext adapt(final HttpContext context) {
Args.notNull(context, "HTTP context");
if (context instanceof HttpClientContext) {
@ -276,4 +282,18 @@ public class HttpClientContext extends HttpCoreContext {
setAttribute(REQUEST_CONFIG, config);
}
/**
* @since 5.1
*/
public String getExchangeId() {
return getAttribute(EXCHANGE_ID, String.class);
}
/**
* @since 5.1
*/
public void setExchangeId(final String id) {
setAttribute(EXCHANGE_ID, id);
}
}

View File

@ -83,25 +83,32 @@ public class RequestAddCookies implements HttpRequestInterceptor {
}
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
// Obtain cookie store
final CookieStore cookieStore = clientContext.getCookieStore();
if (cookieStore == null) {
LOG.debug("Cookie store not specified in HTTP context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Cookie store not specified in HTTP context", exchangeId);
}
return;
}
// Obtain the registry of cookie specs
final Lookup<CookieSpecFactory> registry = clientContext.getCookieSpecRegistry();
if (registry == null) {
LOG.debug("CookieSpec registry not specified in HTTP context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} CookieSpec registry not specified in HTTP context", exchangeId);
}
return;
}
// Obtain the route (required)
final RouteInfo route = clientContext.getHttpRoute();
if (route == null) {
LOG.debug("Connection route not set in the context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Connection route not set in the context", exchangeId);
}
return;
}
@ -111,7 +118,7 @@ public class RequestAddCookies implements HttpRequestInterceptor {
cookieSpecName = StandardCookieSpec.STRICT;
}
if (LOG.isDebugEnabled()) {
LOG.debug("Cookie spec selected: {}", cookieSpecName);
LOG.debug("{} Cookie spec selected: {}", exchangeId, cookieSpecName);
}
final URIAuthority authority = request.getAuthority();
@ -133,9 +140,8 @@ public class RequestAddCookies implements HttpRequestInterceptor {
final CookieSpecFactory factory = registry.lookup(cookieSpecName);
if (factory == null) {
if (LOG.isDebugEnabled()) {
LOG.debug("Unsupported cookie spec: {}", cookieSpecName);
LOG.debug("{} Unsupported cookie spec: {}", exchangeId, cookieSpecName);
}
return;
}
final CookieSpec cookieSpec = factory.create(clientContext);
@ -149,13 +155,13 @@ public class RequestAddCookies implements HttpRequestInterceptor {
if (!cookie.isExpired(now)) {
if (cookieSpec.match(cookie, cookieOrigin)) {
if (LOG.isDebugEnabled()) {
LOG.debug("Cookie {} match {}", cookie, cookieOrigin);
LOG.debug("{} Cookie {} match {}", exchangeId, cookie, cookieOrigin);
}
matchedCookies.add(cookie);
}
} else {
if (LOG.isDebugEnabled()) {
LOG.debug("Cookie {} expired", cookie);
LOG.debug("{} Cookie {} expired", exchangeId, cookie);
}
expired = true;
}

View File

@ -70,22 +70,29 @@ public class RequestAuthCache implements HttpRequestInterceptor {
Args.notNull(context, "HTTP context");
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
final AuthCache authCache = clientContext.getAuthCache();
if (authCache == null) {
LOG.debug("Auth cache not set in the context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Auth cache not set in the context", exchangeId);
}
return;
}
final CredentialsProvider credsProvider = clientContext.getCredentialsProvider();
if (credsProvider == null) {
LOG.debug("Credentials provider not set in the context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Credentials provider not set in the context", exchangeId);
}
return;
}
final RouteInfo route = clientContext.getHttpRoute();
if (route == null) {
LOG.debug("Route info not set in the context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Route info not set in the context", exchangeId);
}
return;
}
@ -104,7 +111,7 @@ public class RequestAuthCache implements HttpRequestInterceptor {
final AuthScheme authScheme = authCache.get(target);
if (authScheme != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("Re-using cached '{}' auth scheme for {}", authScheme.getName(), target);
LOG.debug("{} Re-using cached '{}' auth scheme for {}", exchangeId, authScheme.getName(), target);
}
targetAuthExchange.select(authScheme);
}
@ -117,7 +124,7 @@ public class RequestAuthCache implements HttpRequestInterceptor {
final AuthScheme authScheme = authCache.get(proxy);
if (authScheme != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("Re-using cached '{}' auth scheme for {}", authScheme.getName(), proxy);
LOG.debug("{} Re-using cached '{}' auth scheme for {}", exchangeId, authScheme.getName(), proxy);
}
proxyAuthExchange.select(authScheme);
}

View File

@ -70,11 +70,14 @@ public class RequestClientConnControl implements HttpRequestInterceptor {
}
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
// Obtain the client connection (required)
final RouteInfo route = clientContext.getHttpRoute();
if (route == null) {
LOG.debug("Connection route not set in the context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Connection route not set in the context", exchangeId);
}
return;
}

View File

@ -70,30 +70,38 @@ public class ResponseProcessCookies implements HttpResponseInterceptor {
Args.notNull(context, "HTTP context");
final HttpClientContext clientContext = HttpClientContext.adapt(context);
final String exchangeId = clientContext.getExchangeId();
// Obtain actual CookieSpec instance
final CookieSpec cookieSpec = clientContext.getCookieSpec();
if (cookieSpec == null) {
LOG.debug("Cookie spec not specified in HTTP context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Cookie spec not specified in HTTP context", exchangeId);
}
return;
}
// Obtain cookie store
final CookieStore cookieStore = clientContext.getCookieStore();
if (cookieStore == null) {
LOG.debug("Cookie store not specified in HTTP context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Cookie store not specified in HTTP context", exchangeId);
}
return;
}
// Obtain actual CookieOrigin instance
final CookieOrigin cookieOrigin = clientContext.getCookieOrigin();
if (cookieOrigin == null) {
LOG.debug("Cookie origin not specified in HTTP context");
if (LOG.isDebugEnabled()) {
LOG.debug("{} Cookie origin not specified in HTTP context", exchangeId);
}
return;
}
final Iterator<Header> it = response.headerIterator("Set-Cookie");
processCookies(it, cookieSpec, cookieOrigin, cookieStore);
processCookies(exchangeId, it, cookieSpec, cookieOrigin, cookieStore);
}
private void processCookies(
final String exchangeId,
final Iterator<Header> iterator,
final CookieSpec cookieSpec,
final CookieOrigin cookieOrigin,
@ -108,17 +116,19 @@ public class ResponseProcessCookies implements HttpResponseInterceptor {
cookieStore.addCookie(cookie);
if (LOG.isDebugEnabled()) {
LOG.debug("Cookie accepted [{}]", formatCooke(cookie));
if (LOG.isDebugEnabled()) {
LOG.debug("{} Cookie accepted [{}]", exchangeId, formatCooke(cookie));
}
}
} catch (final MalformedCookieException ex) {
if (LOG.isWarnEnabled()) {
LOG.warn("Cookie rejected [{}] {}", formatCooke(cookie), ex.getMessage());
LOG.warn("{} Cookie rejected [{}] {}", exchangeId, formatCooke(cookie), ex.getMessage());
}
}
}
} catch (final MalformedCookieException ex) {
if (LOG.isWarnEnabled()) {
LOG.warn("Invalid cookie header: \"{}\". {}", header, ex.getMessage());
LOG.warn("{} Invalid cookie header: \"{}\". {}", exchangeId, header, ex.getMessage());
}
}
}