rays/ipx
1
0
Fork 0
Code Issues 1 Pull Requests Actions Packages Projects Releases Wiki Activity

Log as JSON when IPX_LOG_FORMAT=json (#91)

Browse Source 
The log was text, so the Grafana dashboard picked lines apart with
regular expressions, and a change of wording would have blanked its
panels. With IPX_LOG_FORMAT=json each line is one JSON object: the
access log carries method, path, route, status and ms as fields (the
route passed from the routing layer in the response's extensions), and
each wire event its ev, feed, new, downloaded, failed, bytes, msg and
the rest (log_wire), beside the old message. The two startup lines that
were println! are logged, so no line breaks the JSON. Text stays the
default, for a terminal. The dashboard reads the fields with Loki's json
parser, and groups requests by route rather than path.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Ray Slakinski
2026-09-29 13:55:50 +00:00
parent 8ce0a4cb27
commit 4f8b3d6a1d
10 changed files with 95 additions and 35 deletions
Download Patch File Download Diff File Expand all files Collapse all files

30
src/ipc.rs
View File

@@ -157,11 +157,7 @@ impl Emitter {
// The outbound half of the protocol, as it goes on the wire. Progress is the
// high-volume one, so it sits at debug.
if let Ok(json) = serde_json::to_string(&e) {
if matches!(e, Event::Progress { .. }) {
tracing::debug!(target: "ipx::io", "<- {json}");
} else {
tracing::info!(target: "ipx::io", "<- {json}");
}
log_wire(&json, matches!(e, Event::Progress { .. }));
}
// An error here only means nobody is listening yet.
let _ = tx.send(e.clone());
@@ -172,6 +168,28 @@ impl Emitter {
}
}
/// An event as it goes on the wire, `<- {json}`, with its fields as the log line's own as well,
/// so Loki reads `ev`, `feed`, `new` and the rest from the JSON log without parsing the message
/// (#91). A field an event lacks is left out.
fn log_wire(json: &str, debug: bool) {
let v: serde_json::Value = serde_json::from_str(json).unwrap_or_default();
let s = |k: &str| v.get(k).and_then(|x| x.as_str());
let n = |k: &str| v.get(k).and_then(|x| x.as_u64());
macro_rules! wire {
($level:ident) => {
tracing::$level!(
target: "ipx::io",
ev = s("ev"), feed = s("feed"), msg = s("msg"), url = s("url"), reason = s("reason"),
new = n("new"), downloaded = n("downloaded"), failed = n("failed"),
torrents = n("torrents"), bytes = n("bytes"), feeds = n("feeds"),
pending = n("pending"), enclosure = n("enclosure"), files = n("files"),
"<- {json}"
)
};
}
if debug { wire!(debug) } else { wire!(info) }
}
/// True when something is already listening -- i.e. a daemon owns this socket.
pub async fn daemon_is_live(path: &Path) -> bool {
UnixStream::connect(path).await.is_ok()
@@ -258,7 +276,7 @@ async fn handle(
tracing::info!(target: "ipx::io", "-> {line}");
let ev = status().await;
if let Ok(json) = serde_json::to_string(&ev) {
tracing::info!(target: "ipx::io", "<- {json}");
log_wire(&json, false);
}
let _ = reply.send(ev).await;
}

28
src/main.rs
View File

@@ -183,19 +183,32 @@ async fn main() -> Result<()> {
// Two filters, deliberately different. stderr follows IPX_LOG; the in-app buffer
// keeps debug as well, so the log view can show protocol traffic and routine
// skips that would be noise on a terminal. IPX_UI_LOG overrides it.
let stderr_filter = tracing_subscriber::EnvFilter::try_from_env("IPX_LOG")
.unwrap_or_else(|_| "ipx=info".into());
let stderr_filter = || {
tracing_subscriber::EnvFilter::try_from_env("IPX_LOG").unwrap_or_else(|_| "ipx=info".into())
};
// One JSON object a line for Loki (#91), with each event's fields as its own; text
// otherwise, for someone reading a terminal.
let json = std::env::var("IPX_LOG_FORMAT").is_ok_and(|f| f.eq_ignore_ascii_case("json"));
let ui_filter = tracing_subscriber::EnvFilter::try_from_env("IPX_UI_LOG")
.unwrap_or_else(|_| "ipx=debug".into());
tracing_subscriber::registry()
.with(
.with((!json).then(|| {
tracing_subscriber::fmt::layer()
.with_writer(std::io::stderr)
// Colour for a terminal only: in docker logs and Loki the escapes are noise
// every query has to strip (#88).
.with_ansi(std::io::IsTerminal::is_terminal(&std::io::stderr()))
.with_filter(stderr_filter),
)
.with_filter(stderr_filter())
}))
.with(json.then(|| {
tracing_subscriber::fmt::layer()
.json()
.flatten_event(true)
.with_current_span(true)
.with_span_list(false)
.with_writer(std::io::stderr)
.with_filter(stderr_filter())
}))
.with(logbuf::RingLayer.with_filter(ui_filter))
.with(otel.as_ref().map(|p| {
use opentelemetry::trace::TracerProvider;
@@ -575,12 +588,13 @@ async fn start_web(
ctx.set_cfg(fresh.clone());
// The token signs in as the admin, and whatever reads this process's output (docker logs,
// for one) is wider than who reads config.toml. So say where it is, never what it is.
println!(
// Logged, not printed, so a JSON log stays one object a line (#91).
tracing::info!(
"web ui token generated and saved to {} as [web] token. Open http://{bind}/?token=<that token>",
config_path.display()
);
} else {
println!(
tracing::info!(
"web ui at http://{bind}/ (the sign-in token is [web] token in {})",
config_path.display()
);

14
src/web.rs
View File

@@ -1941,7 +1941,10 @@ async fn name_span(route: MatchedPath, req: Request, next: Next) -> Response {
let span = tracing::Span::current();
span.context().span().update_name(format!("{} {}", req.method(), route.as_str()));
span.record("http.route", route.as_str());
next.run(req).await
let mut resp = next.run(req).await;
// For access_log, which runs outside routing and cannot see it otherwise.
resp.extensions_mut().insert(route);
resp
}
/// One line per HTTP request, so the web side shows up in the same log as the daemon.
@@ -1971,12 +1974,15 @@ async fn access_log(req: Request, next: Next) -> Response {
let resp = tracing::Instrument::instrument(next.run(req), span.clone()).await;
span.record("http.response.status_code", resp.status().as_u16());
if !quiet {
let ms = started.elapsed().as_millis();
let ms = started.elapsed().as_millis() as u64;
let status = resp.status().as_u16();
// The same as fields, for the JSON log (#91). Unrouted, a request has no route.
let route = resp.extensions().get::<MatchedPath>().map(|r| r.as_str().to_owned());
let method = method.as_str();
if resp.status().is_success() || resp.status().is_redirection() {
tracing::info!(target: "ipx::http", "{method} {path} -> {status} in {ms}ms");
tracing::info!(target: "ipx::http", method, path, route, status, ms, "{method} {path} -> {status} in {ms}ms");
} else {
tracing::warn!(target: "ipx::http", "{method} {path} -> {status} in {ms}ms");
tracing::warn!(target: "ipx::http", method, path, route, status, ms, "{method} {path} -> {status} in {ms}ms");
}
}
resp