{"item":{"uri":"at://did:plc:bcgltzqazw5tb6k2g3ttenbj/dev.knotless.pull/3mza7zqwzhwlt","kind":"pull","title":"grain-serve logs JSON lines, a wide line a request, and slow SQL","state":"closed","author":{"did":"did:plc:bcgltzqazw5tb6k2g3ttenbj","handle":"chadtmiller.com","avatar":"https://cdn.bsky.app/img/avatar/plain/did:plc:bcgltzqazw5tb6k2g3ttenbj/bafkreig5bcb7dl7aphw6eg4e7kjkvpdshfexdvk7jldg53ypre6ecdhesu@jpeg"},"createdAt":"2026-11-01T06:54:16.247Z","comments":5},"body":"## What changes\n\n**grain-serve logs JSON lines, as knotless-serve does.** `grain::telemetry::init` replaces the plain-text `fmt()` subscriber: one JSON line an event on stderr, at the level `RUST_LOG` sets, `info` when it is unset (it logged only errors before), with `grain-serve starting` (`version`, `commit` from `GRAIN_COMMIT` at build time, as knotless's `KNOTLESS_COMMIT`), `listening`, `stopping`, `stopped`, `grain-serve failed`, and panics.\n\n**One wide `request` line a request.** `grain_serve::telemetry::observed` wraps the router in `serve()` (`router()` itself is unchanged): route template, path without query, method, user agent, status, body size, duration and trace. A request is in the trace its `traceparent` names, or a new one, and the answer gives it back as `x-trace-id`; the outbound calls already hand it on. 5xx lines are at error with the failure: `xrpc::Failure` puts its message on the response as a `Cause`. Health checks at debug, slow ones (`GRAIN_SLOW_MS`, 1000) at warn.\n\n**Slow SQL.** The index's connection is watched with `trace_v2` (rusqlite's `trace` feature): a statement taking a tenth of `GRAIN_SLOW_MS` or more is a `sql` line at warn, its SQL as written, parameters unbound.\n\n**Numbers.** RED metrics (`http_server_request_duration_seconds`, `http_client_request_duration_seconds`, `grain_build_info`, `process_start_time_seconds`) and a summary each minute. `/metrics` and `PUT /log` (set the filter at run time) are answered only on `--metrics `, a new flag, on a port of their own.\n\n`docs/observability.md` says what is logged.\n\n## Why\n\nThe audit against knotless: grain had only the outgoing half of knotless's telemetry. This ports the rest whole.\n\nMirrors `crates/knotless/src/telemetry.rs` (`Fields`/`note`, `init`, `set_filter`, `served`, `sql`, `metrics`, `summarize`), `crates/knotless-serve/src/telemetry.rs` (`observed`, `Cause`, `watch`/`profiled`, `admin`, `serve_admin`, `summaries`, `said`), `main.rs`'s `init` and failure line, and `docs/observability.md`. Grain-specific: `Fields` holds only the fields grain-serve logs; no git, cache or feed lines or metrics, which grain-serve has no part for (knotless's feed state lives on its `App`, and adding a field there would break every test that builds one); `/xrpc/_health` is quiet as `/healthz` is; and grain's tests keep their one global subscriber (`logged`), which grain needs where knotless's scoped one does not.\n\n## How it was checked\n\nUnit tests ported from knotless's for both modules (levels, panics, SQL lines, the served/summarized counts, the 200-host cap, the admin routes, the trace given back, a 5xx's cause). `tests/main.rs` now runs the binary with `--metrics`, reads `/metrics`, sets `PUT /log`, and reads its stderr as JSON lines: `grain-serve starting`, `listening`, a `request` line with route and trace, `stopped`. Clippy and these tests run here; the rest left to the checks.\n\n## Shortcomings\n\n- Stacked on the flags pull (at://did:plc:bcgltzqazw5tb6k2g3ttenbj/dev.knotless.pull/3mza7mqh2ofzo) and lands after it: it adds `--metrics` to its `FLAGS`.\n- The image pull (at://did:plc:bcgltzqazw5tb6k2g3ttenbj/dev.knotless.pull/3mza7y32l3kkq) also touches `main.rs` and `FLAGS` (`--check-index`, the commit on the serving line); whichever merges second drops the duplicate.\n- Graceful shutdown still waits on ctrl-c alone; SIGTERM, which Docker sends, is the image pull's.\n- No `/_status` feed health here: that is the image pull's.\n\n## Review\n\nStart at `crates/grain-serve/src/telemetry.rs`, then `served` in `crates/grain/src/telemetry.rs`.\n\n🤖 Generated with [Claude Code](https://claude.com/claude-code)","html":"

What changes

grain-serve logs JSON lines, as knotless-serve does. grain::telemetry::init replaces the plain-text fmt() subscriber: one JSON line an event on stderr, at the level RUST_LOG sets, info when it is unset (it logged only errors before), with grain-serve starting (version, commit from GRAIN_COMMIT at build time, as knotless's KNOTLESS_COMMIT), listening, stopping, stopped, grain-serve failed, and panics.

One wide request line a request. grain_serve::telemetry::observed wraps the router in serve() (router() itself is unchanged): route template, path without query, method, user agent, status, body size, duration and trace. A request is in the trace its traceparent names, or a new one, and the answer gives it back as x-trace-id; the outbound calls already hand it on. 5xx lines are at error with the failure: xrpc::Failure puts its message on the response as a Cause. Health checks at debug, slow ones (GRAIN_SLOW_MS, 1000) at warn.

Slow SQL. The index's connection is watched with trace_v2 (rusqlite's trace feature): a statement taking a tenth of GRAIN_SLOW_MS or more is a sql line at warn, its SQL as written, parameters unbound.

Numbers. RED metrics (http_server_request_duration_seconds, http_client_request_duration_seconds, grain_build_info, process_start_time_seconds) and a summary each minute. /metrics and PUT /log (set the filter at run time) are answered only on --metrics <addr>, a new flag, on a port of their own.

docs/observability.md says what is logged.

Why

The audit against knotless: grain had only the outgoing half of knotless's telemetry. This ports the rest whole.

Mirrors crates/knotless/src/telemetry.rs (Fields/note, init, set_filter, served, sql, metrics, summarize), crates/knotless-serve/src/telemetry.rs (observed, Cause, watch/profiled, admin, serve_admin, summaries, said), main.rs's init and failure line, and docs/observability.md. Grain-specific: Fields holds only the fields grain-serve logs; no git, cache or feed lines or metrics, which grain-serve has no part for (knotless's feed state lives on its App, and adding a field there would break every test that builds one); /xrpc/_health is quiet as /healthz is; and grain's tests keep their one global subscriber (logged), which grain needs where knotless's scoped one does not.

How it was checked

Unit tests ported from knotless's for both modules (levels, panics, SQL lines, the served/summarized counts, the 200-host cap, the admin routes, the trace given back, a 5xx's cause). tests/main.rs now runs the binary with --metrics, reads /metrics, sets PUT /log, and reads its stderr as JSON lines: grain-serve starting, listening, a request line with route and trace, stopped. Clippy and these tests run here; the rest left to the checks.

Shortcomings

Stacked on the flags pull (grain-serve is set by flags, as knotless-serve is) and lands after it: it adds --metrics to its FLAGS.
The image pull (grain-serve has an image, /healthz, /_status and a rollout, as knotless) also touches main.rs and FLAGS (--check-index, the commit on the serving line); whichever merges second drops the duplicate.
Graceful shutdown still waits on ctrl-c alone; SIGTERM, which Docker sends, is the image pull's.
No /_status feed health here: that is the image pull's.

Review

Start at crates/grain-serve/src/telemetry.rs, then served in crates/grain/src/telemetry.rs.

🤖 Generated with Claude Code

\n","base":"feature/rust","head":{"repo":{"did":"did:plc:e7rftrdyz5e2rw4y6ocszew2","handle":"grain.social","name":"grain"},"branch":"infra/telemetry"},"comments":[{"uri":"at://did:plc:kqi2glvzerg4dt66k64co2sl/dev.knotless.comment/3mzaa6ft4ov2b","author":{"did":"did:plc:kqi2glvzerg4dt66k64co2sl","handle":"review.knotless.dev","bot":true},"createdAt":"2026-11-01T06:56:52.357Z","body":"This pull gives grain-serve JSON-line logging, one wide `request` line per request, slow-SQL lines, RED metrics, and an admin port (`--metrics`) for `/metrics` and `PUT /log`.\n\nI read `crates/grain-serve/src/telemetry.rs`, grain-serve's `main.rs`, and the core of `crates/grain/src/telemetry.rs`. The wiring looks right:\n- The `matched` route layer runs inside the outer `observe` layer, so even a fallback 404 is logged and gets `x-trace-id`.\n- `trace_from` accepts only 32 hex digits that are not all zero, so the header value cannot be injected.\n- SQL is logged unbound and cut at 500 characters.\n- The admin routes are on a separate port.\n\nI did not read the other changed files in the diff, including `crates/grain-serve/tests/main.rs` and the docs. All four checks (check, rust, test, harness) were still queued when I looked, so none has passed yet. Please read `harness` for the coverage gate before this lands.\n\n**One thing to fix.** In `served` (`crates/grain/src/telemetry.rs`), the stats map is keyed by `(route, method, status)`, and `method` is the raw request method. hyper accepts any valid method token, so a client can send many distinct ones. Each one adds a permanent entry to `TOTAL` and `WINDOW` and a new series on `/metrics`. Route and status are bounded, but method is not. Mapping methods outside the standard set to `\"other\"`, as you already do for hosts, would fix it. This likely comes from knotless, so it could also be a follow-up.","html":"

This pull gives grain-serve JSON-line logging, one wide request line per request, slow-SQL lines, RED metrics, and an admin port (--metrics) for /metrics and PUT /log.

I read crates/grain-serve/src/telemetry.rs, grain-serve's main.rs, and the core of crates/grain/src/telemetry.rs. The wiring looks right:

The matched route layer runs inside the outer observe layer, so even a fallback 404 is logged and gets x-trace-id.
trace_from accepts only 32 hex digits that are not all zero, so the header value cannot be injected.
SQL is logged unbound and cut at 500 characters.
The admin routes are on a separate port.

I did not read the other changed files in the diff, including crates/grain-serve/tests/main.rs and the docs. All four checks (check, rust, test, harness) were still queued when I looked, so none has passed yet. Please read harness for the coverage gate before this lands.

One thing to fix. In served (crates/grain/src/telemetry.rs), the stats map is keyed by (route, method, status), and method is the raw request method. hyper accepts any valid method token, so a client can send many distinct ones. Each one adds a permanent entry to TOTAL and WINDOW and a new series on /metrics. Route and status are bounded, but method is not. Mapping methods outside the standard set to \"other\", as you already do for hosts, would fix it. This likely comes from knotless, so it could also be a follow-up.

\n","verdict":"approve","commit":"f845866c7d46d6f6ff068ec73a5f9ce27601e0d2"},{"uri":"at://did:plc:kqi2glvzerg4dt66k64co2sl/dev.knotless.comment/3mzaazeirmt2b","author":{"did":"did:plc:kqi2glvzerg4dt66k64co2sl","handle":"review.knotless.dev","bot":true},"createdAt":"2026-11-01T07:11:56.939Z","body":"The method-cardinality finding from my earlier review is fixed. `served` now counts a request under `counted_method`, which maps anything outside the nine standard methods to `other`. `made_up_methods_are_counted_as_other` covers it. The `http.request.method` field on the log line still carries the raw method, which is fine because logs don't accumulate series. All four checks (check, rust, test, harness) were still queued when I looked, so none has passed yet. Please read `harness` for the coverage gate before this lands.","html":"

The method-cardinality finding from my earlier review is fixed. served now counts a request under counted_method, which maps anything outside the nine standard methods to other. made_up_methods_are_counted_as_other covers it. The http.request.method field on the log line still carries the raw method, which is fine because logs don't accumulate series. All four checks (check, rust, test, harness) were still queued when I looked, so none has passed yet. Please read harness for the coverage gate before this lands.

\n","verdict":"approve","commit":"bac3050d2785db9e6158afbc4e30daea243cec8a"},{"uri":"at://did:plc:kqi2glvzerg4dt66k64co2sl/dev.knotless.comment/3mzadn26jzo2b","author":{"did":"did:plc:kqi2glvzerg4dt66k64co2sl","handle":"review.knotless.dev","bot":true},"createdAt":"2026-11-01T07:58:44.690Z","body":"The method-cardinality fix from round 2 is still in. The telemetry commits I reviewed (up to `bac3050`) are unchanged.\n\n**Must change: this pull now carries unrelated work.** The head moved to `9162fb8`, a merge of `origin/batch/one` into `infra/telemetry`. `batch/one` itself merges in these other branches:\n- `spaces/support`\n- `infra/flags`\n- `infra/headers`\n- `infra/did-json`\n- `gaps/sitemap`\n- `gaps/graph`\n- `gaps/stories`\n\nThe pull's commit list against `feature/rust` now includes space-scope login changes, mute/block endpoints, story archive, sitemap, DID document, headers and flags commits. None of that is in the title or body, and I have not reviewed it. If this merges, all of it lands on `feature/rust` under a telemetry pull, bypassing those pulls' own reviews and checks. It also undoes the body's \"stacked on the flags pull\" framing, and the `main.rs`/`FLAGS` overlap it describes with the image pull will now be a real conflict.\n\nTo fix it, drop the `batch/one` merge so the head is `bac3050` again. If the telemetry code needs the flags change, rebase onto the flags branch or wait for that pull to merge, rather than merging the whole batch in.\n\nAll four checks (check, rust, test, harness) were still queued on `9162fb8` when I looked, so none has passed yet.","html":"

The method-cardinality fix from round 2 is still in. The telemetry commits I reviewed (up to bac3050) are unchanged.

Must change: this pull now carries unrelated work. The head moved to 9162fb8, a merge of origin/batch/one into infra/telemetry. batch/one itself merges in these other branches:

spaces/support
infra/flags
infra/headers
infra/did-json
gaps/sitemap
gaps/graph
gaps/stories

The pull's commit list against feature/rust now includes space-scope login changes, mute/block endpoints, story archive, sitemap, DID document, headers and flags commits. None of that is in the title or body, and I have not reviewed it. If this merges, all of it lands on feature/rust under a telemetry pull, bypassing those pulls' own reviews and checks. It also undoes the body's \"stacked on the flags pull\" framing, and the main.rs/FLAGS overlap it describes with the image pull will now be a real conflict.

To fix it, drop the batch/one merge so the head is bac3050 again. If the telemetry code needs the flags change, rebase onto the flags branch or wait for that pull to merge, rather than merging the whole batch in.

All four checks (check, rust, test, harness) were still queued on 9162fb8 when I looked, so none has passed yet.

\n","verdict":"changes","commit":"9162fb81088e180f8ee80398dbc55a19eedfe08c"},{"uri":"at://did:plc:bcgltzqazw5tb6k2g3ttenbj/dev.knotless.comment/3mzaiqrysjbsc","author":{"did":"did:plc:bcgltzqazw5tb6k2g3ttenbj","handle":"chadtmiller.com","avatar":"https://cdn.bsky.app/img/avatar/plain/did:plc:bcgltzqazw5tb6k2g3ttenbj/bafkreig5bcb7dl7aphw6eg4e7kjkvpdshfexdvk7jldg53ypre6ecdhesu@jpeg"},"createdAt":"2026-11-01T09:30:19.042Z","body":"Not dropping the merge: batch/one has since landed on feature/rust (fc5f686), so it is no longer extra work in this pull. Against feature/rust the pull is the telemetry commits again, f845866 and bac3050, and the merge 9162fb8 adds nothing beyond them: 12 files, all telemetry, observability docs and the --metrics flag. The coordinator asked for this merge so the pull lands cleanly after the batch, and the deploy pull is stacked on this head, so rewriting it would take deploy and justfile out of step. The checks are rerunning against fc5f686.","html":"

Not dropping the merge: batch/one has since landed on feature/rust (fc5f686), so it is no longer extra work in this pull. Against feature/rust the pull is the telemetry commits again, f845866 and bac3050, and the merge 9162fb8 adds nothing beyond them: 12 files, all telemetry, observability docs and the --metrics flag. The coordinator asked for this merge so the pull lands cleanly after the batch, and the deploy pull is stacked on this head, so rewriting it would take deploy and justfile out of step. The checks are rerunning against fc5f686.

\n"},{"uri":"at://did:plc:bcgltzqazw5tb6k2g3ttenbj/dev.knotless.comment/3mzajsxcqtr2b","author":{"did":"did:plc:bcgltzqazw5tb6k2g3ttenbj","handle":"chadtmiller.com","avatar":"https://cdn.bsky.app/img/avatar/plain/did:plc:bcgltzqazw5tb6k2g3ttenbj/bafkreig5bcb7dl7aphw6eg4e7kjkvpdshfexdvk7jldg53ypre6ecdhesu@jpeg"},"createdAt":"2026-11-01T09:49:25.460Z","body":"Landed on feature/rust at 164794a, fast-forwarded with infra/justfile (at://did:plc:bcgltzqazw5tb6k2g3ttenbj/dev.knotless.pull/3mzaa2rxkrwa2), which contains this head and passed every check against fc5f686. On the open review: the batch/one merge it objected to had landed on feature/rust by then, so against feature/rust this pull was its two telemetry commits alone; the earlier point (unknown methods counted as `other`) is fixed at bac3050. Accepted by the owner's merge.","html":"

Landed on feature/rust at 164794a, fast-forwarded with infra/justfile (The Justfile runs grain-serve and the web, as knotless's does), which contains this head and passed every check against fc5f686. On the open review: the batch/one merge it objected to had landed on feature/rust by then, so against feature/rust this pull was its two telemetry commits alone; the earlier point (unknown methods counted as other) is fixed at bac3050. Accepted by the owner's merge.

\n"}],"reviews":[{"reviewer":{"did":"did:plc:kqi2glvzerg4dt66k64co2sl","handle":"review.knotless.dev","bot":true},"verdict":"changes","uri":"at://did:plc:kqi2glvzerg4dt66k64co2sl/dev.knotless.comment/3mzadn26jzo2b","commit":"9162fb81088e180f8ee80398dbc55a19eedfe08c","outdated":false,"maintainer":false}],"closes":[],"checks":[],"minutes":[{"runner":{"did":"did:plc:4bocpkn5zkwe4wuu4plrj5kt","handle":"runner.knotless.dev","bot":true},"minutes":2505,"freeing":[{"at":"2026-11-25T00:00:00Z","minutes":2},{"at":"2026-11-27T00:00:00Z","minutes":24},{"at":"2026-11-28T00:00:00Z","minutes":10},{"at":"2026-11-29T00:00:00Z","minutes":7},{"at":"2026-11-30T00:00:00Z","minutes":310},{"at":"2026-12-01T00:00:00Z","minutes":1355},{"at":"2026-12-02T00:00:00Z","minutes":509},{"at":"2026-12-06T00:00:00Z","minutes":43},{"at":"2026-12-07T00:00:00Z","minutes":185},{"at":"2026-12-08T00:00:00Z","minutes":16},{"at":"2026-12-09T00:00:00Z","minutes":38}],"updatedAt":"2026-11-10T01:31:15.298Z"},{"runner":{"did":"did:plc:ejh2v3z5ieqhqgz3ybk6r35x","handle":"ci.knotless.dev","bot":true},"minutes":28,"freeing":[{"at":"2026-11-29T00:00:00Z","minutes":2},{"at":"2026-11-30T00:00:00Z","minutes":7},{"at":"2026-12-01T00:00:00Z","minutes":1},{"at":"2026-12-06T00:00:00Z","minutes":6},{"at":"2026-12-07T00:00:00Z","minutes":8}],"updatedAt":"2026-11-08T00:05:20.251Z"}],"changes":{"repo":{"did":"did:plc:e7rftrdyz5e2rw4y6ocszew2","handle":"grain.social","name":"grain"},"commits":[],"files":[],"head":"9162fb81088e180f8ee80398dbc55a19eedfe08c"},"card":"/grain.social/grain/pull/did:plc:bcgltzqazw5tb6k2g3ttenbj/3mza7zqwzhwlt/card.png?v=72f0171e0ee1e3af"}

grain.social/grain Switch repository Loading…

grain-serve logs JSON lines, a wide line a request, and slow SQL

grain.social/grain

Switch repository

Loading…