johnandersen777.bsky.social/knotless

Switch repository

Loading…

# Observability

What knotless-serve and knotless-run record of what they do, how, and
why that, for one host running a few containers with one operator. How
to read it is in [deploy/README.md](../deploy/README.md#logs).

## What there is

- **Logs**: JSON lines on stderr, through `tracing` and
  `tracing-subscriber`, one an event, at the level `RUST_LOG` sets
  (`info`). Docker writes them to the host's journal, which keeps them
  after a rollout removes their container, for 30 days, as the privacy
  policy says; jq reads them (`just logs`).
- **One wide line a request**: a `request` line when each request ends,
  with its route, path, query, status, size, duration and trace, as Stripe's
  canonical log lines are [1]: a question about traffic is a jq filter
  over one kind of line, not a join across many. Slow ones (over
  `KNOTLESS_SLOW_MS`, 1000) are at warn, but for long polls, which wait
  on purpose; 5xx at error with the cause. The query (`url.query`) is
  there so a slow page can be told apart by what it asked for, as a filter
  or a cursor: each value of a parameter a secret could be in (`code`,
  `state`, `iss`, `token`, `access_token`, `refresh_token`, `password`,
  `secret`, `key`) is replaced by `_`, the whole cut to 200 characters,
  and a request under `/oauth` logs none.
- **A line for each MCP tool call**: `mcp tool`, with the tool's name
  (`gen_ai.tool.name`), the caller's DID and `duration_ms`, at info, or
  at warn when slow and not asked to wait; `mcp tool failed`, at warn,
  with why. The MCP server calls each tool in a task of its own, so the
  request's trace is handed to it: the call's line, and its calls and
  slow statements, are in the trace of the `/mcp` request that made it. A
  resource read logs the same as `mcp resource` and `mcp resource
  failed`, named for the tool that answers it.
- **A line for each sync of a mirror**: `mirror sync`, with the
  repository, `duration_ms` and `records_ms`, the part of it spent reading
  the repository's records. At info, or at warn when slow. Each read of a
  repository waits for a sync it finds under way, so a burst of slow
  requests for one repository that all end together is explained by the
  sync before it. A sync started by a write the feed brought is in no
  request's trace.
- **A line for each call made**, to a PDS, the PLC directory, Bluesky or
  a handle's host, from the one place every call goes through
  (`knotless::telemetry::send`): host, path, XRPC method, status, error,
  resend count, duration. At debug, so a busy minute does not drown the
  log; failed and slow ones at warn. An XRPC query whose connection broke
  before it was answered, as one kept open that the server had closed
  does, is sent again once, its line with a resend count of 1; a
  procedure, which may have been done, is not.
- **A line for each slow SQL statement**: one of the index's that took
  a tenth of `KNOTLESS_SLOW_MS` (100 ms) or more, at warn, with its SQL
  as written (`db.query.text`, its parameters unbound, so no value it
  was given) and `duration_ms`, in the trace of the request it ran in. A
  slow request's line says how slow it was; these say which query made it.
- **Traces in every line**: each request is in a trace, the one its W3C
  `traceparent` names [2] or a new one; every line logged while it is
  served carries its `trace_id`, every call it makes sends `traceparent`,
  and the answer gives it back as `x-trace-id`. serve hands the trace to
  the pages, and the pages' SvelteKit hook hands it back on their
  XRPC calls, so a page and the data it drew share one trace.
- **Field names from OpenTelemetry's semantic conventions** [3]:
  `http.route`, `http.request.method`, `url.path`, `url.query`, `user_agent.original`,
  `http.response.status_code`, `server.address`, `error.type`,
  `http.request.resend_count`, `rpc.method`. A collector can take the
  lines as they are, and a backend's HTTP views know them.
- **RED metrics** [4] at `/metrics`, in Prometheus's text format:
  `http_server_request_duration_seconds` (rate, errors by status, and
  duration, by route) and `http_client_request_duration_seconds` (by host
  and outcome), OpenTelemetry's metric names [5]; cache lookups by result, and how long a
  miss took to make good (`knotless_cache_build_duration_seconds`, by cache and `how`: patched
  from what was kept, or rebuilt in full);
  each feed's connection, events and lag. Counted in a few maps under a
  mutex: no exporter, no allocation per request beyond the line.
- **A summary each minute**: requests, calls by host, each cache's hits,
  misses and failed fills (and, for a miss made good, how many and how long
  by `how`), and each feed's lag, as log lines, so a jq over
  the log answers "what was it doing at 14:02" without a metrics store.
- **The level changed at run time**: `PUT /log` with a `RUST_LOG`
  directive (`info,knotless::outgoing=debug`), through
  `tracing-subscriber`'s reload layer, to see every call during an
  incident without a restart, which would end it.
- **Deploys with times**: deploy.sh and rollout.sh write each step to
  `/var/log/knotless-deploy.log` on the host.

`/metrics` and `/log` are on `--metrics`' port, which compose binds to
the container's own loopback (`127.0.0.1:9464`): nothing outside the
container reaches it, the proxy included; `docker exec` does.

## What was left out, and why

- **The OpenTelemetry SDK and OTLP export** (`opentelemetry`,
  `tracing-opentelemetry`, `opentelemetry-otlp` [6]). They pay off with a
  backend to send to, and there is none: the SDK adds its batching
  exporter, a few crates more to build, and versions that move in step
  (0.3x, each minor breaking). The ids and names here are W3C's and
  OpenTelemetry's, so adding the layer later changes no line's meaning.
- **Spans for each call inside a request.** A trace id on every line,
  and a line a call, give the part of a trace one reads by hand; a
  waterfall needs a trace store.
- **Sampling.** At knotless.dev's traffic every request's line costs
  less than deciding which to keep; the calls, the bulk, are at debug.
  With a backend, keep every error and slow request and sample the rest
  at the collector (tail sampling), not here.
- **A log store.** jq over the journal answers what one operator asks
  of one host, and costs nothing running. For an operator, or an agent,
  without SSH, serve keeps its own lines in a SQLite file too (`--logs`),
  written by every serve running so that deploys lose none, and read
  through an operator-only query, `dev.knotless.getLogs`: one request by
  its trace, or the last of a message, a level or a duration. It is the
  journal's lines, held as long, not a store to search over weeks: it
  keeps the last 500,000 at info and below, and has no full-text search.

## The next step: a backend

When grepping stops being enough (a freeze that has to be caught as it
happens, or a question over weeks), run one store beside the site, and
keep everything above as it is:

- **VictoriaLogs and VictoriaMetrics** (proposed): each one static binary
  with its own disk, VictoriaLogs taking the JSON lines as they are
  (fields kept, every one searchable, no labels to choose), and
  VictoriaMetrics scraping `/metrics`. Its makers say it needs far less
  RAM than Loki [7]; one team's numbers were 0.8 GB against Loki's 6 to 7
  GB [8], at hundreds of GB a week, far beyond ours. Here: about 100 to
  300 MB of RAM each and well under one core, with a `mem_limit` of
  512 MB each and `cpus: 0.5`, and a few GB of disk for a month at
  `-retentionPeriod=30d`. Grafana in front (another 100 to 200 MB) for
  dashboards, or VictoriaLogs' own UI to search.
- **Grafana's stack** (Alloy, Loki, Tempo, Prometheus or Mimir) does the
  same with more pieces: Loki indexes only labels, so the fields here
  would be parsed again at query time, and Tempo wants object storage.
  Each piece is a few hundred MB; together 1 to 2 GB, more than the host
  should give up beside its other apps.
- **A hosted free tier**, through an OpenTelemetry collector or Alloy on
  the host (about 100 MB) shipping to Grafana Cloud or Honeycomb, keeps
  nothing on the host but the shipper; the free tiers' limits, tens of
  GB a month kept a couple of weeks, are well above our volume. Logs then leave the host, which is a choice to make on purpose.

Either way the change is in compose and the shipper's config: the lines
and `/metrics` are already what they read.

## Sources

1. Stripe, [Fast and flexible observability with canonical log lines](https://stripe.com/blog/canonical-log-lines).
2. W3C, [Trace Context](https://www.w3.org/TR/trace-context/).
3. OpenTelemetry, [Semantic conventions for HTTP spans](https://opentelemetry.io/docs/specs/semconv/http/http-spans/), and their [migration to stable names](https://opentelemetry.io/docs/specs/semconv/http/migration-guide/).
4. Tom Wilkie, [The RED method](https://grafana.com/blog/2018/08/02/the-red-method-how-to-instrument-your-services/).
5. OpenTelemetry, [Semantic conventions for HTTP metrics](https://opentelemetry.io/docs/specs/semconv/http/http-metrics/).
6. [tracing-opentelemetry](https://docs.rs/tracing-opentelemetry), and how it pairs with a JSON layer: [tokio-rs/tracing#1531](https://github.com/tokio-rs/tracing/issues/1531).
7. VictoriaMetrics, [VictoriaLogs](https://docs.victoriametrics.com/victorialogs/).
8. TrueFoundry, [VictoriaLogs vs Loki](https://www.truefoundry.com/blog/victorialogs-vs-loki).