runtime/events: Fix rate limits error handling in recorder

[jvcdk]

History

This is patch stems from investigating the issue described in PR Bugfix: Perform http post in goroutine to prevent locking up the reconciler loop. See this for background info on the issue.

Brief bug explanation

• The Notification Controller returns a 429 Too Many Requests upon receiving duplicate messages (within a 5 minute window). See function eventKeyFunc for details.
• The Event Recorder handles this explicitly in the AnnotatedEventf function.
• However, this is only handled for the initial attempt. When using the go-retryablehttp client, the 429 code is interpreted as "please retry later at <time xxx>" (which is a sane behavior for the general use of go-retryablehttp).
  Code points of interest:
  • Configuration of go-retryablehttp to use ErrorPropagatedRetryPolicy.
  • Calling go-retryablehttp (after initial message post failed).
  • ErrorPropagatedRetryPolicy uses baseRetryPolicy which in turn handles http code 429 as please-retry-again.

Brief bugfix explanation

• Replaced checkRetry callback function (of the go-retryablehttp client) from ErrorPropagatedRetryPolicy to a custom function:
  • Do not perform retry on http code 429.
  • Otherwise, fallback to ErrorPropagatedRetryPolicy.
• Removed the manual check for http code 429 (as this is now handled as a more general case).

Side contemplations

Number of retrys

The default retry count is 4, resulting in 5 post attempts from go-retryablehttp client, and 6 total attempts (including the manual 429 check) for the original code.

With this PR, the manual attempt is removed, and thus the total attempts is 5. I assume this is ok, but if not, it is easy to increment the retry count.

Response code from Notification Controller

I would suggest that the Notification Controller would return StatusAlreadyReported (instead of StatusTooManyRequests) as a result of duplicated messages. This would remove the need for the custom http code handling in the Kustomize Controller.

(However, this stems from the go-limiter package that Notification Controller uses. See middleware.go, L119.)

Detailed failure scenario description

Here I will lay out the failure scenario that led to this PR. It is meant as auxiliary reading if you wish to understand more in depth how this bug plays out.

Details

Here is a screenshot of the event recorder code and go-retryablehttp client. There is an inlay with two log statements from my debugging session.

Here are some notes to explain the steps further:

1. The code starts with a manual message post to the Notification Controller.
2. Unfortunately, the Notification Controller is not reachable and the http call times out. (See note below)
3. Since the result is not StatusTooManyRequests (in fact, res == nil), the code does not return.
4. The message is attempted to be posted again, this time with the retryable http client.
5. The Notification Controller is still unreachable, yielding a timeout error.
6. The baseRetryPolicy handles this with a generic try-again policy.
7. The back-off calculation uses a default policy, resulting in a back-off delay of 2 seconds.
8. 2nd time it tries, the Notification Controller is reachable. The event is a duplicate and thus the Notification Controller returns 429 Too Many Requests.
   • Note: The log file is from edited code (extra log data + PoC bugfix) and thus the "giving up after 2 attempts" is not the behavior of the original code. The original code would succeed in the 3rd attempt, see next points.
9. The 429 Too Many Requests results in a try-again policy. (This is the behavior that is changing with this PR.)
10. The Notification Controller supplies a Retry-After header of 5 minutes. This stems from the command line option --rate-limit-interval which defaults to 5 minutes.
    • It is this behavior that makes the reconciliation stall as described in my original Kustomize Controller PR.
11. [Not shown on screenshot]: After 5 minutes of wait time, the retryable http client posts the message to the Notification Controller again, and this times succeeds (because the back-off time was respected).

Unreachable Notification Controller

This happens in our cluster during start-up and is due to a reconfiguration of Cilium. This is a separate issue that I am investigating as well.

[stefanprodan]

@jvcdk could you please amend your commit and rename it to runtime/events/recorder: Fix rate limits error handling, also sign-off on it with git commit -s and rebase / force push.

[matheuscscp]

Thanks! This fix LGTM, just one nit

[jvcdk]

@jvcdk could you please amend your commit and rename it to runtime/events/recorder: Fix rate limits error handling, also sign-off on it with git commit -s and rebase / force push.

Done.

[stefanprodan]

@jvcdk you need to pull latest main into your fork then rebase your branch and force push

[jvcdk]

@jvcdk you need to pull latest main into your fork then rebase your branch and force push

Sorry. Hadn't seen main had moved. Done :)

[matheuscscp]

LGTM! 🚀

[jvcdk]

Amended commit with fix to tests.