Skip to content

Commit

Permalink
Add retryDecision event to track retry logic in EventListener
Browse files Browse the repository at this point in the history
Introduced a new `retryDecision` event to improve observability of retry logic. This includes detailed reasons for retry decisions, enhancing debugging. Updated relevant tests, interceptors, and event handling to accommodate the new event.

It also cleanly signals the boundary before a prior request and the follow up.
  • Loading branch information
yschimke committed Feb 1, 2025
1 parent 40f183f commit 4717202
Show file tree
Hide file tree
Showing 6 changed files with 125 additions and 15 deletions.
7 changes: 7 additions & 0 deletions okhttp-testing-support/src/main/kotlin/okhttp3/CallEvent.kt
Original file line number Diff line number Diff line change
Expand Up @@ -232,4 +232,11 @@ sealed class CallEvent {
override val timestampNs: Long,
override val call: Call,
) : CallEvent()

data class RetryDecision(
override val timestampNs: Long,
override val call: Call,
val shouldRetry: Boolean,
val reason: String,
) : CallEvent()
}
Original file line number Diff line number Diff line change
Expand Up @@ -274,6 +274,16 @@ class ClientRuleEventListener(
delegate.cacheConditionalHit(call, cachedResponse)
}

override fun retryDecision(
call: Call,
shouldRetry: Boolean,
reason: String,
) {
logWithTime("retryDecision")

delegate.retryDecision(call, shouldRetry, reason)
}

private fun logWithTime(message: String) {
val startNs = startNs
val timeMs =
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,10 @@ open class RecordingEventListener(

inline fun <reified T : CallEvent> removeUpToEvent(): T = removeUpToEvent(T::class.java)

inline fun <reified T : CallEvent> findEvent(): T {
return eventSequence.first { it is T } as T
}

/**
* Remove and return the next event from the recorded sequence.
*
Expand Down Expand Up @@ -288,4 +292,12 @@ open class RecordingEventListener(
call: Call,
cachedResponse: Response,
) = logEvent(CacheConditionalHit(System.nanoTime(), call))

override fun retryDecision(
call: Call,
shouldRetry: Boolean,
reason: String,
) = logEvent(
CallEvent.RetryDecision(System.nanoTime(), call, shouldRetry, reason),
)
}
12 changes: 12 additions & 0 deletions okhttp/src/commonJvmAndroid/kotlin/okhttp3/EventListener.kt
Original file line number Diff line number Diff line change
Expand Up @@ -453,6 +453,18 @@ abstract class EventListener {
) {
}

/**
* Invoked when a failed call is considered for retry.
*
* This event won't be emitted when a call isSuccessful.
*/
open fun retryDecision(
call: Call,
shouldRetry: Boolean,
reason: String,
) {
}

fun interface Factory {
/**
* Creates an instance of the [EventListener] for a particular [Call]. The returned
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -90,7 +90,7 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
.build()

val exchange = call.interceptorScopedExchange
val followUp = followUpRequest(response, exchange)
val followUp = followUpRequest(response, exchange, call)

if (followUp == null) {
if (exchange != null && exchange.isDuplex) {
Expand All @@ -103,12 +103,14 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
val followUpBody = followUp.body
if (followUpBody != null && followUpBody.isOneShot()) {
closeActiveExchange = false
call.eventListener.retryDecision(call, false, "request.body isOneShot is true")
return response
}

response.body.closeQuietly()

if (++followUpCount > MAX_FOLLOW_UPS) {
call.eventListener.retryDecision(call, false, "Too many follow-up requests: $followUpCount")
throw ProtocolException("Too many follow-up requests: $followUpCount")
}

Expand All @@ -133,13 +135,19 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
requestSendStarted: Boolean,
): Boolean {
// The application layer has forbidden retries.
if (!client.retryOnConnectionFailure) return false
if (!client.retryOnConnectionFailure) {
call.eventListener.retryDecision(call, false, "retryOnConnectionFailure is false")
return false
}

// We can't send the request body again.
if (requestSendStarted && requestIsOneShot(e, userRequest)) return false
if (requestSendStarted && requestIsOneShot(e, userRequest)) {
call.eventListener.retryDecision(call, false, "request.body isOneShot is true")
return false
}

// This exception is fatal.
if (!isRecoverable(e, requestSendStarted)) return false
if (!isRecoverable(e, requestSendStarted, call)) return false

// No more routes to attempt.
if (!call.retryAfterFailure()) return false
Expand All @@ -160,16 +168,28 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
private fun isRecoverable(
e: IOException,
requestSendStarted: Boolean,
call: RealCall,
): Boolean {
// If there was a protocol problem, don't recover.
if (e is ProtocolException) {
call.eventListener.retryDecision(call, false, "failure was ProtocolException")
return false
}

// If there was an interruption don't recover, but if there was a timeout connecting to a route
// we should try the next route (if there is one).
if (e is InterruptedIOException) {
return e is SocketTimeoutException && !requestSendStarted
if (e is SocketTimeoutException) {
if (requestSendStarted) {
call.eventListener.retryDecision(call, false, "request was at least partially sent")
return false
}
} else {
call.eventListener.retryDecision(call, false, "failure was InterruptedIOException")
return false
}

return true
}

// Look for known client-side or negotiation errors that are unlikely to be fixed by trying
Expand All @@ -178,13 +198,17 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
// If the problem was a CertificateException from the X509TrustManager,
// do not retry.
if (e.cause is CertificateException) {
call.eventListener.retryDecision(call, false, "failure was CertificateException")
return false
}
}

if (e is SSLPeerUnverifiedException) {
// e.g. a certificate pinning error.
call.eventListener.retryDecision(call, false, "certificate pinning failure")
return false
}

// An example of one we might want to retry with a different route is a problem connecting to a
// proxy and would manifest as a standard IOException. Unless it is one we know we should not
// retry, we return true and try a new route.
Expand All @@ -200,6 +224,7 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
private fun followUpRequest(
userResponse: Response,
exchange: Exchange?,
call: RealCall,
): Request? {
val route = exchange?.connection?.route()
val responseCode = userResponse.code
Expand All @@ -209,15 +234,23 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
HTTP_PROXY_AUTH -> {
val selectedProxy = route!!.proxy
if (selectedProxy.type() != Proxy.Type.HTTP) {
call.eventListener.retryDecision(call, false, "Received HTTP_PROXY_AUTH (407) code while not using proxy")
throw ProtocolException("Received HTTP_PROXY_AUTH (407) code while not using proxy")
}
call.eventListener.retryDecision(call, true, "Received HTTP_PROXY_AUTH (407) code")
return client.proxyAuthenticator.authenticate(route, userResponse)
}

HTTP_UNAUTHORIZED -> return client.authenticator.authenticate(route, userResponse)
HTTP_UNAUTHORIZED -> return client.authenticator.authenticate(route, userResponse).also {
if (it != null) {
call.eventListener.retryDecision(call, true, "Received HTTP_UNAUTHORIZED (401) and authenticate request")
} else {
call.eventListener.retryDecision(call, false, "Received HTTP_UNAUTHORIZED (401) without authenticate request")
}
}

HTTP_PERM_REDIRECT, HTTP_TEMP_REDIRECT, HTTP_MULT_CHOICE, HTTP_MOVED_PERM, HTTP_MOVED_TEMP, HTTP_SEE_OTHER -> {
return buildRedirectRequest(userResponse, method)
return buildRedirectRequest(userResponse, method, call)
}

HTTP_CLIENT_TIMEOUT -> {
Expand All @@ -226,38 +259,46 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
// repeat the request (even non-idempotent ones.)
if (!client.retryOnConnectionFailure) {
// The application layer has directed us not to retry the request.
call.eventListener.retryDecision(call, false, "HTTP_CLIENT_TIMEOUT (408) and retryOnConnectionFailure is false")
return null
}

val requestBody = userResponse.request.body
if (requestBody != null && requestBody.isOneShot()) {
call.eventListener.retryDecision(call, false, "HTTP_CLIENT_TIMEOUT (408) and request.body isOneShot is true")
return null
}
val priorResponse = userResponse.priorResponse
if (priorResponse != null && priorResponse.code == HTTP_CLIENT_TIMEOUT) {
call.eventListener.retryDecision(call, false, "HTTP_CLIENT_TIMEOUT (408) received on retry")
// We attempted to retry and got another timeout. Give up.
return null
}

if (retryAfter(userResponse, 0) > 0) {
call.eventListener.retryDecision(call, false, "HTTP_CLIENT_TIMEOUT (408) with Retry-After")
return null
}

call.eventListener.retryDecision(call, true, "HTTP_CLIENT_TIMEOUT (408)")
return userResponse.request
}

HTTP_UNAVAILABLE -> {
val priorResponse = userResponse.priorResponse
if (priorResponse != null && priorResponse.code == HTTP_UNAVAILABLE) {
// We attempted to retry and got another timeout. Give up.
call.eventListener.retryDecision(call, false, "HTTP_UNAVAILABLE (503) received on retry")
return null
}

if (retryAfter(userResponse, Integer.MAX_VALUE) == 0) {
// specifically received an instruction to retry without delay
call.eventListener.retryDecision(call, true, "HTTP_UNAVAILABLE (503) with Retry-After = 0")
return userResponse.request
}

call.eventListener.retryDecision(call, false, "HTTP_UNAVAILABLE (503)")
return null
}

Expand All @@ -267,35 +308,56 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
// we can retry on a different connection.
val requestBody = userResponse.request.body
if (requestBody != null && requestBody.isOneShot()) {
call.eventListener.retryDecision(call, false, "HTTP_MISDIRECTED_REQUEST (421) and request.body isOneShot is true")
return null
}

if (exchange == null || !exchange.isCoalescedConnection) {
call.eventListener.retryDecision(call, false, "HTTP_MISDIRECTED_REQUEST (421) on non coalesced connection")
return null
}

exchange.connection.noCoalescedConnections()
call.eventListener.retryDecision(call, true, "HTTP_MISDIRECTED_REQUEST (421), retrying without coalesced connection")
return userResponse.request
}

else -> return null
else -> return null.also {
if (!userResponse.isSuccessful) {
call.eventListener.retryDecision(call, false, "No rule to retry request ($responseCode)")
}
}
}
}

private fun buildRedirectRequest(
userResponse: Response,
method: String,
call: RealCall,
): Request? {
// Does the client allow redirects?
if (!client.followRedirects) return null
if (!client.followRedirects) {
call.eventListener.retryDecision(call, false, "followRedirects is false after redirect (${userResponse.code})")
return null
}

val location = userResponse.header("Location") ?: return null
val location =
userResponse.header("Location") ?: return null.also {
call.eventListener.retryDecision(call, false, "redirect (${userResponse.code}) without Location")
}
// Don't follow redirects to unsupported protocols.
val url = userResponse.request.url.resolve(location) ?: return null
val url =
userResponse.request.url.resolve(location) ?: return null.also {
call.eventListener.retryDecision(call, false, "redirect (${userResponse.code}) to unsupported protocol")
}

// If configured, don't follow redirects between SSL and non-SSL.
val sameScheme = url.scheme == userResponse.request.url.scheme
if (!sameScheme && !client.followSslRedirects) return null
if (!sameScheme && !client.followSslRedirects) {
return null.also {
call.eventListener.retryDecision(call, false, "redirect (${userResponse.code}) switching scheme and followSslRedirects is false")
}
}

// Most redirects don't include a request body.
val requestBuilder = userResponse.request.newBuilder()
Expand Down Expand Up @@ -325,6 +387,8 @@ class RetryAndFollowUpInterceptor(private val client: OkHttpClient) : Intercepto
requestBuilder.removeHeader("Authorization")
}

call.eventListener.retryDecision(call, true, "redirect (${userResponse.code})")

return requestBuilder.url(url).build()
}

Expand Down
11 changes: 8 additions & 3 deletions okhttp/src/jvmTest/kotlin/okhttp3/EventListenerTest.kt
Original file line number Diff line number Diff line change
Expand Up @@ -243,8 +243,9 @@ class EventListenerTest {
"CallStart",
"ProxySelectStart", "ProxySelectEnd", "DnsStart", "DnsEnd",
"ConnectStart", "ConnectEnd", "ConnectionAcquired", "RequestHeadersStart",
"RequestHeadersEnd", "ResponseFailed", "ConnectionReleased", "CallFailed",
"RequestHeadersEnd", "ResponseFailed", "RetryDecision", "ConnectionReleased", "CallFailed",
)
assertThat(listener.findEvent<CallEvent.RetryDecision>().reason).isEqualTo("request was at least partially sent")
}

@Test
Expand Down Expand Up @@ -1645,10 +1646,11 @@ class EventListenerTest {
"ProxySelectStart", "ProxySelectEnd", "DnsStart", "DnsEnd",
"ConnectStart", "ConnectEnd", "ConnectionAcquired", "RequestHeadersStart",
"RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd", "ResponseBodyStart",
"ResponseBodyEnd", "RequestHeadersStart", "RequestHeadersEnd", "ResponseHeadersStart",
"ResponseBodyEnd", "RetryDecision", "RequestHeadersStart", "RequestHeadersEnd", "ResponseHeadersStart",
"ResponseHeadersEnd", "ResponseBodyStart", "ResponseBodyEnd", "ConnectionReleased",
"CallEnd",
)
assertThat(listener.findEvent<CallEvent.RetryDecision>().reason).isEqualTo("redirect (302)")
}

@Test
Expand Down Expand Up @@ -1678,6 +1680,7 @@ class EventListenerTest {
"ResponseHeadersEnd",
"ResponseBodyStart",
"ResponseBodyEnd",
"RetryDecision",
"ConnectionReleased",
"ProxySelectStart",
"ProxySelectEnd",
Expand All @@ -1695,6 +1698,7 @@ class EventListenerTest {
"ConnectionReleased",
"CallEnd",
)
assertThat(listener.findEvent<CallEvent.RetryDecision>().reason).isEqualTo("redirect (302)")
}

@Test
Expand Down Expand Up @@ -1915,7 +1919,8 @@ class EventListenerTest {
assertThat(response.code).isEqualTo(504)
response.close()
assertThat(listener.recordedEventTypes())
.containsExactly("CallStart", "SatisfactionFailure", "CallEnd")
.containsExactly("CallStart", "SatisfactionFailure", "RetryDecision", "CallEnd")
assertThat(listener.findEvent<CallEvent.RetryDecision>().reason).isEqualTo("No rule to retry request (504)")
}

@Test
Expand Down

0 comments on commit 4717202

Please sign in to comment.