Repository navigation
feat(telemetry): add JSON log format - #2044
Conversation
Compact log lines can only be searched by matching their text, so fields
cannot be queried directly, multi-line errors split across lines, and any
query that matches the line text is tied to how events happen to print.
`log_format: json` (DWCTL_LOG_FORMAT) writes one JSON object per event,
fields at the top level and the span list under `spans`. `compact` stays the
default.
Switching formats must not lose error logs, so:
- In JSON mode a panic is written to stderr as one JSON error line. The
hook writes it directly instead of emitting a tracing event, which a
RUST_LOG directive or a panic inside the subscriber could drop.
- A config that fails to load is logged in the format it asks for, when
log_format can still be read from it, and a server exiting with an error
logs it before exiting.
- Telemetry now starts before batch config validation, whose error was
emitted before any subscriber existed and so was never written.
- tracing-log is listed explicitly so log-crate events from dependencies
keep reaching the subscriber if default features are ever turned off.
The zero-token analytics error now records request_model and
response_model as plain strings rather than Debug-formatted Options, so
they read as values in either format. Queries that matched the old
`Some("...")` form need updating before this is deployed.
Refs DW-966
Deploying control-layer with
|
| Latest commit: |
33d82c5
|
| Status: | ✅ Deploy successful! |
| Preview URL: | https://585b996c.control-layer.pages.dev |
| Branch Preview URL: | https://feat-dw-966-structured-loggi.control-layer.pages.dev |
There was a problem hiding this comment.
All reported issues were addressed across 11 files
Reply with feedback, questions, or to request a fix.
View guided diff | Turn on auto-fix | Re-trigger cubic
Review follow-ups for the JSON log format: - main reports the error dwctl exits with once, through tracing when logging is up, and exits nonzero. Returning it from main also printed it as plain `Error: ...` lines beside the JSON line. - Logging is installed before the OTLP exporter is built, so an exporter setup error is reported in the configured format, and the `[OTLP]` startup prints become fields on the initialization event. - Panic lines carry the `span` and `spans` the panic happened in, as events do, so a panic can be tied to the request that caused it. - The docs no longer claim compact output is one line per event. Refs DW-966
There was a problem hiding this comment.
All reported issues were addressed across 3 files (changes from recent commits).
Reply with feedback, questions, or to request a fix.
View guided diff | Turn on auto-fix | Re-trigger cubic
…d-logging # Conflicts: # dwctl/src/request_logging/analytics_handler.rs
In JSON mode span fields only appear inside the `spans` array, which Loki's `json` parser does not look into, so the request ID could no longer be used as a key:value lookup. Services downstream of dwctl already log the same ID as a top-level `x_request_id`. A small layer records each span's correlation fields (x_request_id, edge_request_id, provider_request_id, trace_id), and the JSON formatter repeats them at the top level of every event inside that span, the innermost value winning and an event's own field taking precedence. Panic lines carry them too. The analytics handler, which runs after the response and outside the request span, now records the request's x_request_id on its own span so its errors can be found the same way. One query now finds a request across dwctl and the services it calls: `|= "<id>" | json | x_request_id="<id>"`. Refs DW-966
There was a problem hiding this comment.
All reported issues were addressed across 6 files (changes from recent commits).
Reply with feedback, questions, or to request a fix.
View guided diff | Turn on auto-fix | Re-trigger cubic
…d-logging # Conflicts: # Cargo.lock
Only x_request_id is on every request line. edge_request_id, trace_id and provider_request_id appear once known, and a panic outside every span or inside the subscriber has no span context. Refs DW-966
There was a problem hiding this comment.
0 issues found across 1 file (changes from recent commits).
Auto-approved: Adds opt-in JSON log format for dwctl telemetry with compact remaining the default; changes are confined to logging/telemetry setup, config parsing, docs, and analytics field formatting, with no effect on request handling or spend. The change is bounded and revertible.
View guided diff | Turn on auto-fix | Re-trigger cubic
Adds
log_format: compact | json(DWCTL_LOG_FORMAT).compactstays the default.jsonwrites one object per event:timestamp,level,message,target, the event's fields at the top level, and the spans underspanandspans(root first). Loki derivesdetected_levelfromlevel.The setting covers every process that runs the dwctl binary (server, batch daemon,
dwctl migrate), including onwards and fusillade, since they log through dwctl's subscriber.Request IDs as top-level keys
In JSON, span fields sit inside the
spansarray, and Loki'sjsonparser doesn't look into arrays. So every event inside a span that recordedx_request_id,edge_request_id,provider_request_idortrace_idalso carries them at the top level. The innermost value wins, and an event's own field takes precedence. Panic lines carry them as well. The analytics handler runs after the response, outside the request span, so it now records the request'sx_request_idon its own span. One query then finds a request across dwctl and any service that logsx_request_idthe same way:Not losing error logs in the switch
ERRORline withtarget: "panic", including thespan/spansthe panic happened in. The message starts like the default (thread '…' panicked at …). The hook writes the line itself, because a tracing event could be filtered out byRUST_LOGor never reach a subscriber if the panic happens inside one.mainreports the errordwctlexits with once, asdwctl exited with an error, in the configured format. That includes a config that fails to load (whenlog_formatcan still be read from it), an OTLP setup failure (logging is installed before the exporter is built) and a faileddwctl migrate. It's printed as plain text only if logging itself failed to start. Returning the error frommainused to print it a second time as plainError: …lines.[OTLP] …eprintln!lines are now fields on the "Telemetry initialized" event.batches.validate()emitted its error before telemetry started, so it was never written. Telemetry now starts first.log-crate events:tracing-logis listed explicitly, so events from dependencies that use thelogcrate still reach the subscriber if default features are ever disabled.Deploy note
The zero-token analytics error (
Successful generative response recorded zero tokens) now recordsrequest_model/response_modelas plain strings instead ofSome("…"). This changes its compact output too. Before deploying, update any query that matches the oldSome("…")form, and any that matches compact-only text such asWARN <span>:. Both formats can match during rollout, for example withrequest_model(?:=Some\(|":|=)"(?P<request_model>[^"\\]+)".Tests
telemetry::tests::json_logging_writes_every_error_as_one_json_lineruns the real initialization in a child process (it installs the global subscriber and panic hook). It checks that a tracing error with a multi-line field, alog-crate error and a panic each produce exactly one JSON line atERROR, with fields at the top level and the span list present.json_events_carry_their_spans_request_ids_at_the_top_levelcovers the request-ID lifting, andjson_log_lines_carry_request_id_at_top_levelchecks it on a real chat completion through the router.just lint rustandjust test rustpass locally (4238 tests).Refs DW-966
BEGIN_COMMIT_OVERRIDE
feat(telemetry): add JSON log format (#2044)
END_COMMIT_OVERRIDE