Skip to content

Production-grade structured logging (v0.9.0) - #42

Merged
guyte149 merged 1 commit into
masterfrom
feat/structured-logging
May 5, 2026
Merged

Production-grade structured logging (v0.9.0)#42
guyte149 merged 1 commit into
masterfrom
feat/structured-logging

Conversation

@guyte149

@guyte149 guyte149 commented May 5, 2026

Copy link
Copy Markdown
Owner

Replace the global-max-level subscriber with tracing-subscriber + EnvFilter, add --quiet and --log-format compact|json, and unify every log call site around a stable span schema that mirrors the rusnel ctl ID model (client_id / tunnel_id / conn_id).

Why

  • The old subscriber was a single global level knob with no per-module control and no way to gate noisy upstream crates separately, so --debug drowned rusnel's own messages in quinn / rustls trace output.
  • Field names drifted between sites (id vs client_id, local TCP counter id vs admin conn_id, Forward vs "forward"), which made greppable correlation with the admin API unreliable.
  • Connection lifecycles only logged "opened"; closing was silent unless there was an error, so basic "who used the most bytes" questions required either standing up an aggregator or shelling into the admin socket.

What changes

  • init_logging in src/main.rs: EnvFilter honoring RUST_LOG, synthesized defaults that keep quinn/rustls/h3/hyper at WARN while rusnel modules respect -v / --debug / -q. Compact format with ISO-8601 UTC millisecond timestamps, target hidden, ANSI auto-detected from stderr TTY-ness. --log-format json emits one event per line for log aggregators.
  • Stable spans: client{client_id,peer} (server) / session{peer} (client) → tunnel{tunnel_id,dir,spec}conn{conn_id,tunnel_id, peer,proto}. Server-side conn span now uses the real conn_id from ServerState::register_conn; client-side falls back to a local counter when admin tracking is off.
  • Every conn emits structured conn opened / conn closed events; the close line carries bytes_in, bytes_out (snapshotted from the ConnGuard before drop), and dur_ms.
  • Subcommand subscribers (ctl, cert) collapsed into a shared init_simple_logger so they pick up RUST_LOG overrides too.
  • Cargo.toml: enabled the env-filter/fmt/ansi/json/time features on tracing-subscriber and added time for the timestamp format description.
  • Messages rewritten throughout server/, client/, common/{tcp,udp, socks,proxy,tunnel,quic}, server/admin, lib: lowercase, terse, present-tense, key-value structured fields instead of inline format args.
  • README: marked the RUST_LOG TODO done and added a Logging section with the schema, flags, and a real example trace.

Replace the global-max-level subscriber with `tracing-subscriber` +
`EnvFilter`, add `--quiet` and `--log-format compact|json`, and unify
every log call site around a stable span schema that mirrors the
`rusnel ctl` ID model (`client_id` / `tunnel_id` / `conn_id`).

Why
- The old subscriber was a single global level knob with no per-module
  control and no way to gate noisy upstream crates separately, so
  `--debug` drowned rusnel's own messages in quinn / rustls trace output.
- Field names drifted between sites (`id` vs `client_id`, local TCP
  counter `id` vs admin `conn_id`, `Forward` vs `"forward"`), which
  made greppable correlation with the admin API unreliable.
- Connection lifecycles only logged "opened"; closing was silent unless
  there was an error, so basic "who used the most bytes" questions
  required either standing up an aggregator or shelling into the admin
  socket.

What changes
- `init_logging` in `src/main.rs`: `EnvFilter` honoring `RUST_LOG`,
  synthesized defaults that keep quinn/rustls/h3/hyper at WARN while
  rusnel modules respect `-v` / `--debug` / `-q`. Compact format with
  ISO-8601 UTC millisecond timestamps, target hidden, ANSI auto-detected
  from stderr TTY-ness. `--log-format json` emits one event per line for
  log aggregators.
- Stable spans: `client{client_id,peer}` (server) / `session{peer}`
  (client) → `tunnel{tunnel_id,dir,spec}` → `conn{conn_id,tunnel_id,
  peer,proto}`. Server-side conn span now uses the real `conn_id` from
  `ServerState::register_conn`; client-side falls back to a local
  counter when admin tracking is off.
- Every conn emits structured `conn opened` / `conn closed` events; the
  close line carries `bytes_in`, `bytes_out` (snapshotted from the
  `ConnGuard` before drop), and `dur_ms`.
- Subcommand subscribers (`ctl`, `cert`) collapsed into a shared
  `init_simple_logger` so they pick up `RUST_LOG` overrides too.
- Cargo.toml: enabled the `env-filter`/`fmt`/`ansi`/`json`/`time`
  features on `tracing-subscriber` and added `time` for the timestamp
  format description.
- Messages rewritten throughout server/, client/, common/{tcp,udp,
  socks,proxy,tunnel,quic}, server/admin, lib: lowercase, terse,
  present-tense, key-value structured fields instead of inline format
  args.
- README: marked the `RUST_LOG` TODO done and added a Logging section
  with the schema, flags, and a real example trace.

Co-authored-by: Cursor <cursoragent@cursor.com>
@guyte149
guyte149 merged commit cffa5ce into master May 5, 2026
1 check passed
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.

1 participant