feat(tracing): propagate log topic across spawns and label components

[varex83agent]

Summary

MetricsLayer labels app_log_warn_total / app_log_error_total with a topic taken from the nearest enclosing span, falling back to "". Because tracing span context does not cross tokio::spawn, and pluto set the topic field in only two places (health, stacksnipe), effectively every other warn/error landed under topic="".

This PR restores charon-like topic attribution.

1. Every long-running component opens its own topic span at its entry point — a &'static str so the label stays bounded — reusing charon's names. Because the span is opened by the task itself, it works regardless of who spawned it.

2. Subtasks re-attach their caller's span. tokio::spawn, JoinSet::spawn and spawn_blocking all start with an empty span stack, so a subtask that has no topic of its own wraps its future in .instrument(Span::current()), inline and commented at each site. This is what charon gets for free by passing context.Context into a goroutine.

3. Background tasks default to app-start. The node's lifecycle JoinSet opens an app-start span per task via a local background() helper, mirroring charon's lifecycle.Manager, which hands every background hook a log.WithTopic(context.Background(), "app-start") context (app/lifecycle/hook.go). A task with a more specific topic shadows it, exactly as a nested log.WithTopic does in Go.

Topics / components covered

topic	pluto site
sched	core/scheduler.rs actor run, both subscriber loops, per-event callback spawns, duty-broadcast delay, slot ticker
tracker	core/tracker/mod.rs actor run, core/tracker/inclusion.rs run
sigagg	core/sigagg.rs aggregate
bcast	core/bcast/mod.rs broadcast, core/bcast/recast.rs slot_ticked
parsigex	parsigex/behaviour.rs enqueue + notify_subscribers spawn
vapi	core/validatorapi/router.rs per-request middleware
qbft	consensus/qbft/runner.rs propose/participate/run_instance + the instance JoinSet and blocking core, component.rs cleanup spawn
p2p	p2p/p2p.rs handle_event
relay	cli/commands/relay.rs run, p2p/bootnode.rs relay-resolver spawn, relay-server/web.rs resolver spawn
peerinfo	peerinfo/protocol.rs send_peer_info / recv_peer_info
dkg	dkg/dkg.rs run (+ network-driver spawn)
vmock	testutil/validatormock/component.rs slot_ticked / run_scheduler + duty JoinSet
app-start	app/node/mod.rs run and its lifecycle JoinSet, readiness checker, priority consensus spawn, dutydb store callback

Pre-existing health and stacksnipe topics are unchanged.

Notes

• The DB actors (dutydb / parsigdb / aggsigdb) and the fetcher have no distinct charon topic; they fall under app-start, matching charon.
• Spawn sites whose future contains no warn!/error! are left alone — there is nothing to mislabel. app/src/sse/mod.rs does log, but SseListener has no consumer outside its own module yet, so there is no topic to inherit; it will need one when it is wired into the node.
• infosync has no charon topic mapping and was left as-is.

Known limitation (pre-existing, not fixed here)

init.rs attaches EnvFilter as a global layer, which gates span construction for every layer including MetricsLayer. At the default info filter a debug_span!(…, topic = …) is never created, so these labels — and the pre-existing health/stacksnipe ones on main — are only observable under RUST_LOG=debug. Fixing it means moving EnvFilter to a per-layer filter on fmt/Loki and giving MetricsLayer its own; that predates this PR and is tracked separately. Details and a probe in this comment.

Quality gates

• cargo +nightly fmt --all --check — clean
• cargo clippy --workspace --all-targets --all-features -- -D warnings — clean
• cargo test --workspace --all-features — pass

Closes #588

🤖 Generated with Claude Code

[emlautarom1]

@varex83 Could you confirm that the log level is correct and propagation is working as intended to all potential subtasks? I'm not sure the agent covered all scenarios.

[emlautarom1]

It's extremely easy to forget about this wrapper, preferring to use tokio::spawn directly. Prefer to inline it in the callers (only 2) and document it.

[varex83agent]

Done — crates/tracing/src/spawn.rs and the pluto_tracing::spawn re-export are gone. Both callers now inline the wrap with a comment saying why:

// relay-server/src/web.rs
tokio::spawn(
    resolve_external_host_periodically(state, external_host, ct)
        .instrument(Span::current()),
)

The two propagation tests moved to crates/tracing/src/layers/metrics.rs, merged into one that pins both halves of the contract in a single assertion — an instrumented spawn is counted under the topic, a bare tokio::spawn from the same span is not. That's next to the layer that actually reads the span, so it's harder to delete by accident than a test sitting beside a helper nobody calls.

[emlautarom1]

What about JoinSet? Are we covering all cases of subtask spawn? The helper here is only used 2 times, and I'm certain that we spawn a lot more tasks than that.

[varex83agent]

You were right — two call sites was nowhere near the real surface. I went through every non-test tokio::spawn / JoinSet::spawn / spawn_blocking in the workspace (~90 sites) and checked which ones sit under a topic span and can emit warn!/error!. JoinSet::spawn behaves exactly like tokio::spawn here — empty span stack — so all three needed the same treatment.

Fixed:

site	kind	before	after
app/node/mod.rs — the lifecycle JoinSet (8 tasks)	JoinSet::spawn / extend	topic=""	app-start, via a local background() helper
consensus/qbft/runner.rs — instance JoinSet (5 tasks) + the core spawn_blocking	JoinSet::spawn, spawn_blocking	topic=""	inherits qbft
core/scheduler.rs — 2 subscriber loops, 2 per-event callback spawns, duty-broadcast delay, slot ticker	tokio::spawn	topic=""	sched
core/tracker/inclusion.rs::run	—	topic=""	tracker
app/monitoringapi/checker.rs — version metric + ready checker	tokio::spawn	topic=""	inherits app-start
priority/prioritiser.rs::start_consensus	tokio::spawn	topic=""	inherits caller
testutil/validatormock duty JoinSet	JoinSet::spawn	already inherited	reformatted (see below)

Two of those are charon-parity bugs rather than just plumbing:

• InclusionChecker::run had no topic at all. Charon sets tracker on it (core/tracker/inclusion.go:588), so every "Failed to check inclusion" warning was landing on topic="".
• The scheduler's subscriber loops were deliberately left unlabelled in the first pass, on the reasoning that callback errors belong to other components. That doesn't match charon: emitCoreSlot logs "Emit scheduled slot event" with the ctx from Scheduler.Run, which is sched (core/scheduler/scheduler.go:109). They're labelled sched now.

For the app/node/mod.rs JoinSet I used charon's own mechanism rather than inheritance — lifecycle.Manager hands every background hook a fresh log.WithTopic(context.Background(), "app-start") (app/lifecycle/hook.go:101), so background() opens that span at the one place background tasks are started, and a task with its own topic (sched, tracker, health) shadows it.

Deliberately left alone:

• No warn!/error! anywhere in the spawned future, so there is nothing to mislabel: qbft/definition.rs:311 (round timer), qbft/transport.rs:209, core/aggsigdb/memory.rs:165, core/deadline/mod.rs:216, app/node/wire.rs:{520,809,1137}, eth2util/keystore/{load,store}.rs.
• app/src/sse/mod.rs — 11 warn/error sites, but SseListener currently has no consumer outside its own module, so there is no topic to inherit yet. It will need one when it gets wired into the node.
• cli/commands/test/* — one-shot CLI subcommands; charon gives its equivalents no topic either.

The rule this settles on, which I think is the answer to "easy to forget": a task that is a component opens its own topic span (#[instrument(fields(topic = …))] on the entry point, so it works regardless of who spawned it); a task that is a subtask of its caller re-attaches Span::current() at the spawn. Only the second kind is forgettable, and it is now a handful of sites, each with a comment.

[emlautarom1]

Also, formatting might need to be revisited.

[varex83agent]

@emlautarom1 thanks — both inline comments are addressed (replies on the threads), and main is merged. On the two questions in your review body:

"Is the log level correct?"

No, and it is worse than this PR: the whole topic mechanism is inert at the default log level, including the pre-existing health and stacksnipe topics on main.

init.rs attaches EnvFilter as a global layer:

let registry = Registry::default()
    .with(env_filter)     // <- global, default "info"
    .with(fmt_layer)
    .with(MetricsLayer);

A global EnvFilter gates Subscriber::enabled for every layer, so at info a debug_span!("qbft", topic = "qbft") is never constructed, MetricsLayer::on_new_span never fires, no SpanTopic extension is stored, and event_topic walks an empty scope. Every warn/error still lands on topic="".

I probed it directly against MetricsLayer rather than reasoning about it:

PROBE debug_span under info filter: before=0 after=0
PROBE empty label now=1

The fix is to make EnvFilter a per-layer filter on fmt (and Loki) and give MetricsLayer its own narrow filter, so topic spans are constructed regardless of the console level. That also matches charon, where the counter is level-independent by construction — incWarnCounter(ctx) runs before the logger's level check (app/log/log.go:108).

I have not done that here: it restructures subscriber wiring, it fixes a bug that predates this PR, and it deserves its own review. Happy to open a follow-up issue, or to fold it in if you would rather this PR ship working end-to-end — your call. Worth being explicit that until it lands, this PR's labels are correct but unobservable outside RUST_LOG=debug.

"Is propagation working to all potential subtasks?"

It wasn't. Full audit in the JoinSet thread — JoinSet::spawn and spawn_blocking had the same gap as tokio::spawn, and two sites were charon-parity bugs (InclusionChecker::run had no topic at all; the scheduler's subscriber loops should be sched).

Formatting

Fixed. cargo +nightly fmt --all --check is clean. The problem was that rustfmt silently gives up on an expression it cannot fit — wrapping a long async move { … } in Instrument::instrument(fut, span) left the body at its old indentation and the check still passed. Where that happened I hoisted the future into a named binding first (let duty_task = async move { … }; set.spawn(duty_task.instrument(span));), which keeps rustfmt in charge.

Gates

• cargo +nightly fmt --all --check — clean
• cargo clippy --workspace --all-targets --all-features -- -D warnings — clean
• cargo test --workspace --all-features — pass