Skip to content

Commit 945a75d

Browse files
ok2cok2c
committed
HTTPCLIENT-2371: Logging of request re-execution at INFO priority
1 parent 9099978 commit 945a75d

2 files changed

Lines changed: 29 additions & 21 deletions

File tree

‎httpclient5/src/main/java/org/apache/hc/client5/http/impl/async/AsyncHttpRequestRetryExec.java‎

Lines changed: 14 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,6 @@
2929
import java.io.IOException;
3030

3131
import org.apache.hc.client5.http.HttpRequestRetryStrategy;
32-
import org.apache.hc.client5.http.HttpRoute;
3332
import org.apache.hc.client5.http.async.AsyncExecCallback;
3433
import org.apache.hc.client5.http.async.AsyncExecChain;
3534
import org.apache.hc.client5.http.async.AsyncExecChainHandler;
@@ -40,6 +39,7 @@
4039
import org.apache.hc.core5.annotation.ThreadingBehavior;
4140
import org.apache.hc.core5.http.EntityDetails;
4241
import org.apache.hc.core5.http.HttpException;
42+
import org.apache.hc.core5.http.HttpHost;
4343
import org.apache.hc.core5.http.HttpRequest;
4444
import org.apache.hc.core5.http.HttpResponse;
4545
import org.apache.hc.core5.http.nio.AsyncDataConsumer;
@@ -96,6 +96,7 @@ public AsyncHttpRequestRetryExec(final HttpRequestRetryStrategy retryStrategy) {
9696
private static class State {
9797

9898
volatile boolean retrying;
99+
volatile int status;
99100
volatile TimeValue delay;
100101

101102
}
@@ -125,6 +126,7 @@ public AsyncDataConsumer handleResponse(
125126
}
126127
state.retrying = retryStrategy.retryRequest(response, scope.execCount.get(), clientContext);
127128
if (state.retrying) {
129+
state.status = response.getCode();
128130
state.delay = retryStrategy.getRetryInterval(response, scope.execCount.get(), clientContext);
129131
return new DiscardingEntityConsumer<>();
130132
}
@@ -139,13 +141,16 @@ public void handleInformationResponse(final HttpResponse response) throws HttpEx
139141
@Override
140142
public void completed() {
141143
if (state.retrying) {
142-
scope.execCount.incrementAndGet();
144+
final int execCount = scope.execCount.incrementAndGet();
143145
if (entityProducer != null) {
144146
entityProducer.releaseResources();
145147
}
148+
final HttpHost target = scope.route.getTargetHost();
146149
final TimeValue delay = TimeValue.isPositive(state.delay) ? state.delay : TimeValue.ZERO_MILLISECONDS;
147-
if (LOG.isDebugEnabled()) {
148-
LOG.debug("{} wait for {}", exchangeId, delay);
150+
if (LOG.isInfoEnabled()) {
151+
LOG.info("{} {} responded with status {}; " +
152+
"request will be automatically re-executed in {} (exec count {})",
153+
exchangeId, target, state.status, delay, execCount);
149154
}
150155
scope.scheduler.scheduleExecution(
151156
request,
@@ -162,7 +167,7 @@ public void completed() {
162167
@Override
163168
public void failed(final Exception cause) {
164169
if (cause instanceof IOException) {
165-
final HttpRoute route = scope.route;
170+
final HttpHost target = scope.route.getTargetHost();
166171
final HttpClientContext clientContext = scope.clientContext;
167172
if (entityProducer != null && !entityProducer.isRepeatable()) {
168173
if (LOG.isDebugEnabled()) {
@@ -172,10 +177,6 @@ public void failed(final Exception cause) {
172177
if (LOG.isDebugEnabled()) {
173178
LOG.debug("{} {}", exchangeId, cause.getMessage(), cause);
174179
}
175-
if (LOG.isInfoEnabled()) {
176-
LOG.info("Recoverable I/O exception ({}) caught when processing request to {}",
177-
cause.getClass().getName(), route);
178-
}
179180
scope.execRuntime.discardEndpoint();
180181
if (entityProducer != null) {
181182
entityProducer.releaseResources();
@@ -184,8 +185,10 @@ public void failed(final Exception cause) {
184185
final int execCount = scope.execCount.incrementAndGet();
185186
state.delay = retryStrategy.getRetryInterval(request, (IOException) cause, execCount - 1, clientContext);
186187
final TimeValue delay = TimeValue.isPositive(state.delay) ? state.delay : TimeValue.ZERO_MILLISECONDS;
187-
if (LOG.isDebugEnabled()) {
188-
LOG.debug("{} wait for {}", exchangeId, delay);
188+
if (LOG.isInfoEnabled()) {
189+
LOG.info("{} recoverable I/O exception ({}) caught when sending request to {};" +
190+
"request will be automatically re-executed in {} (exec count {})",
191+
exchangeId, cause.getClass().getName(), target, delay, execCount);
189192
}
190193
scope.scheduler.scheduleExecution(
191194
request,

‎httpclient5/src/main/java/org/apache/hc/client5/http/impl/classic/HttpRequestRetryExec.java‎

Lines changed: 15 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,7 @@
4343
import org.apache.hc.core5.http.ClassicHttpResponse;
4444
import org.apache.hc.core5.http.HttpEntity;
4545
import org.apache.hc.core5.http.HttpException;
46+
import org.apache.hc.core5.http.HttpHost;
4647
import org.apache.hc.core5.http.NoHttpResponseException;
4748
import org.apache.hc.core5.http.io.support.ClassicRequestBuilder;
4849
import org.apache.hc.core5.util.Args;
@@ -102,6 +103,7 @@ public ClassicHttpResponse execute(
102103
Args.notNull(scope, "scope");
103104
final String exchangeId = scope.exchangeId;
104105
final HttpRoute route = scope.route;
106+
final HttpHost target = route.getTargetHost();
105107
final HttpClientContext context = scope.clientContext;
106108
ClassicHttpRequest currentRequest = request;
107109

@@ -119,7 +121,12 @@ public ClassicHttpResponse execute(
119121
if (retryStrategy.retryRequest(response, execCount, context)) {
120122
response.close();
121123
final TimeValue delay = retryStrategy.getRetryInterval(response, execCount, context);
122-
pause(exchangeId, delay);
124+
if (LOG.isInfoEnabled()) {
125+
LOG.info("{} {} responded with status {}; " +
126+
"request will be automatically re-executed in {} (exec count {})",
127+
exchangeId, target, response.getCode(), delay, execCount + 1);
128+
}
129+
pause(delay);
123130
currentRequest = ClassicRequestBuilder.copy(scope.originalRequest).build();
124131
} else {
125132
return response;
@@ -143,18 +150,19 @@ public ClassicHttpResponse execute(
143150
if (LOG.isDebugEnabled()) {
144151
LOG.debug("{} {}", exchangeId, ex.getMessage(), ex);
145152
}
153+
final TimeValue delay = retryStrategy.getRetryInterval(request, ex, execCount, context);
146154
if (LOG.isInfoEnabled()) {
147-
LOG.info("Recoverable I/O exception ({}) caught when processing request to {}",
148-
ex.getClass().getName(), route);
155+
LOG.info("{} recoverable I/O exception ({}) caught when sending request to {};" +
156+
"request will be automatically re-executed in {} (exec count {})",
157+
exchangeId, ex.getClass().getName(), target, delay, execCount + 1);
149158
}
150-
final TimeValue delay = retryStrategy.getRetryInterval(request, ex, execCount, context);
151-
pause(exchangeId, delay);
159+
pause(delay);
152160
currentRequest = ClassicRequestBuilder.copy(scope.originalRequest).build();
153161
continue;
154162
}
155163
if (ex instanceof NoHttpResponseException) {
156164
final NoHttpResponseException updatedex = new NoHttpResponseException(
157-
route.getTargetHost().toHostString() + " failed to respond");
165+
target.toHostString() + " failed to respond");
158166
updatedex.setStackTrace(ex.getStackTrace());
159167
throw updatedex;
160168
}
@@ -163,10 +171,7 @@ public ClassicHttpResponse execute(
163171
}
164172
}
165173

166-
private static void pause(final String exchangeId, final TimeValue delay) throws InterruptedIOException {
167-
if (LOG.isDebugEnabled()) {
168-
LOG.debug("{} wait for {}", exchangeId, delay);
169-
}
174+
private static void pause(final TimeValue delay) throws InterruptedIOException {
170175
if (TimeValue.isPositive(delay)) {
171176
try {
172177
delay.sleep();

0 commit comments

Comments
 (0)