Skip to content

Fix request timeouts: retries, body reads, and the flaky timeout test - #31

Merged
ndenny merged 2 commits into
developfrom
fix/flaky-retry-timeout-test
Oct 19, 2026
Merged

ndenny merged 2 commits into
developfrom
fix/flaky-retry-timeout-test

Conversation

@ndenny

@ndenny ndenny commented Oct 16, 2026 •

Copy link
Copy Markdown
Member

Summary

This started as a fix for the flaky TestRequestRetryTimeout. Investigating it turned up three bugs in how doRequestWithRetry (cli/request.go) applies rsh-timeout (-t), so this PR fixes those as well.

The flaky test

The test set a 1ms timeout against a gock mock that waits 2ms before replying. A context is only marked expired when its own timer callback runs, and gock's delay is a separate timer, so on a busy machine gock's timer can fire first. ctx.Err() is then still nil, gock returns the 200, and MakeRequest succeeds.

Reproduced locally by running the test binary with -test.count=3000 -test.cpu 1,2 alongside 8 yes > /dev/null processes: 13 failures in 6,000 runs, each a 200 on the first attempt after about 2ms. The test now uses a 10ms timeout and a 10s delay. gock stops waiting as soon as the request context is done, so the long delay costs nothing.

Timeout bugs fixed

  1. A retry after a timeout failed immediately. Each attempt's timeout context was derived from req.Context(), but req had already been replaced with the previous attempt's request, which carried the expired context. Each attempt now derives its timeout from the request's original context.
  2. -t cut off response bodies. Every attempt's cancel was deferred until doRequestWithRetry returned, which is before the caller reads the body. Any body larger than the transport's buffer failed with context canceled: a 4MB response came back as 3,963 bytes. The returned response's body is now wrapped so its timeout is released when the body is closed. An attempt that is thrown away for a retry has its body closed and its timeout released straight away.
  3. --rsh-retry 0 ignored -t. That path returned client.Do(req) before any timeout was applied. The retry loop now also runs when there are no retries, so the timeout always applies. The request body is still only buffered when a retry might need to resend it.

Behaviour changes beyond the fixes:

  • The timeout now covers reading the body, as well as waiting for the response. Before, it ended as soon as the function returned. Small bodies that were already buffered by then were unaffected, but larger ones were cut off (bug 2), so a slow body download was never actually timed.
  • -v now logs the request and response when --rsh-retry 0 is set. That path used to skip logging.
  • A response discarded for a status retry (429, 503, …) now has its body closed. It used to be left open.

The remaining comment on the test ("delay seems to have a bug where subsequent requests…are still delayed") was describing bug 1, not gock. I replaced it with the reason the mock has to reply twice.

Testing

  • TestRequestRetryTimeout now also checks that the retry reaches the server and that two full timeouts elapse (at least 20ms).
  • New TestRequestTimeoutWithoutRetries: -t applies with --rsh-retry 0.
  • New TestRequestTimeoutAllowsReadingBody: a 4MB body can be read in full after MakeRequest returns, with a timeout set.
  • All three fail against the old request.go (11ms elapsed instead of 20ms; no error after waiting the full 10s delay; context canceled while reading the body) and pass with the fix.
  • Under the CPU-load setup above: 2,000 runs of each of the three tests at -test.cpu 1,2, with no failures.
  • go test -race ./... passes.

🤖 Generated with Claude Code

The test set a 1ms timeout against a 2ms mock delay. A context is only
marked expired when its timer callback runs, so on a busy machine gock's
2ms timer could fire first, the mock replied 200 and MakeRequest
returned no error. Reproduced locally under CPU load (13 failures in
6,000 runs). Use a 10ms timeout and a 10s delay: gock stops waiting as
soon as the context is done, so the test is no slower.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟢 Approval recommended

It is a small, self-contained, empirically validated test-only change whose comment accurately matches the surrounding code and gock v1.1.2 behavior, with no production code affected.

No open issues 🎉

What changed in this PR

This PR fixes a flaky unit test, TestRequestRetryTimeout, in the cli package. The test verifies that a request which exceeds the configured rsh-timeout fails with a "timed out" error. Previously it pitted a 1ms request timeout against a 2ms gock response delay; because a context is only marked expired when its own timer callback runs, a busy CI machine could fire gock's 2ms timer first and return a 200 before the context expired, causing the "An error is expected but got nil" failure. The fix widens the gap between the two timers so the ordering can no longer flip.

Changes:

  • Raise rsh-timeout from 1ms to 10ms and the gock response Delay from 2ms to 10s, so the timeout reliably wins (gock stops waiting once the request context is done, so the long delay doesn't slow the test).
  • Replace a copy-pasted comment that described TestRequestRetryIn's header with an accurate explanation of why the delay must greatly exceed the timeout.
File Description
cli/​request_test.go Adjusts timeout/delay values in TestRequestRetryTimeout to remove timer-ordering flakiness and updates the explanatory comment.

Review effort: Balanced

doRequestWithRetry derived each attempt's rsh-timeout context from
req.Context(), but req had already been replaced with the previous
attempt's request, so a retry after a timeout started with an expired
context and failed immediately. Timeouts were never really retried.

It also deferred every cancel until the function returned, which is
before the caller reads the body. With -t set, any body larger than the
transport's buffer was cut off with "context canceled" (4MB came back
as 3,963 bytes).

And with --rsh-retry 0 it returned early and skipped the timeout
altogether.

Each attempt now derives its timeout from the request's original
context. A discarded attempt is released immediately, and the returned
response's timeout is released when its body is closed. The retry loop
also runs with no retries, so the timeout always applies. As a side
effect, -v now logs the request and response with --rsh-retry 0 too.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@ndenny ndenny changed the title Fix flaky TestRequestRetryTimeout Fix request timeouts: retries, body reads, and the flaky timeout test Oct 16, 2026
@ndenny
ndenny requested a balanced review from Copilot October 16, 2026 21:48

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

It changes context, cancellation, and body-streaming semantics in the core request path for every command, and such subtle concurrency/timeout lifecycle changes warrant final human review despite the added tests.

No open issues 🎉

Review effort: Balanced

@ndenny
ndenny merged commit 03abafd into develop Oct 19, 2026
2 checks passed
@ndenny
ndenny deleted the fix/flaky-retry-timeout-test branch October 19, 2026 14:37
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants