Skip to content
Permalink
Browse files
Improved context and wire logging
  • Loading branch information
ok2c committed Jan 3, 2021
1 parent a0b4dbb commit 8285223560d9c83c6b7d3a3f00dd972fe26f928f
Showing 37 changed files with 296 additions and 189 deletions.
@@ -80,11 +80,14 @@ public List<AuthScheme> select(
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 List<AuthScheme> select(
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 List<AuthScheme> select(
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 List<AuthScheme> select(
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);
}
}
}
@@ -129,7 +129,7 @@ public void execute(
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 @@ private void proceedToNextHop(
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 void completed(final AsyncExecRuntime execRuntime) {
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 void handleInformationResponse(
@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 void failed(final Exception cause) {
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 void failed(final Exception cause) {

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);
@@ -102,7 +102,7 @@ public AsyncDataConsumer handleResponse(
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 void failed(final Exception cause) {
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 {}",
@@ -168,13 +168,13 @@ private void internalExecute(

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 void completed() {
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 void completed() {
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 {
@@ -127,7 +127,7 @@ public AsyncDataConsumer handleResponse(

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 AsyncDataConsumer handleResponse(
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 AsyncDataConsumer handleResponse(
}
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 void completed() {
}
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 {
@@ -83,7 +83,7 @@ public void execute(
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() {
@@ -98,7 +98,7 @@ public void execute(
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);
@@ -180,10 +180,11 @@ public void sendRequest(
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 @@ public void handleInformationResponse(
@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 @@ public void completed() {
@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();
@@ -89,7 +89,7 @@ public Cancellable acquireEndpoint(
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 @@ public void completed(final IOSession ioSession) {
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 @@ public void cancelled() {
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 @@ public Cancellable connectEndpoint(
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 @@ public void completed(final IOSession ioSession) {
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 @@ public Cancellable execute(
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 @@ public void completed(final IOSession ioSession) {
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),

0 comments on commit 8285223

Please sign in to comment.