~ knotless Search/
↑↓ move↵ open⇧↵ all results

chadtmiller.com/knotless

git that lives in your Atmosphere account

knotless.dev
1 collaborator

knotless 0.13.0 Latest 2 packages, 1 image

1
10

XRPC failures log their cause, and a query whose connection broke is asked again

Merged
Merged chadtmiller.com asked to merge into main from chadtmiller.com/knotless:serve/failure-causes

Every 5xx from an /xrpc/ method has been logged without its cause, so the 140 pushRefs 500s of Nov 5 can't be explained from the logs; this puts the cause back on the line. It also asks a PDS query once more when its connection broke before an answer, which turned today's one pushRefs 500 into a failed push. A quick look will do: start at xrpc_failures in web.rs.

Claude Opus 5.5 · high

What changes

A failed XRPC request's log line says why again. web::xrpc_failures turns a plain-text failure under /xrpc/ into XRPC's JSON, and rebuilt the response from its status alone, dropping its extensions, among them the Cause that telemetry::observe puts on the request line as error. It now carries them over. So every AppError answered under /xrpc/ (pushRefs, createCommit, the org methods, most queries) has logged its 5xx at error with no error field; now it has one, as docs/observability.md already said.

An XRPC query whose connection broke is asked again, once. Xrpc::send sends a GET again when the call failed after its connection was made and before any answer (is_request, not is_connect or is_timeout), as when a kept-open connection had been closed by the server. A procedure is not sent again, since it may have been done. The second call's outgoing line has http.request.resend_count = 1; a DPoP nonce retry after it counts 2.

Why

Prod's admin_stats over 14 days: pushRefs answered 140 of 589 calls with 500, almost all from one knotless/0.11.0 client retrying about every 45 s from 18:51 to 22:45 on Nov 5. None of those request lines carries an error, though other 5xx lines do (the ones a handler answered as JSON itself, which skip this middleware). That is how the cause was lost.

Today's one pushRefs 500 (trace aad97b02001d15cc0fdf72175bf60782, 18:20) followed a com.atproto.repo.getRecord to pds.chad-53c.workers.dev that failed after 21 ms with connection reset: a pooled connection the PDS had dropped. A read is safe to repeat, so a broken one is retried at the one place every XRPC call goes through, not in each caller.

How it was checked

  • web::tests::xrpc_failures_keep_their_cause: a route failing with AppError::internal under xrpc_failures answers InternalServerError JSON, and the Cause a layer outside it reads equals the message.
  • library::broken_connections: against a server that closes the first connection once the request is read, a query succeeds on its resend, and a procedure fails rather than being sent again.
  • library::dpop_nonces: a query whose connection broke, then refused with use_dpop_nonce, is sent a third time carrying the nonce the server named, and answered. The first push's coverage gate missed the nonce resend line: no test hits it on purpose, so it seems to have been reached only when a test PDS's nonce changed mid-run.

All three are left to CI; nothing was built here.

Shortcomings

A query whose connection breaks twice in a row still fails. Connect failures and timeouts are not retried. Blob reads (get_blob) go around send and are not retried either.

Approved

I read every changed file and the code around both changes, and found nothing that must change.

  • xrpc_failures: the rebuilt response now takes parts.extensions, so the Cause reaches telemetry::observe again. The status is rebuilt from the same parts, so nothing else changes.
  • Xrpc::send: the retry is limited to GET and to is_request() && !is_connect() && !is_timeout(), so procedures are never resent. The DPoP nonce retry now uses resent + 1, which keeps resend_count right when both retries happen.
  • Tests and docs: both new tests cover the behaviour the body describes. The changeset and docs/observability.md match the code.

I did not run the tests, and the body says nothing was built. Check CI for xrpc_failures_keep_their_cause. It assumes the Cause string equals the body's message, which holds only if AppError::internal writes its cause as the response text.

Approved

I read the diff, including what changed since my approval at 701cc9e. The xrpc_failures change and the Xrpc::send change are the same as before. The only addition is the dpop_nonces test, plus a changeset note. That test drops the first connection and then gets a nonce refusal, so it covers a resend followed by a nonce retry, which is the resend_count 2 case. The server answers {"ok": true} only when the DPoP proof's nonce claim is fresh, so the test passes only if both retries happen. Nothing I approved is broken. I did not run the tests. CI should show them.

Merged as 246dab7