Repository: beam Updated Branches: refs/heads/master beb21f472 -> 0b19fb414
[BEAM-1187] Improve logging to contain the number of retries done due to IOException and unsuccessful response codes. Project: http://git-wip-us.apache.org/repos/asf/beam/repo Commit: http://git-wip-us.apache.org/repos/asf/beam/commit/03741ba0 Tree: http://git-wip-us.apache.org/repos/asf/beam/tree/03741ba0 Diff: http://git-wip-us.apache.org/repos/asf/beam/diff/03741ba0 Branch: refs/heads/master Commit: 03741ba0b55e446cd2583e7ccc88f79ec21705b5 Parents: beb21f4 Author: Luke Cwik <lc...@google.com> Authored: Fri Jun 23 09:32:49 2017 -0700 Committer: Luke Cwik <lc...@google.com> Committed: Tue Jun 27 16:08:53 2017 -0700 ---------------------------------------------------------------------- .../sdk/util/RetryHttpRequestInitializer.java | 148 ++++++++++++------- .../util/RetryHttpRequestInitializerTest.java | 31 ++-- 2 files changed, 116 insertions(+), 63 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/beam/blob/03741ba0/sdks/java/extensions/google-cloud-platform-core/src/main/java/org/apache/beam/sdk/util/RetryHttpRequestInitializer.java ---------------------------------------------------------------------- diff --git a/sdks/java/extensions/google-cloud-platform-core/src/main/java/org/apache/beam/sdk/util/RetryHttpRequestInitializer.java b/sdks/java/extensions/google-cloud-platform-core/src/main/java/org/apache/beam/sdk/util/RetryHttpRequestInitializer.java index a23bee3..fd908cf 100644 --- a/sdks/java/extensions/google-cloud-platform-core/src/main/java/org/apache/beam/sdk/util/RetryHttpRequestInitializer.java +++ b/sdks/java/extensions/google-cloud-platform-core/src/main/java/org/apache/beam/sdk/util/RetryHttpRequestInitializer.java @@ -17,8 +17,9 @@ */ package org.apache.beam.sdk.util; -import com.google.api.client.http.HttpBackOffIOExceptionHandler; -import com.google.api.client.http.HttpBackOffUnsuccessfulResponseHandler; +import static com.google.api.client.util.BackOffUtils.next; + +import com.google.api.client.http.HttpIOExceptionHandler; import com.google.api.client.http.HttpRequest; import com.google.api.client.http.HttpRequestInitializer; import com.google.api.client.http.HttpResponse; @@ -60,65 +61,106 @@ public class RetryHttpRequestInitializer implements HttpRequestInitializer { */ private static final int HANGING_GET_TIMEOUT_SEC = 80; - private static class LoggingHttpBackOffIOExceptionHandler - extends HttpBackOffIOExceptionHandler { - public LoggingHttpBackOffIOExceptionHandler(BackOff backOff) { - super(backOff); + /** Handlers used to provide additional logging information on unsuccessful HTTP requests. */ + private static class LoggingHttpBackOffHandler + implements HttpIOExceptionHandler, HttpUnsuccessfulResponseHandler { + + private final Sleeper sleeper; + private final BackOff ioExceptionBackOff; + private final BackOff unsuccessfulResponseBackOff; + private final Set<Integer> ignoredResponseCodes; + private int ioExceptionRetries; + private int unsuccessfulResponseRetries; + + private LoggingHttpBackOffHandler( + Sleeper sleeper, + BackOff ioExceptionBackOff, + BackOff unsucessfulResponseBackOff, + Set<Integer> ignoredResponseCodes) { + this.sleeper = sleeper; + this.ioExceptionBackOff = ioExceptionBackOff; + this.unsuccessfulResponseBackOff = unsucessfulResponseBackOff; + this.ignoredResponseCodes = ignoredResponseCodes; } @Override public boolean handleIOException(HttpRequest request, boolean supportsRetry) throws IOException { - boolean willRetry = super.handleIOException(request, supportsRetry); + // We will retry if the request supports retry or the backoff was successful. + // Note that the order of these checks is important since + // backOffWasSuccessful will perform a sleep. + boolean willRetry = supportsRetry && backOffWasSuccessful(ioExceptionBackOff); if (willRetry) { + ioExceptionRetries += 1; LOG.debug("Request failed with IOException, will retry: {}", request.getUrl()); } else { - LOG.warn( - "Request failed with IOException (caller responsible for retrying): {}", + String message = "Request failed with IOException, " + + "performed {} retries due to IOExceptions, " + + "performed {} retries due to unsuccessful status codes, " + + "HTTP framework says request {} be retried, " + + "(caller responsible for retrying): {}"; + LOG.warn(message, + ioExceptionRetries, + unsuccessfulResponseRetries, + supportsRetry ? "can" : "cannot", request.getUrl()); } return willRetry; } - } - - private static class LoggingHttpBackoffUnsuccessfulResponseHandler - implements HttpUnsuccessfulResponseHandler { - private final HttpBackOffUnsuccessfulResponseHandler handler; - private final Set<Integer> ignoredResponseCodes; - - public LoggingHttpBackoffUnsuccessfulResponseHandler(BackOff backoff, - Sleeper sleeper, Set<Integer> ignoredResponseCodes) { - this.ignoredResponseCodes = ignoredResponseCodes; - handler = new HttpBackOffUnsuccessfulResponseHandler(backoff); - handler.setSleeper(sleeper); - handler.setBackOffRequired( - new HttpBackOffUnsuccessfulResponseHandler.BackOffRequired() { - @Override - public boolean isRequired(HttpResponse response) { - int statusCode = response.getStatusCode(); - return (statusCode == 0) // Code 0 usually means no response / network error - || (statusCode / 100 == 5) // 5xx: server error - || statusCode == 429; // 429: Too many requests - } - }); - } @Override - public boolean handleResponse(HttpRequest request, HttpResponse response, - boolean supportsRetry) throws IOException { - boolean retry = handler.handleResponse(request, response, supportsRetry); - if (retry) { + public boolean handleResponse(HttpRequest request, HttpResponse response, boolean supportsRetry) + throws IOException { + // We will retry if the request supports retry and the status code requires a backoff + // and the backoff was successful. Note that the order of these checks is important since + // backOffWasSuccessful will perform a sleep. + boolean willRetry = supportsRetry + && retryOnStatusCode(response.getStatusCode()) + && backOffWasSuccessful(unsuccessfulResponseBackOff); + if (willRetry) { + unsuccessfulResponseRetries += 1; LOG.debug("Request failed with code {}, will retry: {}", response.getStatusCode(), request.getUrl()); + } else { + String message = "Request failed with code {}, " + + "performed {} retries due to IOExceptions, " + + "performed {} retries due to unsuccessful status codes, " + + "HTTP framework says request {} be retried, " + + "(caller responsible for retrying): {}"; + if (ignoredResponseCodes.contains(response.getStatusCode())) { + // Log ignored response codes at a lower level + LOG.debug(message, + response.getStatusCode(), + ioExceptionRetries, + unsuccessfulResponseRetries, + supportsRetry ? "can" : "cannot", + request.getUrl()); + } else { + LOG.warn(message, + response.getStatusCode(), + ioExceptionRetries, + unsuccessfulResponseRetries, + supportsRetry ? "can" : "cannot", + request.getUrl()); + } + } + return willRetry; + } - } else if (!ignoredResponseCodes.contains(response.getStatusCode())) { - LOG.warn( - "Request failed with code {} (caller responsible for retrying): {}", - response.getStatusCode(), - request.getUrl()); + /** Returns true iff performing the backoff was successful. */ + private boolean backOffWasSuccessful(BackOff backOff) { + try { + return next(sleeper, backOff); + } catch (InterruptedException | IOException e) { + return false; } + } - return retry; + /** Returns true iff the {@code statusCode} represents an error that should be retried. */ + private boolean retryOnStatusCode(int statusCode) { + return (statusCode == 0) // Code 0 usually means no response / network error + || (statusCode / 100 == 5) // 5xx: server error + || statusCode == 429; // 429: Too many requests } } @@ -174,20 +216,20 @@ public class RetryHttpRequestInitializer implements HttpRequestInitializer { // TODO: Do this exclusively for work requests. request.setReadTimeout(HANGING_GET_TIMEOUT_SEC * 1000); - // Back off on retryable http errors. - request.setUnsuccessfulResponseHandler( + LoggingHttpBackOffHandler loggingHttpBackOffHandler = new LoggingHttpBackOffHandler( + sleeper, + // Retry immediately on IOExceptions. + BackOff.ZERO_BACKOFF, + // Back off on retryable http errors. // A back-off multiplier of 2 raises the maximum request retrying time // to approximately 5 minutes (keeping other back-off parameters to // their default values). - new LoggingHttpBackoffUnsuccessfulResponseHandler( - new ExponentialBackOff.Builder().setNanoClock(nanoClock) - .setMultiplier(2).build(), - sleeper, ignoredResponseCodes)); - - // Retry immediately on IOExceptions. - LoggingHttpBackOffIOExceptionHandler loggingBackoffHandler = - new LoggingHttpBackOffIOExceptionHandler(BackOff.ZERO_BACKOFF); - request.setIOExceptionHandler(loggingBackoffHandler); + new ExponentialBackOff.Builder().setNanoClock(nanoClock).setMultiplier(2).build(), + ignoredResponseCodes + ); + + request.setUnsuccessfulResponseHandler(loggingHttpBackOffHandler); + request.setIOExceptionHandler(loggingHttpBackOffHandler); // Set response initializer if (responseInterceptor != null) { http://git-wip-us.apache.org/repos/asf/beam/blob/03741ba0/sdks/java/extensions/google-cloud-platform-core/src/test/java/org/apache/beam/sdk/util/RetryHttpRequestInitializerTest.java ---------------------------------------------------------------------- diff --git a/sdks/java/extensions/google-cloud-platform-core/src/test/java/org/apache/beam/sdk/util/RetryHttpRequestInitializerTest.java b/sdks/java/extensions/google-cloud-platform-core/src/test/java/org/apache/beam/sdk/util/RetryHttpRequestInitializerTest.java index 37551a4..13a9309 100644 --- a/sdks/java/extensions/google-cloud-platform-core/src/test/java/org/apache/beam/sdk/util/RetryHttpRequestInitializerTest.java +++ b/sdks/java/extensions/google-cloud-platform-core/src/test/java/org/apache/beam/sdk/util/RetryHttpRequestInitializerTest.java @@ -49,10 +49,11 @@ import java.net.SocketTimeoutException; import java.security.PrivateKey; import java.util.Arrays; import java.util.concurrent.atomic.AtomicLong; +import org.apache.beam.sdk.testing.ExpectedLogs; import org.hamcrest.Matchers; import org.junit.After; -import org.junit.Assert; import org.junit.Before; +import org.junit.Rule; import org.junit.Test; import org.junit.runner.RunWith; import org.junit.runners.JUnit4; @@ -67,6 +68,8 @@ import org.mockito.stubbing.Answer; @RunWith(JUnit4.class) public class RetryHttpRequestInitializerTest { + @Rule public ExpectedLogs expectedLogs = ExpectedLogs.none(RetryHttpRequestInitializer.class); + @Mock private PrivateKey mockPrivateKey; @Mock private LowLevelHttpRequest mockLowLevelRequest; @Mock private LowLevelHttpResponse mockLowLevelResponse; @@ -135,6 +138,7 @@ public class RetryHttpRequestInitializerTest { verify(mockLowLevelRequest).setTimeout(anyInt(), anyInt()); verify(mockLowLevelRequest).execute(); verify(mockLowLevelResponse).getStatusCode(); + expectedLogs.verifyNotLogged("Request failed"); } /** @@ -153,7 +157,7 @@ public class RetryHttpRequestInitializerTest { HttpResponse response = result.executeUnparsed(); assertNotNull(response); } catch (HttpResponseException e) { - Assert.assertThat(e.getMessage(), Matchers.containsString("403")); + assertThat(e.getMessage(), Matchers.containsString("403")); } verify(mockHttpResponseInterceptor).interceptResponse(any(HttpResponse.class)); @@ -162,6 +166,7 @@ public class RetryHttpRequestInitializerTest { verify(mockLowLevelRequest).setTimeout(anyInt(), anyInt()); verify(mockLowLevelRequest).execute(); verify(mockLowLevelResponse).getStatusCode(); + expectedLogs.verifyWarn("Request failed with code 403"); } /** @@ -188,6 +193,7 @@ public class RetryHttpRequestInitializerTest { verify(mockLowLevelRequest, times(3)).setTimeout(anyInt(), anyInt()); verify(mockLowLevelRequest, times(3)).execute(); verify(mockLowLevelResponse, times(3)).getStatusCode(); + expectedLogs.verifyDebug("Request failed with code 503"); } /** @@ -211,6 +217,7 @@ public class RetryHttpRequestInitializerTest { verify(mockLowLevelRequest, times(2)).setTimeout(anyInt(), anyInt()); verify(mockLowLevelRequest, times(2)).execute(); verify(mockLowLevelResponse).getStatusCode(); + expectedLogs.verifyDebug("Request failed with IOException"); } /** @@ -224,19 +231,22 @@ public class RetryHttpRequestInitializerTest { int n = 0; @Override public Integer answer(InvocationOnMock invocation) { - return (n++ < retries - 1) ? 503 : 200; + return n++ < retries ? 503 : 9999; }}); Storage.Buckets.Get result = storage.buckets().get("test"); - HttpResponse response = result.executeUnparsed(); - assertNotNull(response); + try { + result.executeUnparsed(); + fail(); + } catch (Throwable t) { + } verify(mockHttpResponseInterceptor).interceptResponse(any(HttpResponse.class)); - verify(mockLowLevelRequest, atLeastOnce()).addHeader(anyString(), - anyString()); - verify(mockLowLevelRequest, times(retries)).setTimeout(anyInt(), anyInt()); - verify(mockLowLevelRequest, times(retries)).execute(); - verify(mockLowLevelResponse, times(retries)).getStatusCode(); + verify(mockLowLevelRequest, atLeastOnce()).addHeader(anyString(), anyString()); + verify(mockLowLevelRequest, times(retries + 1)).setTimeout(anyInt(), anyInt()); + verify(mockLowLevelRequest, times(retries + 1)).execute(); + verify(mockLowLevelResponse, times(retries + 1)).getStatusCode(); + expectedLogs.verifyWarn("performed 10 retries due to unsuccessful status codes"); } /** @@ -276,6 +286,7 @@ public class RetryHttpRequestInitializerTest { } catch (Throwable e) { assertThat(e, Matchers.<Throwable>instanceOf(SocketTimeoutException.class)); assertEquals(1 + defaultNumberOfRetries, executeCount.get()); + expectedLogs.verifyWarn("performed 10 retries due to IOExceptions"); } } }