Capture and log information about gorouter retries

[peanball]

Is this a security vulnerability?

No.

Issue

The time that is spent on Gorouter retries is unclear / invisible in the gorouter 'access log' and requires manual correlation with other logs.

The response_time metric does not break down further into components that would be useful for error triage, latency analysis and customer support.

Affected Versions

All.

Context

Gorouter retries requests that can safely be retried on other route endpoints (if available). Such retries can take time. Depending on the type of error, this time can be much higher than the regular response time.

Each retry is logged explicitly as log message, indicating the request attempt and reason for error, but the number of attempts or time taken for all unsuccessful attempts is not recorded in the final log summarizing the request.

Other times, e.g. the dial time to particular endpoints, is also not recorded and would help to fine-tune the endpoint_dial_timeout property that would allow reducing the time spent on retries due to unreachable endpoint that ends in an i/o timeout error.

The 'access log' is the gorouter log that includes the URL, response code, etc. and is logged at the end of the negroni middleware chain.

Proposal

We propose to:

1. capture the time taken on a particular attempt and log it in the retry error log
2. log the cumulative time spent on unsuccessful attempts, and the number of attempts it took to complete the request in the 'access log'
3. capture the dial time as part of the Dialer to collect metrics, which would allow allow finding the 'worst case scenario' for currently deployed backends and adjust a lower endpoint_dial_timeout accordingly.
4. log the dial time for each attempt.

The result would be an access log that contains:

• response_time -> the complete time the request has taken from arriving at gorouter to responding to the client (unchanged)
• gorouter_time -> the time gorouter required for internal processing, including route lookup, etc.
• retry_time -> the time gorouter spent on unsuccessful attempts that needed to be retried.
• dial_time -> the dial_time of the successful response

The app response time for the successful response could then be computed as follows: response_time - gorouter_time - retry_time

The same logic could apply for failed requests, i.e. when none of the gorouter retries would lead to a successful backend response.

[plowin]

We would like to contribute the proposed functionality. If there are objections/concerns/remarks, feel free to add them here!
/cc @ameowlia

[a18e]

I generally agree.
But rather than logging retry_time in the access log, I would propose logging the inverse, i.e. the time of the last request (whether that was successful or not).
I believe that this value (let's call it app_instance_response_time or instance_response_time) is more directly useful for the customer, as they can see how long their app takes to respond when it is working correctly.
And even if their app fails for every attempt, the value of instance_response_time would equal endpoint_dial_timeout, which could be communicated to the customer as a quick indication that it's an app issue (instead of a platform issue).
The amount of time spent on unsuccessful connection attempts (your retry_time) could still be calculated as response_time - gorouter_time - instance_response_time

Additionally, we should consider including the amount of attempts (attempt_count) as a separate field in the logs.
Otherwise the customer would have perform the following calculation to get to that value:

retry_time = response_time - gorouter_time - instance_response_time
attempt_count = retry_time / endpoint_dial_timeout + 1

Of course it would also help platform operators as they no longer need to correlate the access logs with the retry error logs, which would also enable statistical analysis of retry behaviour on a landscape.

[peanball]

@a18e, I would like the retry time or failed attempt time to be measured by the sum of failed request durations, not computed from other times. Otherwise we might mask times that were introduced somewhere in the chain without seeing the discrepancy towards the overall response_time.
But fair point that the time for the last (and successful) request could be pointed out specifically.

Logging the total number of attempts in the 'access log' was intended in the description but maybe not clear enough. Thanks for highlighting it. This number must be the sum of actual attempts and must not be computed or derived from any timeouts.

[domdom82]

dial_time will be interesting, because you have the dial time of an individual attempt (i.e. Transport.DialTLS), where I assume it will be part of the retry_time (rather: attempt_time) and then you have the total of all dial_time that you may or may not want report on the access log.

I'd favor a simple approach:

• per each attempt, record:
  • dial_time (the time it took to connect to the backend)
  • response_time (the time it took for the backend to respond, if at all)
  • gorouter_time (the time spent on gorouter doing lookups etc, may be one time for all attempts combined)
• write all times to the error log as we do now

on the access log, we have two options:
A) record a sum of all attempts combined, i.e. dial_time = sum(dial_time_1, dial_time_2, ..)

B) record only the last attempt with its dial_time, gorouter_time and response_time. Then combine all of the attempt's times into one "retry_time" so that the user can compare that time with the total response_time to see how much % of time was spent on retries vs. the actual app's response.

[peanball]

@domdom82 I'm in favor of your option B), with one minor change in phrasing:

Then combine all of the failed attempt's times into one "retry_time" so that the user can compare that time with the total response_time to see how much % of time was spent on failed attempts that needed to be retried vs. the actual app's response.

[ameowlia]

It never occurred to me that these time values would include retry times. I support the idea of making these values easier to reason about.

However, I am worried about breaking backwards compatibility. I believe option B would change the definitions of the properties as they currently stand.

Here is my understanding of what proposal B is. Please correct me if I am wrong.

Property Name	Current definition	Proposed definition per "B" above
response_time	Time it took for the app to respond. Including all retry attempts.	Time it took for the app to respond on a success. Only the value for the last attempt. No retries included. ❌ I think this would be a confusing breaking change.
gorouter_time	This is calculated my tracking the time through most of the gorouter handlers + the response time, then subtracting the response time. The retry time ends up being removed.	Maybe this stays the same?
retry_time	does not exist yet	I think this would be the original definition of response_time.
dial_time	does not exist yet	Time it take to connect to an app. Only the value for the last attempt. No retires included.

Overall take aways

1. Is there a way to do this that does not change the definitions of the current properties?
2. If you think changing the current properties is absolutely needed, what is your backwards compatibility plan?
3. If you end up making a per-request metric, make sure users can opt out using this gorouter property.

[peanball]

@ameowlia The idea is to not break anything. We'll provide a graphic that makes the different times clearer on Monday.

[peanball]

@ameowlia a week late but here's the graphic I was talking about.

All colored variables are new values. Italic values are existing variables.

This is a minor deviation from what we call "Option B)" but as you say, the goal should be to not make incompatible changes. Thanks for pointing out that there would have been with Option B.

[ameowlia]

✨ Thanks for the clear diagram of all the times @peanball! At the bottom you have examples of access logs and errors logs that you want to exist (right?). Can you also add examples of what currently exists, so I can easily compare them and see what you intend to change? Thanks!

[ameowlia]

Also we should definitely add that diagram to the docs somewhere as part of this effort.

[peanball]

@ameowlia I've updated the graphic in the comment above to highlight new values and already existing values.

All colored variables are new values. Italic values are existing variables.

So in the access log we had (those remain unchanged):

• gorouter_time - time that was spent in gorouter to find routes, do checks, extract and log headers, etc.
• response_time - the end-to-end time from request coming in to response going out

new for the access log:

• retries - the number of unsuccessful attempts and consequently retries that were necessary before the successful attempt was made, or attempts that just shows the total number of attempts.
• retry_time - the time spent on unsuccessful attempts (w/o dial)
• retry_dial_times - the time spent on dials during unsuccessful attempts
• backend_time (alternative app_time?) - time taken for the successful attempt. app_time might be misleading if we retry because of retriable errors on a faulty app instance
• dial_time - the dial time of the successful attempt

In the error logs we had:

• attempt - number of the attempt that failed
• (information about the error, number of available endpoints for this route and other information that is not relevant for this issue and will remain untouched)

new in error logs:

• backend_time - the time spent on this unsuccessful attempt (w/o dial)
• dial_time - the time spent dialing to this endpoint

[ameowlia]

Thanks for calling out all of this explicitly @peanball .

1. I like the attempt better than retry. I find it clearer.
2. I like backend_time better than app_time.
3. I think this diagram is missing a small amount of gorouter time that would happen at the very end.

I like this idea of being more specific and improving troubleshooting. However, I am always worried about adding more logs given that operators are often very sensitive to the size of logs, especially on per request logs.

❓ Can you add these additional items behind a bosh property. You can have it default to true, but if we get push back from endusers I want an easy way to be able to turn it off.

[maxmoehl]

I'm starting to implement the proposed changes.

1. I like the attempt better than retry. I find it clearer.

✅

2. I like backend_time better than app_time.

✅

3. I think this diagram is missing a small amount of gorouter time that would happen at the very end.

I will update the diagram with our latest understanding, we have some additional changes.

❓ Can you add these additional items behind a bosh property. You can have it default to true, but if we get push back from endusers I want an easy way to be able to turn it off.

Will do, but it will probably default to false to avoid unexpected changes to the log format that can break log parsing.

[maxmoehl]

To further extend on the comment from @peanball:

new for the access log:

• retries - the number of unsuccessful attempts and consequently retries that were necessary before the successful attempt was made, or attempts that just shows the total number of attempts.
  • => Renamed to failed_attempts.
• retry_time - the time spent on unsuccessful attempts (w/o dial)
  • => Renamed to failed_attempts_time.
• retry_dial_times - the time spent on dials during unsuccessful attempts
  • => Omitted, available in the error log.
• backend_time (alternative app_time?) - time taken for the successful attempt. app_time might be misleading if we retry because of retriable errors on a faulty app instance
  • => Will stay as backend_time
• dial_time - the dial time of the successful attempt
  • Will also add: tls_time, dns_time

new in error logs:

• backend_time - the time spent on this unsuccessful attempt (w/o dial)
• dial_time - the time spent dialing to this endpoint
  • Already present in the error log.

---

This makes the diagram a bit simpler:

---

In the case that all attempts fail, the times in the access log will be empty and the entire time spent trying will be stored in failed_attempts_time, the error logs will still contain the detailed timings of each attempt.