Logs

tracing::info!, debug!, warn!, error! are the framework’s logging API. Every event flows through the installed subscriber to the console and, when OTLP is configured, through the OpenTelemetryTracingBridge to OTel logs. Backend collectors index them alongside the traces of the same request.

Default level per layer

Concern	Target	Default level
Operation log — one line per unit of work, every edge	nest_rs::operation	info
HTTP span	nest_rs::http	info
MCP operations	nest_rs::mcp	info
Route / endpoint mounting (boot)	nest_rs::routes	info
ORM queries	nest_rs::orm	trace
Layer composition (per-route guard/pipe/… chains)	nest_rs::layers	trace for the per-route effective-chain dump; debug for the redundant multi-scope lint (HTTP deduped once, WS per gateway); warn for actionable posture smells (reversed authn/authz order, denials, routes with no guard and no #[public] when no global pool is active)
Authn / Authz	nest_rs::authn / nest_rs::authz	info (denials warn)
OAuth client	nest_rs::oauth::client	info (callback refusals warn)
RFC 9728 discovery	nest_rs::oauth::resource	info (boot misconfiguration warn)
WebSocket events	nest_rs::ws	info
GraphQL execution and subscriptions	nest_rs::graphql	info
Queue / Schedule	nest_rs::queue / nest_rs::schedule	info
Redis connection (the one handle the queue, worker and rate-limit store share)	nest_rs::redis	warn per connect attempt while the boot budget runs
Module lifecycle	nest_rs::module	info
Application spans	<crate>::<feature> (e.g. features::users)	info

Controllers, resolvers, gateways log at info on success. Services keep per-call chatter at debug; a discrete operational event a service owns — a job enqueued, a file transcoded — earns info. Repo at trace. Access denials and security events at warn+ so they appear under the default info filter. A production deploy should respect info — no per-request debug! on the hot path.

Structured fields

crates/features/src/users/service.rs

tracing::info!(
    target: "features::users",
    user_id = %id,
    "creating user",
);

user_id is the subject the event is about. Who asked for it is not a field you write: the operation span carries actor_id, and restating it here gives a backend two spellings of one fact.

Always prefer field = %value to format!("{}", value). The OTLP bridge serializes structured fields directly; a formatted string becomes opaque text the backend cannot filter on.

Every event runs under the operation span its edge opened, which already carries trace_id and span_id — the OpenTelemetry log-record vocabulary, so a backend joins logs to traces with no field mapping — and actor_id once an authn guard resolved a principal. Your structured fields layer on top of those, and you never write either by hand.

Both are also readable from code, anywhere the framework carries work: a handler, a service below it, a WS message, an MCP tool, a queue job in another process. And inside a streaming response, which is the one that surprises people — an #[sse] stream is written after its handler returned, and it still runs under the request that opened it.

crates/features/src/users/service.rs

let trace_id = nest_rs::core::current_trace_id();
let span_id = nest_rs::core::current_span_id();
// `None` for an anonymous caller — absence is the answer, not a missing one.
let actor_id = nest_rs::core::current_actor_id();

actor_id is an audit identity: who, for a log line or a created_by column. What a caller may do is decided in a guard, never by branching on this value.

One line, one unit of work

Every log line carries the W3C trace context of the unit of work that emitted it, in both formats — trace_id, span_id, and actor_id once a guard resolved a principal. That is the whole correlation mechanism: two lines belong to the same work when the ids match, and you join them on that.

DEBUG features::posts: creating post title="hello" trace_id=01a01569ae687353bc034a9ee8bd8774 span_id=a3f7cc8bac648278 actor_id=01a0112ce24e75509be691162cbbab1f

{"timestamp":"2026-08-18T15:07:22.601081Z","level":"DEBUG","fields":{"message":"creating post","title":"hello"},"target":"features::posts","trace_id":"01a01569ae697a718f7e41c79e0eefe6","span_id":"39d4f26e5d048754","actor_id":"01a0112ce24e75509be691162cbbab1f"}

This owes nothing to a collector, an exporter or this crate: the trace context is a kernel primitive, so a bare app logging to a terminal has it. Adding nest-rs-opentelemetry exports the same ids — it does not own them, and it does not change the shape of a line.

The ids are read from the context, never from the span

A line carries no span attributes and no span names. That is worth stating, because the alternative looks harmless and is not. A service runs under the HTTP request’s span, so rendering span state put the request’s method, path, client address and user agent on every line the service emitted. The line stopped being about what the service did. Nested work made it worse, printing one trace_id per level:

DEBUG http.request{otel.kind="server" trace_id=01a014ec…a4 span_id=5fcb…b7 http.request.method=POST url.path="/posts" client.address=127.0.0.1}:mcp.operation{otel.kind="server" trace_id=01a014ec…a4 span_id=b0c0…72}: features::posts: creating post title="hello"

Reading the context instead of the scope is what makes the line self-contained, and it is the same read your own code does:

crates/features/src/users/service.rs

let trace_id = nest_rs::core::current_trace_id();
let span_id = nest_rs::core::current_span_id();
let actor_id = nest_rs::core::current_actor_id();

It also reaches further than a span stack can. A streaming body is polled after its handler returned; the framework re-installs the request around it, so those lines carry the ids too.

Span structure itself is untouched — nesting is normal, and it is what the OTLP export builds its tree from.

Every unit of work files one line

The ids relate lines to each other; they do not say what the work was. That is a separate line, one per unit of work, on the shared target nest_rs::operation — and every edge files one, not just HTTP:

Edge	Canonical name	Names
HTTP request	http.request	method, path, status, bytes, client
WS message	ws.message	event, conn_id
WS socket open	ws.connect	conn_id
WS socket close	ws.disconnect	conn_id
Scheduled tick	schedule.tick	provider, method
Queue job	queue.job	queue, processor, job_id, attempt
MCP operation	mcp.operation	the JSON-RPC method
GraphQL operation	graphql.operation	role, operation
GraphQL subscription	graphql.subscription	the connection is the unit
Event dispatch	events.dispatch	event, listener

The name is <edge>.<unit>, and it is the same string the operation’s span carries. It is declared once, by the crate that owns the edge, as <crate>::unit::<UNIT> — nest_rs_http::unit::REQUEST, nest_rs_ws::unit::MESSAGE, nest_rs_queue::unit::JOB, and so on. It is then read three times: by the span, by the log record’s event name (what an OTLP exporter reports as event.name), and by the message a console prints. The grammar is nest_rs_core::operation_log’s; the names are not, for the same reason a span target is not — a unit name says which edge did the work, and the kernel does not know the edges exist. There used to be two vocabularies for these eight things — the spans said http.request while the lines said request served — so an operator learned the set twice and a query could pick the wrong one.

Every one carries duration_ms, and every one but HTTP carries outcome (ok / error / panic) — a request has status, which says how it ended more precisely than three words could. So one query answers “what did this deployment do”, and “what failed” is outcome != ok or status >= 400.

INFO nest_rs::operation: http.request method=GET path="/users" status=401 bytes=127 duration_ms=0.103 client_ip=127.0.0.1 forwarded=false user_agent="curl/8.14.1" trace_id=01a015a9433c7c2393647b0a40e5b658 span_id=6c6f2ed837da7b3b
INFO nest_rs::operation: schedule.tick provider="AudioTasks" method="warmup_on_boot" outcome="ok" duration_ms=0.302 trace_id=01a015a91d527cb1b9d15a8ba7fe8846 span_id=bd824ae7eb1f9e7a

The target is the toggle. NESTRS_LOG=info,nest_rs::operation=off silences the whole family at once, which is why no edge carries a config flag for it. NESTRS_HTTP__ACCESS_LOG predates the family and stays, as an app’s pinned config rather than a deployment’s filter — it is one edge’s line, not the family’s.

It was nest_rs::access through 5.1, so a filter, runbook or dashboard still naming the old string matches nothing. That string also matched something it never meant to: EnvFilter compares a directive’s target with starts_with on the raw string rather than by :: segment, so nest_rs::access=off also silenced nest_rs::access_graph — the boot warning naming resolvers unreachable from the GraphQL schema. A deployment that quieted its access log lost that diagnostic with nothing on the console to say so. Neither old name survives: that warning is nest_rs::graphql’s now, filed by the crate that owns the resolver registry. nest_rs::operation prefixes no other target, and a test fails the day one prefixes another.

Following one operation across two processes

A scheduled tick in the api binary enqueues a job; the worker binary picks it up ninety seconds later. One trace_id, two span_ids — the job is a child of the tick, across a process boundary:

DEBUG features::audio: enqueued transcode job file="track-1787069801760.mp3" trace_id=01a015a9252076e399f736a97ae90784 span_id=052e261668035200
 INFO nest_rs::operation: schedule.tick provider="AudioTasks" method="enqueue_transcode" outcome="ok" duration_ms=101.901 trace_id=01a015a9252076e399f736a97ae90784 span_id=052e261668035200
DEBUG features::audio: transcoded file="track-1787069801760.mp3" byte_size=50 trace_id=01a015a9252076e399f736a97ae90784 span_id=7bbcfc44c1f0c676
 INFO nest_rs::operation: queue.job queue="audio" processor="AudioProcessor::transcode" attempt=1 outcome="ok" duration_ms=33.733 trace_id=01a015a9252076e399f736a97ae90784 span_id=7bbcfc44c1f0c676

The first two lines are the api’s, the last two the worker’s. Nothing was configured for that: the producer seals its trace context into the queue envelope, the consumer continues from it.

Text vs JSON

The console layer ships both formats. Default is text (pretty for dev). For prod, set:

NESTRS_LOG_FORMAT=json

Both are the framework’s own formatters, and they say the same thing: JSON puts trace_id, span_id and actor_id at the top level of the record, where a backend reads them with no field mapping, rather than nested under a span object. There is no variable that puts span state back on a line.

JSON also carries trace_flags, the third field OpenTelemetry’s log data model names beside the two ids. Text does not: a record joined against an export needs to know whether the export exists, and a human at a console never acts on a sampling bit.

Source location (file:line)

To trace a console line back to the exact source that emitted it, enable source location:

NESTRS_LOG_SOURCE_LOCATION=true

Each event then carries the emitting file:line:

DEBUG nest_rs::layers: crates/nest-rs-core/src/layer_chain.rs: layer declared at multiple scopes…

Off by default — it widens every line and leaks source paths, so it stays out of production. Turn it on in .env.development (next to NESTRS_LOG=debug) so it is live while developing and off everywhere else, or pin it explicitly with OpenTelemetryConfig::with_log_source_location(true).

Access log

The access log belongs to nest-rs-http, not to this crate. Method, path, status, duration, client, trace_id, span_id and actor_id are what the transport knows about a request it served — no collector, no exporter and no propagator is involved, so none is required. It emits one event per request on nest_rs::operation, at end-of-body, with byte-accurate bytes:

INFO nest_rs::operation: http.request method=GET path="/users" status=401 bytes=127 duration_ms=0.09 trace_id=01a0112ce24e75509be691162cbbab1f span_id=3f2b91c40a7e5d16 client_ip=127.0.0.1 forwarded=false

actor_id joins the line once an authn guard resolved a principal, and is absent above because nobody was authenticated — which is why that request is a 401. trace_id and span_id are the transport’s own W3C trace context and need no collector to exist. That is the shape of the whole relationship: the observability stack enriches what is exported and never owns what this line can say.

Toggle it with NESTRS_HTTP__ACCESS_LOG=false. That silences the line only — the trace is still started, still reported as traceresponse, and still carried into the response body, because everything else is filed under it.

OTel logs bridge

The OpenTelemetryTracingBridge is wired in only when an OTLP endpoint is configured. Without an endpoint, the bridge is skipped — it pays a small per-event cost just to drop the event, which is not worth paying when console-only logging is the goal. When the endpoint is set, every tracing event becomes an OTel log record with the same target, level, fields and trace_id.

Going further

• Traces — the spans logs correlate against.
• Metrics — the aggregate counterpart to logs.
• OpenTelemetry — the appender and OTLP export.