fix: retry message-less 400 on UploadPart - #147
Merged
Conversation
Hetzner sheds load under concurrency by returning a bare 400 with an empty body, which botocore surfaces as InvalidArgument with Message=None. #144 made GatewayTimeout retryable but not this variant, so it hit `raise` on first sight and failed the whole multi-GB part -- and through rclone's job error, the whole Scylla backup run. All 4 occurrences captured on main.companies had Message=None, on legal 50MiB non-final parts (part 2-16, never part 1). A real InvalidArgument always names the offending argument, so the message-less form is congestion, not a malformed request. Reproduced: 24 x 50MiB parts at 16-way concurrency yielded 1 failure, surfaced as GatewayTimeout("The server did not respond in time") -- the same congestion event, with a body Hetzner managed to write. Latency degrades from p50 1.79s unloaded to p50 13.09s / max 52.32s under concurrency. Also adds two events the retry loop was missing: UPLOAD_PART_RECOVERED a part that only landed after N attempts, previously a silent success that hid how close a run ran to the edge UPLOAD_PART_GAVE_UP carries attempts/max_attempts/classified_retryable/ exhausted, so "gave up after N transient failures" is distinguishable from "rejected outright" -- they were identical in UPLOAD_PART_CLIENT_ERROR, which made every past investigation guess between the two
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
Scylla backup runs keep failing on
main.companieswith:#143 added UploadPart retry and #144 made
GatewayTimeout/504 retryable, but this variant still failed on first sight — one bad part out of thousands aborts the file, and through rclone's job error, the entire run. Observed 4x during a single run, on two of 13 racks.Root cause
Hetzner sheds load under concurrency by returning a bare 400 with an empty body, which botocore surfaces as
InvalidArgumentwithMessage=None.All 4 captured occurrences had
Message=None, on legal 50 MiB non-final parts (parts 2–16, never part 1):{"event": "UPLOAD_PART_CLIENT_ERROR", "part_num": 16, "content_length": 52428800, "aws_error_code": "InvalidArgument", "aws_error_message": null, "http_status": 400}A real
InvalidArgumentalways names the offending argument (ArgumentName/ArgumentValue). The message-less form is congestion, not a malformed request.Reproduced: 24 × 50 MiB parts at 16-way concurrency against the production backend yielded 1 failure — surfaced as
GatewayTimeout: "The server did not respond in time."Same congestion event, except Hetzner managed to write a body that time. Latency confirms the mechanism:A 7× latency degradation under load, with a heavy tail — so the backend starts dropping requests at the tail.
Fix
Treat a 400 with no message as retryable, alongside the existing transient set:
Deliberately narrow: a genuine
InvalidArgumentwith a reason still fails immediately, so a truly malformed request can't retry forever.Observability
The retry loop logged retries but nothing on the terminal outcome, so
UPLOAD_PART_CLIENT_ERRORlooked identical whether the part was rejected outright or gave up after 4 transient failures. That ambiguity has misdirected every previous investigation into this class of failure.UPLOAD_PART_RECOVERED— part landed after N attempts (previously a silent success that hid how close a run ran to the edge)UPLOAD_PART_GAVE_UP—attempts,max_attempts,classified_retryable,exhausted,part_size,elapsed_sec, AWS code/messageUPLOAD_PART_RETRYalso gainspart_size,aws_error_code,max_attempts.Testing
638 passed— 12 new tests covering the message-less 400 (retried), a realInvalidArgumentwith a reason (not retried), permanent errors, and both new log events.Note: the log assertions target the logger directly rather than captured stdout — asserting on
capsyspassed in isolation but failed in the full suite, since another test reconfigures structlog.Scope
This fixes one confirmed failure mode. Separately still open:
ContentLengthErrortruncated reads continue at ~5–30/min (handled byread_source_bytesresume from fix: retry 504 GatewayTimeout and resume truncated source reads #144, but the underlying congestion remains)worker_upload.go:213retries onlyerrJobNotFound), so any error escaping the proxy still costs a whole host's uploadaws_error_message: nullon a legal 50 MiB part is arguably a Hetzner bug worth reporting upstream