Add structured tracing fields for debuggability by Dominik1999 · Pull Request #83 · 0xMiden/note-transport-service

Dominik1999 · 2026-04-23T08:28:38Z

Summary

Added structured tracing fields across gRPC handlers, DB layer, maintenance, and streaming
Identifiers (note_id, tag) at debug level for privacy (opt-in via RUST_LOG)
Operational data (counts, cursors, subscription lifecycle) at info level
Rejection paths log structured reason fields for filtering
Subscription lifecycle: connect/disconnect with active count, duration, disconnect reason

What operators see at `RUST_LOG=info` (default)

send_note: note_size
fetch_notes: tag_count, cursor, notes_returned, response_cursor
stream_notes: subscription_id
Rejections: warn with reason field (note_too_large, too_many_tags, invalid_header)
Maintenance: notes_deleted, retention_days
Subscriptions: add/remove with active count, backpressure drops, client disconnect with duration

What operators see at `RUST_LOG=miden_note_transport=debug`

All of the above, plus: note_id, tag per request

Test plan

make lint passes
make test passes (13/13)
Spot-check with RUST_LOG=info and RUST_LOG=miden_note_transport=debug

🤖 Generated with Claude Code

Closes #82

WiktorStarczewski · 2026-04-23T11:22:41Z

This depends on #81 right? At least the branch is stacking on top. If intentional, can you change base branch to #81's branch so this can be reviewed in isolation? Thanks

Dominik1999 · 2026-04-23T11:28:32Z

Done, you can review now

WiktorStarczewski

LGTM

mmagician

What is the verbosity we actually expect NTS operators to run?

+ Changed base branch as Wiktor suggested

+ The changes look good but I'm not so versed in tracing, adding @kkovaacs to provide input here please 🙏🏼

kkovaacs

Looks good to me!

Just a small nit related to one of the error events.

kkovaacs · 2026-06-08T14:51:51Z

+        );
        if let Err(e) = self.streamer_tx.try_send(StreamerMessage::RemoveSub((self.id, self.tag))) {
-            tracing::error!("Streamer remove sub control message sending error: {e}");
+            tracing::error!(subscription_id = %self.id, tag = self.tag.as_u32(), "Streamer remove sub control message sending error: {e}");


Would be cool to have the error as a field instead of formatting into the message.

Suggested change

tracing::error!(subscription_id = %self.id, tag = self.tag.as_u32(), "Streamer remove sub control message sending error: {e}");

tracing::error!(subscription_id = %self.id, tag = self.tag.as_u32(), error=%e, "Streamer remove sub control message sending error");

WiktorStarczewski

Nice cleanup. Bonus: switching to skip(self, request) also kills the old full-request Debug dump that was landing in the spans, so it's a net privacy/cost win on top.

Two things worth surfacing up here (rest inline):

Privacy: the subscription lifecycle logs leak tag at info/warn/error, which goes against the PR's own "identifiers at debug only" rule. Lines flagged inline.
Merge order vs #84: you both touch fetch_notes/fetch_notes_by_tags in sqlite/mod.rs, and #84 makes limit a mandatory 3rd arg while streaming.rs here still calls fetch_notes with 2 args. Whoever lands second has to reconcile by hand — keep both the tracing fields and the limit wiring, and pass None at the streaming call site. Not a bug here, just don't let the merge silently drop one side.

(Also confirmed cleanup_old_notes already returns u64 on the base branch, so notes_deleted is legit — no signature change.)

WiktorStarczewski · 2026-06-17T09:44:17Z

-        // Remove non-responding subs
+        // Remove non-responding subs (backpressure)
        for (sub_id, tag) in remove_subs {
+            tracing::warn!(subscription_id = %sub_id, tag = tag.as_u32(), reason = "backpressure", "Dropping subscription");


tag at warn = leaked at the default log level, but the PR says identifiers are debug-only for privacy. Same thing in add_sub/remove_sub/Drop below. Drop tag here (keep subscription_id + reason + count) or move these to debug.

WiktorStarczewski · 2026-06-17T09:44:17Z

        let entry = self.tags.entry(sub.tag).or_insert_with(TagData::new);
        entry.subs.insert(sub.id, sub.tx);
+        let active = self.tags.values().map(|td| td.subs.len()).sum::<usize>();
+        tracing::info!(subscription_id = %sub.id, tag = sub.tag.as_u32(), active_subscriptions = active, "Subscription added");


Same tag-at-info leak (also remove_sub L168 and Drop L288). subscription_id + active_subscriptions are fine at info — it's just tag that needs to go or drop to debug.

WiktorStarczewski · 2026-06-17T09:44:17Z

            self.tags.remove(&tag);
        }
+        let active = self.tags.values().map(|td| td.subs.len()).sum::<usize>();
+        tracing::info!(subscription_id = %sub_id, tag = tag.as_u32(), active_subscriptions = active, "Subscription removed");


Minor: this "Subscription removed" plus Drop's "Subscription dropped" means every removal logs twice, and only one line carries the count while the other carries the reason. Probably cleaner as a single removal event.

WiktorStarczewski · 2026-06-17T09:44:17Z

+            tag = self.tag.as_u32(),
+            duration_secs = duration_secs,
+            reason = "client_disconnect",
+            "Subscription dropped"


reason = "client_disconnect" fires unconditionally, but Drop also runs on backpressure/server eviction where the client didn't disconnect. Either drop the reason field or thread an evicted flag. (tag here is the same privacy nit.)

WiktorStarczewski · 2026-06-17T09:44:17Z

        let pnote = request_data.note.ok_or_else(|| Status::invalid_argument("Missing note"))?;

-        let timer = self.metrics.grpc_send_note_request((pnote.header.len() + pnote.details.len()) as u64);
+        let note_size = pnote.header.len() + pnote.details.len();


Heads up: note_size here is header+details, but the rejection log below uses size = payload_size = details+metadata. Same handler, two different "size" numbers — mildly confusing when correlating accept vs reject.

gRPC handlers: - send_note: note_size (info), note_id/tag (debug), warn on rejection - fetch_notes: tag_count/cursor/notes_returned/response_cursor (info), warn on too-many-tags rejection - stream_notes: subscription_id (info), tag/cursor (debug) Database layer: - store_note: note_id/tag (debug) - fetch_notes_by_tags: tag_count/cursor/notes_returned (info) - Legacy cursor reset promoted to info log - Removed redundant instrument from fetch_notes wrapper Maintenance: - Log notes_deleted count and retention_days per cleanup cycle Streaming lifecycle: - Subscription add/remove with active count - Backpressure drops with warn + reason - Client disconnect with subscription duration Design decisions: - Identifiers (note_id, tag) at debug level for privacy - Operational data (counts, cursors) at info level - Structured reason fields for rejections (filterable) Closes #82 Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Per review feedback (Wiktor, kkovaacs): - Privacy: stop logging note tag above debug level. Removed tag from the add_sub/remove_sub/backpressure/Drop lifecycle logs, per the PR's own 'identifiers at debug only' rule. subscription_id + active_subscriptions + reason remain at info. - Single removal event: consolidate the duplicate 'Subscription dropped' (Drop) and 'Subscription removed' (remove_sub) into one canonical event in remove_sub, carrying active count, duration, and a threaded reason. It only logs when a sub was actually present, so a backpressure eviction followed by a client-side Drop no longer double-logs or mislabels the reason. created_at moved into the manager's sub map so duration survives on that single event for every removal reason. - Error as field: the Drop send-failure log now records error=%e instead of interpolating it into the message.

* Release v0.4.1 Bump workspace version 0.4.0 -> 0.4.1 and add CHANGELOG entries for the changes merged since v0.4.0 (#80, #81, #83). Also dates the stale 'v0.4.0 (unreleased)' header (0.4.0 shipped 2026-06-08). * Drop [BREAKING] tag on OTel changelog entry The OTel change is a new way to configure the node, not an API break. Keep the note that the old env vars are no longer read. --------- Co-authored-by: Claude (Opus) <noreply@anthropic.com>

Dominik1999 added this to the Release v0.4.0 milestone Apr 23, 2026

Dominik1999 force-pushed the dominik1999-claude/structured-tracing branch from 8958693 to b46d326 Compare April 23, 2026 08:41

Dominik1999 marked this pull request as ready for review April 23, 2026 08:48

WiktorStarczewski self-requested a review April 23, 2026 11:18

Dominik1999 changed the base branch from main to dominik1999-claude/block-context April 23, 2026 11:28

WiktorStarczewski approved these changes Apr 23, 2026

View reviewed changes

Dominik1999 changed the base branch from dominik1999-claude/block-context to next April 23, 2026 16:38

mmagician changed the base branch from next to dominik1999-claude/block-context June 8, 2026 09:28

mmagician approved these changes Jun 8, 2026

View reviewed changes

mmagician requested a review from kkovaacs June 8, 2026 09:32

kkovaacs approved these changes Jun 8, 2026

View reviewed changes

WiktorStarczewski reviewed Jun 17, 2026

View reviewed changes

Dominik1999 force-pushed the dominik1999-claude/structured-tracing branch from b46d326 to 3522bb6 Compare June 17, 2026 13:29

claude added 2 commits June 17, 2026 15:49

Dominik1999 force-pushed the dominik1999-claude/structured-tracing branch from 3522bb6 to c802419 Compare June 17, 2026 13:53

Dominik1999 changed the base branch from dominik1999-claude/block-context to main June 17, 2026 13:53

Dominik1999 merged commit d7d0937 into main Jun 17, 2026
13 of 22 checks passed

Dominik1999 mentioned this pull request Jun 17, 2026

Release v0.4.1 #93

Merged

Navigation Menu

Uh oh!

Add structured tracing fields for debuggability - #83

Add structured tracing fields for debuggability#83
Dominik1999 merged 2 commits into
mainfrom
dominik1999-claude/structured-tracing

Dominik1999 commented Apr 23, 2026

Uh oh!

WiktorStarczewski commented Apr 23, 2026

Uh oh!

Dominik1999 commented Apr 23, 2026

Uh oh!

WiktorStarczewski left a comment

Uh oh!

mmagician left a comment

Uh oh!

kkovaacs left a comment

Uh oh!

kkovaacs Jun 8, 2026

Uh oh!

WiktorStarczewski left a comment

Uh oh!

WiktorStarczewski Jun 17, 2026

Uh oh!

WiktorStarczewski Jun 17, 2026

Uh oh!

WiktorStarczewski Jun 17, 2026

Uh oh!

WiktorStarczewski Jun 17, 2026

Uh oh!

WiktorStarczewski Jun 17, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

	tracing::error!(subscription_id = %self.id, tag = self.tag.as_u32(), "Streamer remove sub control message sending error: {e}");
	tracing::error!(subscription_id = %self.id, tag = self.tag.as_u32(), error=%e, "Streamer remove sub control message sending error");

Uh oh!

Conversation

Dominik1999 commented Apr 23, 2026

Summary

What operators see at RUST_LOG=info (default)

What operators see at RUST_LOG=miden_note_transport=debug

Test plan

Uh oh!

WiktorStarczewski commented Apr 23, 2026

Uh oh!

Dominik1999 commented Apr 23, 2026

Uh oh!

WiktorStarczewski left a comment

Choose a reason for hiding this comment

Uh oh!

mmagician left a comment

Choose a reason for hiding this comment

Uh oh!

kkovaacs left a comment

Choose a reason for hiding this comment

Uh oh!

kkovaacs Jun 8, 2026

Choose a reason for hiding this comment

Uh oh!

WiktorStarczewski left a comment

Choose a reason for hiding this comment

Uh oh!

WiktorStarczewski Jun 17, 2026

Choose a reason for hiding this comment

Uh oh!

WiktorStarczewski Jun 17, 2026

Choose a reason for hiding this comment

Uh oh!

WiktorStarczewski Jun 17, 2026

Choose a reason for hiding this comment

Uh oh!

WiktorStarczewski Jun 17, 2026

Choose a reason for hiding this comment

Uh oh!

WiktorStarczewski Jun 17, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

What operators see at `RUST_LOG=info` (default)

What operators see at `RUST_LOG=miden_note_transport=debug`