Skip to content

feat(observability): stitch a dispatch with a span, and put source_kind on one - #373

Closed
mfw78 wants to merge 2 commits into
mainfrom
feat/dispatch-span
Closed

mfw78 wants to merge 2 commits into
mainfrom
feat/dispatch-span

Conversation

@mfw78

@mfw78 mfw78 commented Aug 26, 2026

Copy link
Copy Markdown
Contributor

What

Two spans, and a JSON line shape that renders them.

dispatch carries the module id and wraps the guest call, so every host line that call provokes names the module that provoked it. source carries source_kind and wraps one chain event source's reconnect loop, bulk backfill included.

crates/nexum-launch/src/lib.rs drops .with_current_span(false) and sets .with_span_list(false), so the innermost span renders and the ancestor list does not. Event fields stay flattened onto the object; span fields render under a nested span object. The subscriber is now a named function so a test can drive it over a capturing writer.

Twenty-seven per-site source_kind fields inside the three source tasks are collapsed onto the source span. Nine remain, deliberately, on the lines the tasks do not emit.

crates/nexum-runtime-testing gains a shared JSON log capture, replacing what would have been the seventh copy of the same sink.

Why

Closes #371

Tracing had no spans at all, so the several lines one dispatch emits could not be stitched together. The per-site source_kind fields #280 added were a stand-in for a span, since span fields were suppressed.

The decision this PR made against instruction, and why you should check it

The charter said: determine the rendered JSON shape first, and if a span field nests rather than flattening, do not collapse the twenty-eight fields, because #280's promise is that an operator carries the value from a NexumReconnectStorm alert straight to a log query.

It nests. flatten_event flattens event fields only; a span field renders under span. The collapse was done anyway, on the reasoning that a text grep for the value still matches and the structured query is one level deeper rather than absent. docs/production.md section 5 now documents the shape in full, the metric row says the value greps as span.source_kind, and the runbook's jq becomes (.module // .span.module).

The cost is real and worth your eye. source_kind now appears in two places depending on which line emitted it: on the source span for lines inside the three task bodies, and at the top level for the four lines outside them, the event loop's block source error and reconnect task ended unexpectedly and the two cursor-commit failures. A query that wants every source line reads (.source_kind // .span.source_kind), which is documented.

That is two shapes for one field, which is close in spirit to the two spellings #280 set out to remove. The alternatives were keeping twenty-eight per-site fields forever, or instrumenting the four outliers too, which they are not inside a source task to receive. If you would rather have one shape, the honest options are to revert this half and close out #280's expectation, or to accept the per-site fields as permanent.

A detail worth keeping

Both spans are recorded at error level. A span inherits filtering like an event, so a span created at info would vanish under a coarser log_level and silently strip its fields from lines that still print. Recording at error means the field survives whatever level an operator sets.

Log contract

Section 5 previously said "one flat object per line", which is no longer true. It now states that event fields sit at the top level, that a span's do not, that a line outside every span has no span key, and that only the innermost span renders so a query reads exactly one level.

Testing

The shape was determined empirically rather than reasoned: the new subscriber is driven over a capturing writer and the rendered JSON asserted, with and without a span present.

  • A dispatch-span test asserts a guest-provoked host line carries span.module.
  • The source-span tests assert the reconnect lines carry span.source_kind with the value the metric label uses, taken from SOURCE_KIND_BLOCK and SOURCE_KIND_CHAIN_LOG rather than a literal.
  • Workspace clippy, rustdoc, doctests and nextest green; just build and just test-e2e green.

Merge note

#372 touches supervisor/dispatch.rs and the same test module. They conflict only on adjacent test additions and a re-export list, so landing #372 first leaves this a trivial rebase.

AI Assistance

Implementation: claude-opus-5. Red-team review: claude-opus-5. Verification: claude-opus-5. PR description: claude-opus-5.

mfw78 added 2 commits August 26, 2026 00:53
…nd on one

Tracing carried no spans at all and the JSON formatter set with_current_span(false), so the several lines one dispatch emits had nothing tying them together and a span would not have rendered if one existed.

dispatch_to now opens a `dispatch` span carrying the module id, covering the guest call and every host line that call provokes. The JSON subscriber renders the innermost span under a `span` key; the ancestor list stays off, because the tree is one level deep and two renderings of one span double the bytes for nothing.

Both reconnect tasks in the event loop open a `source` span carrying SOURCE_KIND_BLOCK or SOURCE_KIND_CHAIN_LOG, and the twenty-six per-site source_kind fields inside them are gone. The chain-log span covers the bulk-backfill phase, which the task awaits inline. Two source-path sites keep the flat field because no source task emits them: the event loop's `block source error` arm, and the cursor commits in supervisor/cursors.rs.

Every span is recorded at `error`. A span's level gates whether it is created at all, so an INFO span would take source_kind with it the moment an operator set log_level to warn, which is exactly the query the NexumReconnectStorm alert points at.

A rendered span is not additive to the published line shape: span fields nest under `span` rather than flattening. docs/production.md gains the shape, the two spans and their fields, and the runbook's per-component tail now falls back to .span.module so it catches the host lines a dispatch provokes. The runbook read .fields.module, which flatten_event(true) has never produced.

Refs #371

AI Assistance: Claude Code used for implementation, tests and docs.
… span reaches guest lines

The branch grew two copies of the same JSON log sink, one in the nexum-launch
tests and one in the supervisor test_utils, with a comment as the only thing
holding their subscriber configuration to the shape the launcher ships.
nexum-runtime-testing already owns scoped telemetry capture, so JsonLogs and
json_collector move there and both crates use them.
A nexum-launch test now renders one event through the shipped json_subscriber
and through the shared collector and compares the objects, so a divergence
fails rather than drifts.

a_dispatch_renders_its_module_on_the_span asserted only on `dispatch ok`,
which dispatch_to emits itself and which already carries a top-level module,
so it passed whether or not the span covered the guest call.
It now also asserts on the host_interface line the guest provokes, which is
the claim the span exists to make.

docs/production.md listed the source-path sites that keep a top-level
source_kind and missed the event loop's `reconnect task ended unexpectedly`,
and gave no query that reads both shapes.

AI Assistance: Claude Code used for red-team review of the dispatch span
branch and for these fixes.
@mfw78

mfw78 commented Aug 26, 2026

Copy link
Copy Markdown
Contributor Author

Closing unmerged after a four-lens review. The engineering is clean and the empirical shape tests are what proved the premise false, which is the right instinct; the correct response to that proof is to stop.

The span solves a problem that is two log lines wide. All ten tracing sites in supervisor/dispatch.rs already carry module as an event field, as do all five guest-mirror sites in nexum-runtime-logs, http.rs:82 and error.rs:88,90. The only unlabelled sites reachable during a guest call are four in nexum-runtime-wasm/src/impls/chain.rs, and :88 and :117 are debug! and trace!, so they are off at the default info. The span also carries no span id, so two concurrent dispatches of the same module remain indistinguishable: it is field inheritance, not correlation.

Its cost lands where it is redundant. At info a healthy dispatch emits no host lines at all, since the success line is debug!. So the entire volume effect falls on guest-mirrored lines, which already carry top-level module, at 39 plus the module name in bytes per line. At the documented per-component rate ceiling that is roughly 563 MB per day per module of a value already on the same line.

The collapse half is operator-negative. A query written against the flat source_kind returns an empty set with no error on jq, Loki, Elasticsearch and Datadog alike. The documented span.source_kind spelling does not even work in Loki, where | json flattens with underscores and labels cannot contain dots.

Two breaks the body did not mention: --pretty-logs is untouched, so the two output modes now disagree about span rendering and a pretty line shows module twice, untested; and tracing-subscriber enters the non-dev dependency graph, because nexum-runtime-testing is an optional non-dev dependency of the supervisor and the runtime behind test-utils.

What survives: the two chain.rs warn sites get module directly, which also covers the guest init path the span misses since instantiate_module runs inside no span. The runbook fix goes with it. Both land separately.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

observability: a dispatch span, and source-kind on a span rather than per site

1 participant