Skip to content

Commit

Permalink
[improvement] Improve exceptions and logging when retrying (#941)
Browse files Browse the repository at this point in the history 
## Before this PR
- Request failures were logged at the `debug` level
- Nothing was logged when handling a `RetryOther` QoS response
- The message "Rescheduling call after backoff" was logged when retrying requests for different reasons
- `IOException` was used to indicate failures

## After this PR
- Request failures are logged at the `info` level
- Log when handling any QoS response
- Use unique, descriptive messages when retrying requests
- Use `SafeIoException` to indicate failures

Logging request failures at the info level is the primary motivation of this PR. Without this there is no indication when requests fail.

cc @pnepywoda
  • Loading branch information
@pkoenig10 @bulldozer-bot
pkoenig10 authored and bulldozer-bot[bot] committed Feb 25, 2019
1 parent d3d824f commit b401608
Show file tree
Hide file tree
Showing 3 changed files with 117 additions and 70 deletions.
1 change: 1 addition & 0 deletions okhttp-clients/build.gradle
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ dependencies {

testImplementation project(":conjure-java-jersey-server")
testImplementation project(":keystores")
testImplementation 'com.palantir.safe-logging:preconditions-assertj'
testImplementation "com.squareup.okhttp3:mockwebserver"
testImplementation "javax.ws.rs:javax.ws.rs-api"
testImplementation "junit:junit"
Expand Down
128 changes: 82 additions & 46 deletions okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,8 @@
import com.palantir.conjure.java.api.errors.RemoteException;
import com.palantir.conjure.java.client.config.ClientConfiguration;
import com.palantir.logsafe.SafeArg;
import com.palantir.logsafe.UnsafeArg;
import com.palantir.logsafe.exceptions.SafeIoException;
import java.io.IOException;
import java.io.InterruptedIOException;
import java.time.Duration;
Expand Down Expand Up @@ -175,25 +177,35 @@ public void onFailure(Call call, IOException exception) {
// Fail call if backoffs are exhausted or if no retry URL can be determined.
Optional<Duration> backoff = backoffStrategy.nextBackoff();
if (!backoff.isPresent()) {
callback.onFailure(call, new IOException("Failed to complete the request due to an "
+ "IOException", exception));
callback.onFailure(call, new SafeIoException(
"Failed to complete the request due to an IOException",
exception,
UnsafeArg.of("requestUrl", call.request().url().toString())));
return;
}

Optional<HttpUrl> redirectTo = urls.redirectToNext(request().url());
if (!redirectTo.isPresent()) {
callback.onFailure(call, new IOException("Failed to determine valid failover URL for '"
+ request().url() + "' and base URLs " + urls.getBaseUrls()));
callback.onFailure(call, new SafeIoException(
"Failed to determine valid failover URL",
exception,
UnsafeArg.of("requestUrl", call.request().url().toString()),
UnsafeArg.of("baseUrls", urls.getBaseUrls())));
return;
}

log.info("Retrying call after failure",
SafeArg.of("backoffMillis", backoff.get().toMillis()),
UnsafeArg.of("redirectToUrl", redirectTo.get()),
exception);
Request redirectedRequest = request().newBuilder()
.url(redirectTo.get())
.build();
RemotingOkHttpCall retryCall =
client.newCallWithMutableState(redirectedRequest, backoffStrategy, maxNumRelocations - 1);
log.debug("Rescheduling call after backoff", SafeArg.of("backoffMillis", backoff.get().toMillis()),
exception);
scheduleExecution(() -> retryCall.enqueue(callback), backoff.get());
scheduleExecution(
() -> retryCall.enqueue(callback),
backoff.get());
}

@Override
Expand Down Expand Up @@ -258,65 +270,89 @@ private QosException.Visitor<Void> createQosVisitor(Callback callback, Call call
public Void visit(QosException.Throttle exception) {
Optional<Duration> nonAdvertizedBackoff = backoffStrategy.nextBackoff();
if (!nonAdvertizedBackoff.isPresent()) {
callback.onFailure(call, new IOException("Failed to reschedule call since "
+ "the number of configured backoffs are exhausted", exception));
callback.onFailure(call, new SafeIoException(
"Failed to complete the request due to QosException.Throttle",
exception,
UnsafeArg.of("requestUrl", call.request().url().toString())));
return null;
}

Duration backoff = exception.getRetryAfter().orElse(nonAdvertizedBackoff.get());
log.debug("Rescheduling call after backoff", SafeArg.of("backoffMillis", backoff.toMillis()),
log.debug("Rescheduling call after receiving QosException.Throttle",
SafeArg.of("backoffMillis", backoff.toMillis()),
exception);
scheduleExecution(() -> doClone().enqueue(callback), backoff);
scheduleExecution(
() -> doClone().enqueue(callback),
backoff);
return null;
}

@Override
public Void visit(QosException.RetryOther exception) {
if (maxNumRelocations <= 0) {
callback.onFailure(call, new IOException("Exceeded the maximum number of allowed redirects for "
+ "initial URL: " + call.request().url()));
} else {
// Redirect to the URL specified by the exception.
Optional<HttpUrl> redirectTo = urls.redirectTo(request().url(),
exception.getRedirectTo().toString());
if (!redirectTo.isPresent()) {
callback.onFailure(call, new IOException("Failed to determine valid redirect URL for '"
+ exception.getRedirectTo() + "' and base URLs " + urls.getBaseUrls()));
} else {
Request redirectedRequest = request().newBuilder()
.url(redirectTo.get())
.build();
client.newCallWithMutableState(redirectedRequest, backoffStrategy, maxNumRelocations - 1)
.enqueue(callback);
}
callback.onFailure(call, new SafeIoException(
"Exceeded the maximum number of allowed redirects",
exception,
UnsafeArg.of("requestUrl", call.request().url().toString())));
return null;
}

// Redirect to the URL specified by the exception.
Optional<HttpUrl> redirectTo = urls.redirectTo(request().url(), exception.getRedirectTo().toString());
if (!redirectTo.isPresent()) {
callback.onFailure(call, new SafeIoException(
"Failed to determine valid redirect URL after receiving QosException.RetryOther",
exception,
UnsafeArg.of("requestUrl", call.request().url().toString()),
UnsafeArg.of("redirectToUrl", exception.getRedirectTo().toString()),
UnsafeArg.of("baseUrls", urls.getBaseUrls())));
return null;
}

log.debug("Retrying call after receiving QosException.RetryOther",
UnsafeArg.of("requestUrl", call.request().url()),
UnsafeArg.of("redirectToUrl", redirectTo.get()),
exception);
Request redirectedRequest = request().newBuilder()
.url(redirectTo.get())
.build();
client.newCallWithMutableState(redirectedRequest, backoffStrategy, maxNumRelocations - 1)
.enqueue(callback);
return null;
}

@Override
public Void visit(QosException.Unavailable exception) {
Optional<Duration> backoff = backoffStrategy.nextBackoff();
if (!backoff.isPresent()) {
log.debug("Max number of retries exceeded, failing call");
callback.onFailure(call,
new IOException("Failed to complete the request due to a "
+ "server-side QoS condition: 503", exception));
} else {
log.debug("Rescheduling call after backoff",
SafeArg.of("backoffMillis", backoff.get().toMillis()), exception);
// Redirect to the "next" URL, whichever that may be, after backing off.
Optional<HttpUrl> redirectTo = urls.redirectToNext(request().url());
if (!redirectTo.isPresent()) {
callback.onFailure(call, new IOException("Failed to determine valid redirect URL for base "
+ "URLs " + urls.getBaseUrls()));
} else {
Request redirectedRequest = request().newBuilder()
.url(redirectTo.get())
.build();
scheduleExecution(() -> client.newCallWithMutableState(redirectedRequest, backoffStrategy,
maxNumRelocations).enqueue(callback), backoff.get());
}
callback.onFailure(call, new SafeIoException(
"Failed to complete the request due to QosException.Unavailable",
exception,
UnsafeArg.of("requestUrl", call.request().url().toString())));
return null;
}

// Redirect to the "next" URL, whichever that may be, after backing off.
Optional<HttpUrl> redirectTo = urls.redirectToNext(request().url());
if (!redirectTo.isPresent()) {
callback.onFailure(call, new SafeIoException(
"Failed to determine valid redirect URL after receiving QosException.Unavailable",
UnsafeArg.of("requestUrl", call.request().url().toString()),
UnsafeArg.of("baseUrls", urls.getBaseUrls())));
return null;
}

log.debug("Retrying call after receiving QosException.Unavailable",
SafeArg.of("backoffMillis", backoff.get().toMillis()),
UnsafeArg.of("redirectToUrl", redirectTo.get()),
exception);
Request redirectedRequest = request().newBuilder()
.url(redirectTo.get())
.build();
scheduleExecution(
() -> client.newCallWithMutableState(redirectedRequest, backoffStrategy, maxNumRelocations)
.enqueue(callback),
backoff.get());
return null;
}
};
Expand Down
58 changes: 34 additions & 24 deletions okhttp-clients/src/test/java/com/palantir/conjure/java/okhttp/OkHttpClientsTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@

package com.palantir.conjure.java.okhttp;

import static com.palantir.logsafe.testing.Assertions.assertThatLoggableExceptionThrownBy;
import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.api.Assertions.assertThatExceptionOfType;
import static org.assertj.core.api.Assertions.assertThatThrownBy;
Expand All @@ -31,6 +32,7 @@
import com.palantir.conjure.java.api.errors.SerializableError;
import com.palantir.conjure.java.client.config.ClientConfiguration;
import com.palantir.conjure.java.client.config.ClientConfigurations;
import com.palantir.logsafe.UnsafeArg;
import com.palantir.logsafe.exceptions.SafeIoException;
import java.io.IOException;
import java.nio.file.Paths;
Expand Down Expand Up @@ -228,17 +230,19 @@ public void handlesUnavailable_obeysMaxNumRetriesAndEventuallyPropagatesQosExcep

server.enqueue(new MockResponse().setResponseCode(503));
call = createRetryingClient(0).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to complete the request due to a server-side QoS condition: 503");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to QosException.Unavailable")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));

server.enqueue(new MockResponse().setResponseCode(503));
server.enqueue(new MockResponse().setResponseCode(503));
server.enqueue(new MockResponse().setResponseCode(503));
call = createRetryingClient(2).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to complete the request due to a server-side QoS condition: 503");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to QosException.Unavailable")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));

assertThat(server.getRequestCount()).isEqualTo(4 /* original plus two retries */);
}
Expand All @@ -260,17 +264,19 @@ public void handlesThrottle_obeysMaxNumRetriesAndEventuallyPropagatesQosExceptio

server.enqueue(new MockResponse().setResponseCode(429));
call = createRetryingClient(0).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to reschedule call since the number of configured backoffs are exhausted");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to QosException.Throttle")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));

server.enqueue(new MockResponse().setResponseCode(429));
server.enqueue(new MockResponse().setResponseCode(429));
server.enqueue(new MockResponse().setResponseCode(429));
call = createRetryingClient(2).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to reschedule call since the number of configured backoffs are exhausted");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to QosException.Throttle")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));

assertThat(server.getRequestCount()).isEqualTo(4 /* original plus two retries */);
}
Expand All @@ -281,9 +287,10 @@ public void handlesThrottle_obeysMaxNumRetriesEvenWhenRetryAfterHeaderIsGiven()
server.enqueue(new MockResponse().setResponseCode(429).addHeader(HttpHeaders.RETRY_AFTER, "0"));
server.enqueue(new MockResponse().setResponseCode(429).addHeader(HttpHeaders.RETRY_AFTER, "0"));
Call call = createRetryingClient(2).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to reschedule call since the number of configured backoffs are exhausted");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to QosException.Throttle")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));
assertThat(server.getRequestCount()).isEqualTo(3 /* original plus two retries */);
}

Expand Down Expand Up @@ -317,9 +324,10 @@ public void handlesThrottle_usesConfiguredBackoffWhenResponseDoesNotAdvertiseBac
// no backoff advertised, configured no retry: fails
server.enqueue(new MockResponse().setResponseCode(429).setBody("foo"));
call = createRetryingClient(0).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to reschedule call since the number of configured backoffs are exhausted");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to QosException.Throttle")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));
}

@Test
Expand Down Expand Up @@ -372,9 +380,10 @@ public void handlesRetryOther_doesNotRedirectInfinitelyOften() throws Exception
}

Call call = createRetryingClient(1).newCall(new Request.Builder().url(url).build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Exceeded the maximum number of allowed redirects for initial URL: %s/", url);
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Exceeded the maximum number of allowed redirects")
.hasArgs(UnsafeArg.of("requestUrl", url + "/"));
assertThat(server.getRequestCount()).isEqualTo(21);
}

Expand Down Expand Up @@ -447,9 +456,10 @@ public void handlesIoExceptions_obeysMaxNumRetries() throws Exception {

OkHttpClient client = createRetryingClient(1, url, url2, url3);
Call call = client.newCall(new Request.Builder().url(url + "/foo?bar").build());
assertThatThrownBy(call::execute)
.isInstanceOf(IOException.class)
.hasMessage("Failed to complete the request due to an IOException");
assertThatLoggableExceptionThrownBy(call::execute)
.isInstanceOf(SafeIoException.class)
.hasLogMessage("Failed to complete the request due to an IOException")
.hasArgs(UnsafeArg.of("requestUrl", url2 + "/foo?bar"));

assertThat(server3.getRequestCount()).isEqualTo(0);
}
Expand Down

0 comments on commit b401608

Please sign in to comment.