Log as JSON for Loki #91

New Issue

rays · 2026-09-29T06:51:48-07:00

rays commented

2026-09-29 06:51:48 -07:00

The log is text, so the Grafana dashboard (grafana/dashboard.py) picks lines apart with regular expressions: the access log's 'GET /x -> 200 in 3ms' and the events' '<- {json}'. Logged as JSON with the request's method, path, status and time, and each event's fields, as fields, Loki's json parser reads them directly and a change of wording breaks nothing.

rays added the enhancement label 2026-09-29 06:51:48 -07:00

rays referenced this issue from a commit

2026-09-29 06:55:53 -07:00

Log as JSON when IPX_LOG_FORMAT=json (#91)

rays commented

2026-09-29 07:07:40 -07:00

Fixed in 4f8b3d6: IPX_LOG_FORMAT=json logs one JSON object a line, with the access log's method, path, route, status and ms and each event's fields as fields. Production sets it; the Grafana dashboard reads the fields with Loki's json parser. Deployed.

Fixed in 4f8b3d6: IPX_LOG_FORMAT=json logs one JSON object a line, with the access log's method, path, route, status and ms and each event's fields as fields. Production sets it; the Grafana dashboard reads the fields with Loki's json parser. Deployed.

rays closed this issue

2026-09-29 07:07:41 -07:00

rays commented

2026-09-29 08:08:13 -07:00

Follow-up from Dash0's structured logging guide (https://www.dash0.com/guides/structured-logging-for-modern-applications), checked against what production logs now (4f8b3d6). These are the parts that apply to ipx, most useful first.

1. Put the trace id on every log line. The guide's main point: log lines carry trace_id and span_id so a log line and its trace can be joined. Ours don't. A line has span (name, feed), but nothing that leads to Tempo. query.py trace only shows log lines because tracing-opentelemetry also records them as span events, and that doesn't work in the other direction: from a feed_error or a slow ipx::http line in Loki there is no way to find its trace. The fix is to add the OTel context to the JSON formatter's fields (tracing-opentelemetry's OtelData on the current span, via a custom FormatEvent or a layer that records it). A Loki derived field on trace_id then links each line to Tempo in Grafana. This also covers the guide's "propagate a request id": the trace id is that id, for requests and scans both.

2. Record failures as fields, not as sentences. The guide wants errors structured (exception.type, exception.message in OTel's naming) rather than written into the message. Ours:

ipx::scan warnings are only a message: gizmodo: error: HTTP 404 Not Found. The ipx::io line for the same event has feed and msg, but msg is still one string holding the status, the DNS failure or the redirect loop.
Grouping failures by kind ("how many 404s this week", "every DNS failure") means a regex over msg. That's the same text-parsing #91 set out to remove.
Add http.response.status_code where there is one, and an error.type taken from what explain_failure in src/feed.rs already works out (http_404, dns, redirect_loop, forbidden, timeout, ...), to feed_error and download_error.
Elsewhere, error = ?e (Debug) and error = %e (Display) are mixed, in main.rs:466/472 and access.rs among others. Pick one, Display with {:#} for the anyhow chain, so the field reads the same everywhere.

3. Units in field names. The guide recommends duration_ms over ms. bytes already says what it is; ms mostly does. Renaming ms breaks the Grafana panels and ipx-prod-check's queries (CLAUDE.md: rename a field and its panels go blank), so only do it together with regenerating grafana/dashboard.py and updating the skill. Low value on its own. Any new field should carry its unit from the start, though.

4. One event, one line. Every scan event is logged twice, once as ipx::io (fields) and once as ipx::scan (the same thing in words, and the only one at WARN). The ipx::io message is also the whole event again as JSON text (<- {"ev":...}) beside the flattened fields. In JSON mode, one line per event would do: the ipx::io line at the event's own level (WARN for failures), with a short human message. The text format for a terminal can stay as it is. That halves the volume Loki stores and makes check 1 in ipx-prod-check (warnings grouped by message) group by feed properly.

Not needed here:

severityNumber and a separate body/attributes split: that is the OTLP log data model, and ipx ships to Loki, where level and flattened fields are what LogQL wants.
service.name and resource attributes: Alloy labels the stream with container. Worth adding only if logs ever go over OTLP next to the traces.
Parsing old unstructured lines: the text lines before 2026-09-29 14:00 UTC age out of Loki on their own.
The guide's advice to add "as many high-cardinality attributes as you can" applies to fields, never to Loki labels. feed, path and trace_id must stay in the line, not in stream labels.

Follow-up from Dash0's structured logging guide (https://www.dash0.com/guides/structured-logging-for-modern-applications), checked against what production logs now (4f8b3d6). These are the parts that apply to ipx, most useful first. **1. Put the trace id on every log line.** The guide's main point: log lines carry `trace_id` and `span_id` so a log line and its trace can be joined. Ours don't. A line has `span` (name, feed), but nothing that leads to Tempo. `query.py trace` only shows log lines because tracing-opentelemetry also records them as span events, and that doesn't work in the other direction: from a `feed_error` or a slow `ipx::http` line in Loki there is no way to find its trace. The fix is to add the OTel context to the JSON formatter's fields (tracing-opentelemetry's `OtelData` on the current span, via a custom `FormatEvent` or a layer that records it). A Loki derived field on `trace_id` then links each line to Tempo in Grafana. This also covers the guide's "propagate a request id": the trace id is that id, for requests and scans both. **2. Record failures as fields, not as sentences.** The guide wants errors structured (`exception.type`, `exception.message` in OTel's naming) rather than written into the message. Ours: - `ipx::scan` warnings are only a message: `gizmodo: error: HTTP 404 Not Found`. The `ipx::io` line for the same event has `feed` and `msg`, but `msg` is still one string holding the status, the DNS failure or the redirect loop. - Grouping failures by kind ("how many 404s this week", "every DNS failure") means a regex over `msg`. That's the same text-parsing #91 set out to remove. - Add `http.response.status_code` where there is one, and an `error.type` taken from what `explain_failure` in src/feed.rs already works out (`http_404`, `dns`, `redirect_loop`, `forbidden`, `timeout`, ...), to `feed_error` and `download_error`. - Elsewhere, `error = ?e` (Debug) and `error = %e` (Display) are mixed, in main.rs:466/472 and access.rs among others. Pick one, Display with `{:#}` for the anyhow chain, so the field reads the same everywhere. **3. Units in field names.** The guide recommends `duration_ms` over `ms`. `bytes` already says what it is; `ms` mostly does. Renaming `ms` breaks the Grafana panels and `ipx-prod-check`'s queries (CLAUDE.md: rename a field and its panels go blank), so only do it together with regenerating `grafana/dashboard.py` and updating the skill. Low value on its own. Any new field should carry its unit from the start, though. **4. One event, one line.** Every scan event is logged twice, once as `ipx::io` (fields) and once as `ipx::scan` (the same thing in words, and the only one at WARN). The `ipx::io` message is also the whole event again as JSON text (`<- {"ev":...}`) beside the flattened fields. In JSON mode, one line per event would do: the `ipx::io` line at the event's own level (WARN for failures), with a short human message. The text format for a terminal can stay as it is. That halves the volume Loki stores and makes check 1 in `ipx-prod-check` (warnings grouped by message) group by feed properly. **Not needed here:** - `severityNumber` and a separate `body`/`attributes` split: that is the OTLP log data model, and ipx ships to Loki, where `level` and flattened fields are what LogQL wants. - `service.name` and resource attributes: Alloy labels the stream with `container`. Worth adding only if logs ever go over OTLP next to the traces. - Parsing old unstructured lines: the text lines before 2026-09-29 14:00 UTC age out of Loki on their own. - The guide's advice to add "as many high-cardinality attributes as you can" applies to fields, never to Loki labels. `feed`, `path` and `trace_id` must stay in the line, not in stream labels.

rays reopened this issue

2026-09-29 08:08:13 -07:00

rays referenced this issue from a commit

2026-09-29 09:25:56 -07:00

Trace ids, failure kinds and one line per event in the JSON log (#91)

rays commented

2026-09-29 09:28:09 -07:00

Fixed in 448e557, all four follow-ups: JSON lines inside a traced span carry trace_id and span_id (the access log included, now written inside its request's span); feed and download failures carry error.type and http.response.status_code; each scan event is one line under ipx::scan (the wire copy is at debug, for the admin page); the access log's ms is duration_ms. grafana/dashboard.py and the ipx-prod-check skill follow, and the dashboard is regenerated. Deployed 2026-09-29 16:26 UTC. Tempo's link to Loki (filterByTraceID) now finds lines; the link the other way, Loki to Tempo, needs a derived field on trace_id in the monitoring project's loki.yaml, which is outside this repo.

Fixed in 448e557, all four follow-ups: JSON lines inside a traced span carry trace_id and span_id (the access log included, now written inside its request's span); feed and download failures carry error.type and http.response.status_code; each scan event is one line under ipx::scan (the wire copy is at debug, for the admin page); the access log's ms is duration_ms. grafana/dashboard.py and the ipx-prod-check skill follow, and the dashboard is regenerated. Deployed 2026-09-29 16:26 UTC. Tempo's link to Loki (filterByTraceID) now finds lines; the link the other way, Loki to Tempo, needs a derived field on trace_id in the monitoring project's loki.yaml, which is outside this repo.

rays closed this issue

2026-09-29 09:28:10 -07:00

rays commented

2026-09-29 09:35:27 -07:00

Loki to Tempo is linked too: /mnt/fast/arcane/projects/monitoring/grafana-provisioning/datasources/loki.yaml has a derived field matching "trace_id":"..." in a line, pointing at Tempo (uid P214B5B846CF3925F). Grafana restarted to load it.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: rays/ipx#91