Skip to content

fix: retry 504 GatewayTimeout and resume truncated source reads - #144

Merged
ServerSideHannes merged 3 commits into
mainfrom
fix/source-read-resume
Jul 29, 2026
Merged

fix: retry 504 GatewayTimeout and resume truncated source reads#144
ServerSideHannes merged 3 commits into
mainfrom
fix/source-read-resume

Conversation

@ServerSideHannes

@ServerSideHannes ServerSideHannes commented Jul 29, 2026

Copy link
Copy Markdown
Owner

Two independent backend failure modes taking down the Scylla main.companies backup, plus a test-fidelity fix that let one of them hide.

1. Unretried 504 GatewayTimeout (the dominant cause)

Census of the 288 fatal copy failures captured live during a failing run:

273 x  504 GatewayTimeout  on UploadPartCopy   <- 95%
 17 x  504 GatewayTimeout  on PutObject
  7 x  504 GatewayTimeout  on GetObject
  8 x  ContentLengthError (truncation)

copy.py already retries via is_retryable_source_error, but _RETRYABLE_S3_ERROR_CODES contained 500, 502, 503 — and not 504. So a 504 hit raise on first occurrence. The smoking gun is the ratio in the logs:

297 x  504 GatewayTimeout
  4 x  UPLOAD_PART_COPY_SEGMENT_RETRY

Reproduced against the real object: 572 UploadPartCopy calls at 8-way concurrency → 1 x 504 (0.17%), latency p50 1.14s / p90 3.31s / max 61.86s. Latency is heavy-tailed, so a 504 is transient congestion when Hetzner's own server-side copy exceeds an internal deadline.

At 0.17% per copy, a 4.7GB file (572 copies) has a ~63% chance of hitting one; 10 nodes concurrently approaches certainty. That's why companies failed on 10 of 13 racks while smaller tables passed.

botocore does retry 504 (its _retry.json has a gateway_timeout policy) but all attempts fire inside the same congestion window and exhaust — "reached max retries: 3" appears 297 times. Retrying here with SOURCE_READ_BACKOFF_SEC exponential backoff gives the backend time to clear. UploadPartCopy is idempotent for a given PartNumber+range, so the retry is safe — the same argument #133 used.

2. Truncated source reads

Hetzner ends a response mid-body with a clean TCP FIN while still advertising the full Content-Length. All 327 captured occurrences were clean closes — none carried the connection_closed_cleanly=False suffix aiohttp/client_proto.py:147 adds for connection errors.

Ruled out by measurement: network fault (clean FIN, not a reset), crypto blocking the loop (8MB AES-GCM decrypt = 1.9ms), memory governor (zero backpressure/rejection events), HAProxy (not on this hop — direct HTTPS), pod/node specific (all 28 pods, ~25 nodes, amd64 + arm64).

Truncation lands on a page boundary, only two values ever:

190 x  received 4165632 of 8388636   (1017 x 4096)
137 x  received 8331264 of 8388636   (2034 x 4096)

Re-requesting the identical range reproduces the identical truncation — 9 of 12 retried ranges cut at the same offset every attempt. So retry cannot make progress; resume can, because a fresh request gets a fresh response buffer. Same vendor behaviour COPY_SOURCE_STREAM_RESUME already handles on the upload side.

Implementation notes:

  • Chunked accumulation is required: StreamingBody.read() collects blocks in a local list and discards them all if the stream raises mid-body.
  • async with resp["Body"] unwraps to the raw ClientResponse, whose read() takes no size argument, so the chunk loop must stay outside that context.

3. Mock fidelity

That second note was a real bug I shipped and only caught in end-to-end testing — the shared MockS3Response.__aenter__ returned self, keeping a size-aware read() that production does not have. It now returns a wrapper without it, matching aiobotocore.

Reintroducing that bug now fails 24 tests instead of 0.

Verification

Resume, against the production object that fails — truncate at the observed prod offset, resume, compare:

expected len=8388636 sha=452e3406c6370759
resumed  len=8388636 sha=452e3406c6370759
IDENTICAL: True

Resume returns exactly the missing bytes, 4 real prod-failing ranges:

full=0-8388635              trunc@4165632 -> need 4223004  got 4223004  OK
full=87381896-95770531      trunc@4165632 -> need 4223004  got 4223004  OK
full=4998244300-5006632935  trunc@8331264 -> need   57372  got   57372  OK
full=253407494-261796129    trunc@4165632 -> need 4223004  got 4223004  OK
check result
new tests 22 passed
full unit suite 735 passed, 0 failed
ruff check / format --check clean
control: revert resume 5 fail
control: revert 504 3 fail
control: revert mock fix 24 fail

Scope

MULTIPART_ABORTED (292) and the InvalidPart seen on an earlier run are consequences, not separate causes — 261 of 292 aborts directly follow a fatal copy failure, and orphaned multiparts are what a later completion rejects. Removing the 504s should remove both.

Residual risk: with 4 attempts and exponential backoff, per-copy failure probability drops to roughly 0.17%^4 — negligible if 504s are independent. Measurement showed one isolated 504 in 572 calls rather than a burst, but independence under 10-node concurrent load is not proven.

Test mocks in test_source_read_retry.py needed read(n) signatures; those tests' behaviour is unchanged (8 passed).

Hetzner terminates a response mid-body with a clean TCP FIN while still
advertising the full Content-Length, so aiohttp raises ClientPayloadError with
only part of the payload delivered. All 327 occurrences captured during a live
backup were clean closes (no ConnectionError suffix), i.e. the sender ended the
response deliberately -- not a network fault, not socket starvation (8MB
AES-GCM decrypt measured at 1.9ms), not the memory governor (zero
MEMORY_BACKPRESSURE/REJECTED events).

Measured at ~0.5% per read (2 of 400 in a sustained 16-way probe against the
same object), always ending on a page boundary. Only two values ever appeared:

    190 x  received 4165632 of 8388636   (1017 x 4096)
    137 x  received 8331264 of 8388636   (2034 x 4096)

Re-requesting the identical range reproduces the identical truncation (9 of 12
retried ranges cut at the same offset every attempt), so plain retry cannot make
progress -- ~12% of reads never recovered regardless of attempt count. At ~572
reads per 4.7GB copy a large file had a ~94% chance of hitting at least one,
which is why main.companies failed nearly every run while smaller tables passed.

Keep what arrived and request only the remainder: a fresh request gets a fresh
response buffer. Same vendor behaviour COPY_SOURCE_STREAM_RESUME already handles
on the upload side; the source-read path never got it.

Reading must accumulate in bounded chunks off the StreamingBody: read() collects
blocks in a local list and discards them all when the stream raises mid-body.
Note `async with resp["Body"]` unwraps to the raw ClientResponse, whose read()
takes no size argument, so the chunk loop stays outside that context.

Verified against the production object that fails: truncating at the observed
prod offset and resuming yields bytes SHA-256 identical to an untruncated read.
aiobotocore's StreamingBody.__aenter__ returns the *wrapped*
aiohttp.ClientResponse, whose read() takes no size argument -- so
`async with body: body.read(n)` is a TypeError in production. The mock
returned `self`, which kept the size-aware read() available and let that
exact bug pass the whole unit suite while failing against the real backend.

Reintroducing the bug now fails 24 tests instead of 0.
273 of 288 fatal copy failures in the 2026-07-29 capture were HTTP 504
GatewayTimeout on UploadPartCopy; another 17 on PutObject and 7 on GetObject.
The segment loop in copy.py already retries via is_retryable_source_error, but
504/GatewayTimeout was absent from _RETRYABLE_S3_ERROR_CODES -- which had 500,
502 and 503 but not 504 -- so it hit `raise` on first occurrence. That is why
only 4 UPLOAD_PART_COPY_SEGMENT_RETRY events were logged against 297 x 504.

Reproduced against the real object: 572 UploadPartCopy calls at 8-way
concurrency yielded 1 x 504 (0.17%), latency p50 1.14s / p90 3.31s / max 61.86s.
Latency is heavy-tailed, so a 504 is transient congestion when Hetzner's own
server-side copy exceeds an internal deadline -- not a permanent condition.

botocore does retry 504 (its _retry.json has a gateway_timeout policy) but all
its attempts fire inside the same congestion window and exhaust ("reached max
retries: 3" x297). Retrying here with SOURCE_READ_BACKOFF_SEC exponential
backoff gives the backend time to clear. UploadPartCopy is idempotent for a
given PartNumber+range, so the retry is safe -- the same argument #133 used.

At 0.17% per copy a 4.7GB file (572 copies) has a ~63% chance of hitting a 504,
and 10 nodes doing this concurrently approaches certainty, which is why
main.companies failed on 10 of 13 racks while smaller tables passed.

Also fixes MockS3Response.__aenter__ fidelity: aiobotocore's StreamingBody
returns the wrapped ClientResponse (no size-aware read()), so the mock returning
`self` let an `async with body: body.read(n)` TypeError pass the whole suite
while failing in production. Reintroducing that bug now fails 24 tests.
@ServerSideHannes ServerSideHannes changed the title fix: resume truncated source reads instead of restarting them fix: retry 504 GatewayTimeout and resume truncated source reads Jul 29, 2026
@ServerSideHannes
ServerSideHannes merged commit 1c84dc4 into main Jul 29, 2026
11 checks passed
@ServerSideHannes
ServerSideHannes deleted the fix/source-read-resume branch July 29, 2026 17:01
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.

1 participant