Tracing Best Practices

Tracing Best Practices

When to Apply

This skill MUST be followed whenever you:

• Add or modify #[instrument] attributes
• Write tracing::info!, tracing::debug!, tracing::warn!, tracing::error!, tracing::trace! events
• Create or modify spans (info_span!, debug_span!, etc.)
• Write tokio::spawn or any async task spawning
• Modify subscriber/tracing initialization code
• Handle errors at boundary layers
• Write state machine event handlers
• Add IPC/daemon request handlers

1. Core Concepts

tracing records three types of structured data — NOT print text:

• Span: A time range (request, usecase execution, state machine event handler)
• Event: A discrete fact at a single moment ("received pairing proof", "db write failed")
• Field: Structured key-value data (trace_id, device_id, session_id, state, elapsed_ms)

Design Principles

• Spans = flow boundaries; Events = facts within flows
• Every span MUST contain at least one event — #[instrument] alone only creates a span; tracing_subscriber::fmt only outputs events. A span with no events inside it produces zero log output, making the function invisible in logs.
• Fields first, messages second
• Stable field names over ad-hoc description strings
• Record business context, never sensitive plaintext
• Call chains connect via span hierarchy, not string search
• Default to info/debug-safe for production

2. Where Spans Are REQUIRED

2.1 Entry Layer (MUST have top-level span)

Applies to: host command handlers, CLI handlers, HTTP/IPC handlers, background task entries, scheduled task entries.

#[instrument(
    name = "cmd.get_clipboard_items",
    level = "info",
    skip(runtime),
    fields(trace_id = %uuid::Uuid::new_v4())
)]
pub async fn get_clipboard_items(runtime: State<'_, AppRuntime>) -> Result<Vec<Item>, String> {
    // ...
}

Requirements:

• Every entry function MUST have a top-level span
• MUST include trace_id or equivalent request identifier
• MUST include business object IDs (session_id, device_id, space_id)

2.2 UseCase / Orchestrator Layer (MUST have span)

Applies to: start_join_space, submit_passphrase, persist_entry, handle_event, sync_once, etc.

#[instrument(
    name = "space_access.submit_passphrase",
    level = "info",
    skip(self, passphrase),
    fields(session_id = %self.session_id, device_id = %self.device_id, state = ?self.state)
)]
async fn submit_passphrase(&mut self, passphrase: String) -> Result<()> {
    // Span name reflects business action, not technical detail
}

2.3 External Boundaries (at least event, preferably span)

Applies to: DB read/write, file I/O, network send/receive, subprocess calls, encryption boundaries, WebSocket/libp2p/relay/RPC.

• MUST record: target object, result, elapsed time, error code/kind
• Large payloads MUST NEVER be logged directly

2.4 Async Spawn (MUST propagate span)

// CORRECT - Propagate current span
tokio::spawn(task().in_current_span());

// CORRECT - Create specific span for spawned work
let span = tracing::info_span!("pairing_session", session_id = %session_id);
tokio::spawn(task.instrument(span));

Long-lived background loops MUST create child spans or events per iteration. Channel/callback boundaries MUST re-attach message IDs into new span context.

2.5 Async Span Lifecycle — Three Correct Patterns

Core Rule: NEVER use .entered() in async functions

EnteredSpan contains *mut () → not Send → holding it across .await makes the future non-Send → tokio::spawn / JoinSet::spawn will fail to compile.

Pattern 1: Function-level — #[instrument] (preferred)

Best for: standalone async functions where parameters can be skipped.

#[instrument(skip_all, fields(session_id = %session_id, peer_id = %peer_id))]
async fn handle_message(session_id: &str, peer_id: &str, msg: Message) -> Result<()> {
    info!("received message");  // automatically under the span
    do_something().await;       // await-safe
}

Pattern 2: Spawn-level — .instrument(span)

Best for: futures passed to tokio::spawn / JoinSet::spawn.

let span = tracing::info_span!("pairing.action_loop");
tasks.spawn(run_action_loop(rx, cancel).instrument(span));

Pattern 3: Inline async block — async { }.instrument(span).await

Best for: match arms, if-branches, or other blocks that need a local span with .await inside.

match event {
    Event::Succeeded { session_id } => {
        let span = info_span!("pairing.session", session_id = %session_id);
        async {
            info!(event = "succeeded");    // under the span
            notify_peer().await;           // await-safe
        }.instrument(span).await;
    }
}

FORBIDDEN Patterns

// ❌ Compile error — EnteredSpan is not Send
let _guard = info_span!("my_span").entered();
something.await;  // _guard held across await

// ❌ Same problem, different syntax
let span = info_span!("my_span");
let _guard = span.enter();
something.await;  // _guard still held across await

3. Where NOT to Use #[instrument]

Pure utility functions — NO span

hash_bytes, normalize_path, parse_header, to_png — no business semantics, no span. Adds noise.

High-frequency hot paths — NO span

Tight loops, per-poll/tick functions, per-item iteration helpers. Use sampled events or aggregate stats instead.

Functions with sensitive/large parameters — MUST skip

#[instrument] records params via Debug by default. Passwords, tokens, ciphertext, large blobs WILL leak unless explicitly skip()-ed.

4. #[instrument] Standard Template

#[instrument(
    name = "space_access.submit_passphrase",  // Stable name — survives refactors
    level = "info",                            // Explicit default level
    skip(self, passphrase),                    // Skip sensitive/large params
    fields(
        session_id = %self.session_id,         // Key business context
        device_id = %self.device_id,
        state = ?self.state
    )
)]
async fn submit_passphrase(&mut self, passphrase: String) -> Result<()> { ... }

skip Rules — ALWAYS skip:

• self (unless Debug is very light and valuable)
• All secrets: password, passphrase, token, secret
• Large collections, binary data, raw request/response bodies
• Sensitive DTOs, large Arc<AppState> / runtime / container

% vs ? Selection:

• %field (Display): stable, short, search-friendly fields
• ?field (Debug): enums, struct summaries, diagnostic detail

Return Values:

Do NOT automatically record full return values. Log key results as separate events:

tracing::info!(session_id = %session_id, result = "accepted", "space access completed");

CRITICAL: #[instrument] Requires Events Inside the Function Body

#[instrument] generates a span, not an event. tracing_subscriber::fmt only writes events to log output (console/JSON file). A function with only #[instrument] and no event macros (info!, debug!, etc.) produces zero log output — the function is completely invisible in logs.

Every #[instrument]-annotated function MUST emit at least one tracing event. Minimum pattern:

#[instrument(name = "api.search_query", level = "info", skip(state, params), fields(query = %params.query))]
async fn search_query_handler(state: State, params: Query) -> Result<Json<Response>, Error> {
    // ... business logic ...
    let result = do_search().await?;
    // At minimum, log the outcome — this makes the function visible in logs
    info!(total = result.total, "search completed");
    Ok(Json(result))
}

For thin delegation functions (usecases that just call a port), a single debug! after the call is sufficient:

#[tracing::instrument(name = "usecase.index_entry.execute", skip(self, doc, postings), fields(entry_id = %doc.entry_id))]
pub async fn execute(&self, doc: SearchDocument, postings: Vec<SearchPosting>) -> Result<(), SearchError> {
    self.search_index.index_entry(doc, postings).await?;
    tracing::debug!("entry indexed successfully");
    Ok(())
}

5. Event Standards

Events record facts within a span. Message MUST be short; fields carry the data.

Success Event

tracing::info!(
    session_id = %session_id,
    peer_id = %peer_id,
    attempt = retry_count,
    "relay connection established"
);

Failure Event

MUST include: error_kind (stable category), error or source = ?err, retryability flag, key context IDs.

tracing::error!(
    session_id = %session_id,
    error_kind = "proof_verification_failed",
    retryable = false,
    error = %err,
    "space access failed"
);

State Machine Transition Event

tracing::debug!(
    session_id = %session_id,
    event = "ReceivedProof",
    from_state = ?old_state,
    to_state = ?new_state,
    "state transition"
);

6. Field Naming Convention

Field names MUST be stable (once shipped, avoid renaming). Use snake_case.

Common Fields (use consistently):