Cache restore hangs forever when parts are large (64MiB) — merge abort deadlocks pumpPartsToStreams, client sees "Premature close"

[SpectralAngel]

Been running this in my homelab for a couple of days (single node k8s, Garage for S3, postgres for metadata) and my NuGet cache restores never work. Smaller caches are fine. Took me a while to pin down so figured I'd write it up.

Symptom, every single run, same key:

Cache hit for: nuget-Linux-c0767851...
Warning: Failed to restore: Premature close
Cache not found for input keys: nuget-Linux-c0767851..., nuget-Linux-

That cache has never restored once, not one time in two days. It saves fine, it just can't be read back.

Setup: 9.6.0, STORAGE_DRIVER=s3 pointed at Garage (path style), DB_DRIVER=postgres, ENABLE_DIRECT_DOWNLOADS=true, CACHE_MAX_SIZE_BYTES 50GiB but only ~11GB used so eviction isn't running, STORAGE_S3_SOCKET_TIMEOUT_MS unset so 10000. Runners are ARC using your actions-runner fork with CUSTOM_ACTIONS_RESULTS_URL.

Cut actions/cache out of it and just curl the download endpoint:

curl -sS --max-time 90 -o /dev/null -w 'bytes=%{size_download} t=%{time_total} code=%{http_code}\n'
http://gha-cache-server:3000/download/

curl: (28) Operation timed out after 90000 milliseconds with 67108864 bytes received
bytes=67108864 t=90.002414 code=200

67108864 is exactly 64MiB, which is exactly part 0 of that entry (884332399 bytes over 14 parts, so 13x64MiB plus a small one). It sends part 0 and then just stops. 200, headers sent, body stalls. curl exits 28 (timeout) and not 18, so the connection is still open and idle, nothing got reset. It'll sit like that forever.

The thing that made it click: it depends on how big the parts are, not how many. actions/cache uploads in 64MiB chunks and it's broken. BuildKit type=gha uploads ~1MiB chunks and it's completely fine. I tested an unmerged entry with 37 parts of ~1MiB (37880506 bytes) and it downloads in full in 2.9s and merges fine. So 37 part boundaries are no problem, but the first 64MiB one kills it.

Garage side for one failing restore:

01:17:55.758 GET /gha-cache/?list-type=2&prefix=gh-actions-cache/2007184102/parts/
01:17:55.773 GET /gha-cache/gh-actions-cache/2007184102/parts/0
01:17:55.995 POST .../merged CreateMultipartUpload
01:17:56.028 PUT .../merged?partNumber=1... 200
... 12 x UploadPart, all 200 ...
01:17:57.649 PUT .../merged?partNumber=12... 200
01:17:57.750 DELETE .../merged?uploadId=... AbortMultipartUpload

So the merge upload gets aborted 100ms after a PUT that succeeded, right where it would move from part 0 to part 1. GET parts/1 never happens at all. Garage 200s everything and logs no errors, it's serving that 64MiB part at ~32MB/s, so I don't think storage is the problem. Server logs are completely silent during this, nothing.

18 aborts over 48h, same folders over and over. Merges that don't involve big parts work fine, 126 CompleteMultipartUpload in that same window.

Two things I already ruled out so you don't have to:

• ENABLE_DIRECT_DOWNLOADS isn't involved. storage.ts:690 only signs merged entries and every affected one is unmerged. I also saw this before I turned that on.
• Not the socket timeout. The abort is 100ms after a successful PUT, well under the 10s default (and under the 3s 9.4.7 hardcoded).

[LouisHaftmann]

Please try the latest dev image and report back if it's still a problem 🙏

[eplightning]

For garage specifically you might need to set those two environment variables:

AWS_REQUEST_CHECKSUM_CALCULATION: WHEN_REQUIRED
AWS_RESPONSE_CHECKSUM_VALIDATION: WHEN_REQUIRED

AWS SDK introduced some breaking changes last year which didn't play well with S3 alternatives. Using these env vars to override SDK behavior worked for me at least.

The exception that would help debugging this is unfortunately not being logged currently.

[SpectralAngel]

Thanks for taking a look at this, and for the quick turnaround — sorry for the wall of text.

Your race fix looks right to me, for what it's worth. The old sequential once(..., 'drain') really can lose the merger's drain event and hang when both streams backpressure at once, so that's a real one. It just wasn't what I was hitting — but turning on DEBUG=true on your dev build is actually what showed me the real problem, so testing it was far from wasted. It's a separate checksum thing with Garage.

The error that 9.6.0 was hiding:

Client aborted /download/70e9a037-...: Checksum mismatch: expected "E/fSkA==" but received "rpsxqw==" in response header "x-amz-checksum-crc32"

Nothing had actually aborted — that's the SDK throwing. Since uploadStream uploads in 5MB parts, my bigger cache entries get stored as multipart objects, and Garage returns the composite crc32 without the -N suffix that real S3 uses to mark it as composite. The SDK (^3.1085, validation on by default) reads it as a whole-object checksum, recomputes over the body, and throws at end of stream. head-object confirms it — ETag ends in -13 and the CRC32 is exactly the "expected" value from the error. It also explains why my Docker layer cache was always fine: those parts are under 5MB, so they go up as plain PutObjects with a real whole-object checksum. It's the 5MB line, not part count.

AWS_RESPONSE_CHECKSUM_VALIDATION=when_required fixed it completely, no patch. My 884MB nuget cache restored for the first time ever, merged fine, and the second restore came straight off the presigned URL. All on plain 9.6.0.

So nothing you need to change for my case — that was config on my end. But a couple of small things made it much harder to find than it needed to be, if you're interested:

The checksum error gets logged as "Client aborted" at debug and swallowed, which threw me for ages because nothing had aborted — and since the response never ends, the client just hangs instead of erroring, which is where the "Premature close" comes from. And the merge catch in storage.ts doesn't keep the error and resets mergedAt to null, so a broken entry keeps retrying the same failing path forever. If either one had printed the actual error I'd have found it in five minutes instead of two evenings.

Also worth flagging for me personally: now that the checksum thing is sorted, my large restores actually stream through the pumpPartsToStreams path with real backpressure — which is exactly the case your race fix covers. So I'll want that once it's in a release. I'm back on 9.6.0 for now.

One correction on my original report, too: I confidently blamed a stream deadlock and said the trigger was unknown. That was wrong — it was the checksum all along, and the info to find it existed the whole time, nothing just printed it. Sorry for sending you down the wrong path there.