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

Requests are counted in /metrics, and only a failed one is logged (#364)

Browse Source 
ipx logged a line for every request: 2,306 a day, over half its log by
size, repeating Caddy's access line and the request's span. It stayed
because ipx had no request metric and the dashboard's API row was built
on the line. /metrics now has ipx_http_request_duration_seconds, a
histogram by method, route and status (5 ms to 10 s), the event stream
left out as the panels left it out. The route is the pattern, "" for an
unrouted path, and an unusual method is "other", so a scanner cannot make
a row a request. A request that went well is logged at debug, which the
admin page's log view keeps; a failed one keeps its warning in Loki.

The dashboard's API row reads the histogram (the slowest-request series
becomes the 99th percentile, a bucket's bound; the slowest themselves are
in Tempo). prom() takes instant queries and table() a unit for it.

The prod-check skill, reviewed whole: check 3 reads the histogram; the
directory has metrics, which it said it had not; "all gauges" was half
counters; the healthcheck removed in #218 was still named three times;
Caddy's /api/events aborts (600 a week, a page closing its stream) are
filtered as by design; the monitoring section checks Tempo's block poll,
which failed on 2026-10-25 on one empty block and left every search with
only the last 15 minutes; and the lines to expect from each container
are counted over a day, now that iPX can be quiet for an hour.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Ray Slakinski
2026-10-25 15:11:20 +00:00
parent 6352324bcb
commit c788112190
6 changed files with 154 additions and 47 deletions
Download Patch File Download Diff File Expand all files Collapse all files

88
.claude/skills/ipx-prod-check/SKILL.md
View File

@@ -12,7 +12,7 @@ Production is three containers in the Arcane project `ipx` on Tower
|---|---|---|---|---|
| `ipx-web` | Caddy: serves the page, passes `/api` and `/media` to ipx (#203). Port 8099, the LAN and the tunnel | `{container="ipx-web"}`, JSON: a line a request (`http.log.access`), its own errors | service `ipx-web`: a span a request, passing `traceparent` on to ipx (#213) | none |
| `iPX` | the daemon: API, scans, downloads, DeadAir | `{container="iPX"}`, JSON (`IPX_LOG_FORMAT=json`) | service `ipx`; passes `traceparent` to the directory | `job="ipx"`, its `/metrics` |
| `ipx-directory` | the directory of public podcasts, `directory.ipxreader.app` (#204, #214) | `{container="ipx-directory"}`, JSON (`DIRECTORY_LOG_FORMAT=json`) | service `ipx-directory`: a span a request, joining ipx's trace when ipx called; a trace a refresher round (#213) | none |
| `ipx-directory` | the directory of public podcasts, `directory.ipxreader.app` (#204, #214) | `{container="ipx-directory"}`, JSON (`DIRECTORY_LOG_FORMAT=json`) | service `ipx-directory`: a span a request, joining ipx's trace when ipx called; a trace a refresher round (#213) | `job="ipx-directory"`, its `/metrics` |
Under them, Tower itself: `job="node"` (the node exporter: load, CPU, memory, disks). The Grafana
dashboard `iPX` draws all of it in that order (`grafana/dashboard.py`). A trace without the
@@ -60,18 +60,23 @@ Lines inside a traced span, requests and scans, also carry `trace_id` and `span_
lines had no trace id, the access log's time was `ms`, and each event was logged twice, words under
`ipx::scan` and fields under `ipx::io`.)
What is routine is logged at debug, which goes to the admin page's Log view and not to Loki: a
request that went well (#364), a scan's end (`scan_done`, #363), a feed not due (`feed_skip`), a
feed starting (`feed_start`), and a feed that brought nothing (`feed_done` with every count 0).
Count those from the metrics, not the log.
| target | fields | what |
|---|---|---|
| `ipx::http` | `method`, `path`, `route`, `status`, `duration_ms` | one per web request; `route` is the pattern, empty for an unrouted path |
| `ipx::http` | `method`, `path`, `route`, `status`, `duration_ms` | a warning for each request answered 4xx or 5xx; `route` is the pattern, empty for an unrouted path. Every request, as info, until #364; now those that went well are only in `ipx_http_request_duration_seconds` |
| `ipx::scan` | `ev` and the event's own: `feed`, `new`, `downloaded`, `failed`, `bytes`, `msg`, `url`, `feeds`, `reason`, `from`, `to`; on a failure `error.type` and, from an HTTP error, `http.response.status_code` | the daemon's events, one line each, in words; warnings are feed and download failures |
| `ipx::io` | `ev`, `feeds`, `pending`, `downloaded` on the `status` reply | commands arriving (`-> {...}`) and the healthcheck's answer |
| `ipx::io` | `ev`, `feeds`, `pending`, `downloaded` on the `status` reply | commands arriving on the socket (`-> {...}`) and the answer to `ipx status` |
| `ipx::daemon`, `ipx::cli`, `ipx::catalogue`, `ipx::scan`, ... | message, sometimes fields | start-up, shutdown, account and config messages, under the module that logs them; plain `ipx` before 2026-10-24, when main.rs was split (#356) |
| `ipx::client` | `ev`, `user`, `feed`, `enclosure`, `deadair`; `msg`, `src`, `line` on an error; `ms` on a timing | what the page reports from the browser (#190): `page_error`, `rejection` and `player_error` as warnings; `play_start` (ms from play to sound), `stall` (ms waiting mid-play) and `list_shown` (ms from a click to its list drawn, with `feed` the view and `filter`, #246) as info. Lines carry the trace of the action in the page: its API requests send `traceparent`, one trace id per tap or key |
Events (`ev`): `feed_start`, `feed_done` (new, downloaded, failed, torrents), `feed_skip` (not due,
routine), `feed_error` (msg), `feed_moved` (from, to: a permanent redirect followed, the address
Events (`ev`): `feed_start` (debug), `feed_done` (new, downloaded, failed, torrents), `feed_skip`
(not due, debug), `feed_error` (msg), `feed_moved` (from, to: a permanent redirect followed, the address
updated), `download_done` (bytes), `download_error` (msg, url),
`torrent_deferred`, `reaped`, `reap_done`, `status` (feeds, pending, downloaded: the answer to
`torrent_deferred`, `reaped`, `reap_done`, `scan_done` (feeds; debug), `status` (feeds, pending, downloaded: the answer to
`ipx status`, only when someone runs it since #218), `deadair_done` (feed, enclosure, `saved_s` at the
default pause), `error` (msg). DeadAir also logs `DeadAir found the silences` (`cuts`, `saved_s`,
`took_ms`) under `ipx::deadair`, and warns `DeadAir could not read a file` when ffmpeg fails on
@@ -89,7 +94,7 @@ cheaper than parsing every line. Lines before 2026-09-29 14:00 UTC are text, not
The daemon's own state between requests, which no log line or trace holds (#194): ipx serves
`/metrics` on `[web] metrics_bind` (production: `192.168.1.130:9187`, LAN only), on a thread and
port of its own, from memory alone, and Prometheus scrapes it every 15 s as `job="ipx"`. Kept
from 2026-10-11 15:15 UTC. All gauges:
from 2026-10-11 15:15 UTC. Gauges, but for the counters (`_total`) and the one histogram:
| metric | what |
|---|---|
@@ -102,10 +107,11 @@ from 2026-10-11 15:15 UTC. All gauges:
| `ipx_process_resident_bytes`, `ipx_process_open_fds` | memory and open files and sockets; mimalloc gives back what is freed, so memory follows use and a rise that never comes down is a leak (#224) |
| `ipx_feed_fetches_total`, `ipx_feed_bytes_total` | counters: feeds fetched (304s included) and the bytes of their bodies, read whole, so what scans allocate |
| `ipx_uptime_seconds`, `ipx_build_info{version}` | since the daemon started; what runs |
| `ipx_worker_busy`, `ipx_worker_job_seconds{kind}` | the worker's job now (`scan`, `reap`, `download`, `status`, `reload`) and for how long; the healthcheck passes while it is stuck |
| `ipx_worker_busy`, `ipx_worker_job_seconds{kind}` | the worker's job now (`scan`, `reap`, `download`, `status`, `reload`) and for how long; `ipx status` still answers while it is stuck |
| `ipx_jobs_total{kind}`, `ipx_job_seconds_total{kind}` | counters: jobs finished, and their seconds all told |
| `ipx_last_scan_age_seconds` | since a scan last finished; absent until one has since starting |
| `ipx_http_requests_in_flight`, `ipx_scan_feeds_fetching`, `ipx_downloads_active` | work in progress |
| `ipx_http_request_duration_seconds{method,route,status}` | histogram: each request answered and its seconds, buckets 5 ms to 10 s; `_count` is requests, `_sum` their time. `route` is the pattern, `""` for an unrouted path; the event stream is left out (#364). From 2026-10-25 |
| `ipx_download_bytes_total` | counter; `rate()` is the download speed |
| `ipx_event_queue`, `ipx_events_missed_total` | live updates unread by some listener; counter of those dropped for one that fell behind |
| `ipx_deadair_backlog`, `ipx_deadair_busy_seconds` | files of shows with DeadAir on not yet looked at (episodes everyone heard through stay counted); how long it has been on its file |
@@ -117,7 +123,7 @@ from 2026-10-11 15:15 UTC. All gauges:
| `ipx_jev_tokens_total{kind="input"\|"output",user,key}` | counter: tokens TypeSafe counted, as its answers say, by person and whose key paid: what Signals, icon picks and key checks cost (#275, #278). A call shared on the server's key is split by each person's share of its questions |
| `ipx_signals_last_pass_age_seconds`, `ipx_signals_keys_refused` | since the Signals judge last finished a pass (at most 5 minutes when well; absent until one has); people whose key TypeSafe refused |
| `directory_process_resident_bytes`, `directory_process_open_fds`, `directory_feed_fetches_total`, `directory_feed_bytes_total`, `directory_uptime_seconds`, `directory_build_info` | the directory's, `job="ipx-directory"`, from its `metrics_bind` (production `192.168.1.130:9188`, LAN only) |
| `ipx_feeds`, `ipx_downloads_pending`, `ipx_files_downloaded` | the library, as the healthcheck last counted it (every 30 s) |
| `ipx_feeds`, `ipx_downloads_pending`, `ipx_files_downloaded` | the library, as the daemon counts it every 30 s |
### The checks
@@ -140,11 +146,15 @@ a count says something happened, the lines and traces say why.
browser, a redirect loop ipx should follow, or the same failure on many feeds at once is ipx.
3. **Server errors and slow requests.**
```
$Q metric 'sum by (method, route, status) (count_over_time({container="iPX"} |= "\"target\":\"ipx::http\"" | json | __error__="" | status >= 500 [$range]))'
$Q metric 'topk(10, quantile_over_time(0.95, {container="iPX"} |= "\"target\":\"ipx::http\"" | json | __error__="" | route != "" | route != "/api/events" | unwrap duration_ms [$range]) by (method, route))'
$Q prom 'sum by (method, route, status) (increase(ipx_http_request_duration_seconds_count{job="ipx",status=~"4..|5.."}[$range])) > 0' 24h
$Q prom 'topk(10, histogram_quantile(0.95, sum by (method, route, le) (rate(ipx_http_request_duration_seconds_bucket{job="ipx",route!=""}[$range]))))' 24h
$Q logs '{container="iPX"} |= "\"target\":\"ipx::http\""' 24h
```
Any 5xx is worth a look. 401s are people signing in, not a problem unless one address is
hammering. For a slow route, find its traces (check 5) and see which span holds the time.
Any 5xx is worth a look; the log has each failed request's own line, with its trace id. 401s
are people signing in, not a problem unless one address is hammering. The 95th percentile is
read off the buckets, so it says which bucket, not the exact time: for a slow route, find its
spans (check 5) and see which step holds the time. The histogram restarts at 0 with the daemon,
which `increase` and `rate` allow for.
4. **Is the worker keeping up?** Scans should finish regularly, the queue should drain, and the
daemon should not be restarting on its own.
```
@@ -174,6 +184,10 @@ a count says something happened, the lines and traces say why.
$Q traces '{resource.deployment.environment.name="production" && status = error}'
$Q trace <id>
```
Tempo keeps about two weeks. A trace id from a log line that Tempo answers 404 for, or a
search that finds only the last quarter of an hour, is Tempo not reading its stored blocks: see
the monitoring section.
Group the first by hour and by route (`awk '{print substr($3,1,2), $NF}' | sort | uniq -c`),
then lay the hours beside Tower's (the Tower section): load over 100 with processes blocked
and memory under 4 GB is the host stalling, and every request of those minutes is slow with
@@ -229,7 +243,7 @@ a count says something happened, the lines and traces say why.
reset of the uptime is a restart: match it with a deploy, or it is a crash (check 4).
The worker: one job over 30 minutes (`ipx_worker_job_seconds`), or a scan last finished over
15 minutes ago, is the worker stuck, which the healthcheck does not notice; its trace and the
15 minutes ago, is the worker stuck, which `ipx status` does not show; its trace and the
log lines of that time say on what. A kind whose share of `ipx_job_seconds_total` jumps is
where the worker's time went (reap was most of it until #193). Web requests in flight near
the pool's max mean the pool is what they wait on. Live updates missed mean a page showed stale
@@ -257,23 +271,25 @@ a count says something happened, the lines and traces say why.
Caddy logs one JSON line a request (#210), logger `http.log.access.log0`: Loki's `| json` gives
`request_uri`, `request_method`, `request_remote_ip`, `status`, `duration` (seconds, not ms), `size`.
The request's headers and a `?token=` are filtered out before it is written. Requests from
`127.0.0.1` are local checks; leave them out. `/api` and `/media` pass on to ipx and
are in ipx's own access log too, with ipx's time; Caddy's `duration` for them adds the hop.
`127.0.0.1` are local checks; leave them out. `/api` and `/media` pass on to ipx, which counts
them in `ipx_http_request_duration_seconds` with its own time; Caddy's `duration` for them adds
the hop. This is the only log with a line for every request.
```sh
W='{container="ipx-web"} |= "http.log.access" | json | __error__="" | request_remote_ip != "127.0.0.1"'
$Q metric "sum by (status) (count_over_time($W [\$range]))"
$Q metric "sum by (request_uri) (count_over_time($W | status >= 500 [\$range]))"
$Q metric "topk(10, quantile_over_time(0.95, $W | request_uri !~ \"/(api|media)/.*\" | unwrap duration [\$range]) by (request_uri))"
$Q logs '{container="ipx-web"} | json | __error__="" | level=~"warn|error" | msg !~ "admin endpoint disabled|automatic HTTPS is completely disabled|HTTP/[23] skipped.*|exiting; byeee.*"'
$Q logs '{container="ipx-web"} | json | __error__="" | level=~"warn|error" | msg !~ "admin endpoint disabled|automatic HTTPS is completely disabled|HTTP/[23] skipped.*|exiting; byeee.*" | request_uri != "/api/events"'
```
A 502 is ipx not answering Caddy: a restart (match the deploy) or ipx down; Caddy's error line
names it (`dial tcp ...:8099: connect: connection refused`). The page itself (`/`, `/admin`)
waits on `/api/page-check` before it is sent, so a slow page is usually a slow page-check: look it
up in ipx's access log. 401 and 303 on `/` are people signed out being sent to `/login`, not a
waits on `/api/page-check` before it is sent, so a slow page is usually a slow page-check: its
route in the histogram (check 3), or ipx's span inside Caddy's in the trace. 401 and 303 on `/` are people signed out being sent to `/login`, not a
problem. Caddy's own notices at each start (no admin endpoint, no HTTPS or HTTP/3, its goodbye on
SIGTERM) are by design and filtered out above.
SIGTERM) are by design and filtered out above, and so is `aborting with incomplete response` on
`/api/events`: a page closing or reconnecting its live-update stream, about 600 a week.
Each access line carries the request's `traceID` (`| json` gives `traceID`): give it to `$Q trace`
to see where the time went, Caddy's span with ipx's inside it. A slow page with ipx's span short is
@@ -298,7 +314,10 @@ It logs a line a request (`target` `ipx_directory::http`: `method`, `path`, `sta
line a refresher round (`feeds checked`: `checked`), a line a failed feed check (`feed check
failed`: `feed`, the directory's id, and `error`), the admin's actions (`feed removed and
blocked`, `feed unblocked`, `snapshot dropped`, each with `by`), and `config read again` when its
token file changes. It has no metrics. Its traces (#213): a span a request (`http`), a child of
token file changes. Its lines carry their own fields and no span (#363). Its metrics, as
`job="ipx-directory"` (production `192.168.1.130:9188`): `directory_process_resident_bytes`,
`directory_process_open_fds`, `directory_feed_fetches_total`, `directory_feed_bytes_total`,
`directory_uptime_seconds`, `directory_build_info`. Its traces (#213): a span a request (`http`), a child of
ipx's when ipx called with a `traceparent`, and a trace a refresher round (`refresh`, `feeds`)
with a `feed` span for each check. Its log lines carry no trace id; find the trace by time or by
the feed.
@@ -368,11 +387,26 @@ container's lines are reaching Loki:
```sh
curl -s http://192.168.1.130:9090/api/v1/targets | python3 -c 'import json,sys
for t in json.load(sys.stdin)["data"]["activeTargets"]: print(t["health"], t["labels"]["job"], t["scrapeUrl"], t.get("lastError","")[:80])'
for c in iPX ipx-web ipx-directory; do echo "$c $($Q metric "sum(count_over_time({container=\"$c\"} [1h]))" 1h | tail -1)"; done
for c in iPX ipx-web ipx-directory; do echo "$c $($Q metric "sum(count_over_time({container=\"$c\"} [24h]))" 24h | tail -1)"; done
docker ps -a --filter label=com.docker.compose.project=monitoring --format '{{.Names}} {{.Status}}'
docker logs --since 1h tempo 2>&1 | grep -E 'failed to poll|blocklist poll complete' | tail -2
```
`ipx` and `node` should be `up`. Every monitoring container should be running; after Docker
`ipx`, `ipx-directory` and `node` should be `up`.
Tempo looks over its stored blocks every 5 minutes. `failed to poll or create index for tenant`
means it could not, and then searches and trace lookups see only what it still holds in memory,
about the last 15 minutes, while its 2,000 blocks sit unread on disk (its search log says
`total_blocks=0`). On 2026-10-25 that was one block left empty, every file 0 bytes, by a write cut
short the night before: `unexpected end of JSON input`. Find it and move it out of
`/mnt/user/logs/tempo/blocks/single-tenant/`; the next look over, within 5 minutes, logs
`writing tenant index` and finds the rest. Tell the user, since it is the monitoring's, not ipx's:
```sh
for d in /mnt/user/logs/tempo/blocks/single-tenant/*/; do python3 -c 'import json,sys; json.load(open(sys.argv[1]))' "$d/meta.json" 2>/dev/null || echo "$d"; done
```
Every monitoring container should be running; after Docker
restarts, one can be left `Exited (255)` though its policy is `unless-stopped` (Prometheus, on
2026-10-12, when Docker lost its exit during an overload): `docker start` it and say so. blocky
and nut on 192.168.2.21 are another machine, not ipx's; leave them. A container with no lines in
@@ -410,6 +444,8 @@ check is for finding them.
## When the checks come back empty
Check that there is data before concluding all is well (the monitoring section's per-container
count): iPX should have hundreds of lines an hour or more, ipx-web at least its healthchecks'
120, ipx-directory a few dozen. Nothing at all means Alloy is not shipping it, or the container
is down.
count over a day): iPX a few hundred (new items, Signals, shares with the directory, the page's
timings; more on a busy day), ipx-web two thousand or so while the page is in use (a line a
request), ipx-directory several hundred. Since #363 and #364 iPX can go an hour at night with no
line at all, so judge it by the day. Nothing in a day means Alloy is not shipping it, or the
container is down.

10
CLAUDE.md
View File

@@ -318,10 +318,12 @@ ms in ipx, the difference being new connections, 80-330 ms each to open (#241).
watch the shutdown channel itself; the daemon ignored SIGTERM for exactly this reason.
* Only one daemon per socket. Removing the socket file defeats the guard and you get two daemons
fighting over the database, with the stale one still holding the port.
* **The Grafana dashboard reads the log's fields** (`grafana/dashboard.py`). Production logs JSON
(`IPX_LOG_FORMAT=json`); the access log's `method`, `path`, `route`, `status`, `duration_ms` and
the events' `ev`, `feed`, `new`, `bytes`, `msg` (`log_event` in ipc.rs) are what the panels query.
Rename one and its panels go blank without an error; regenerate the dashboard to match.
* **The Grafana dashboard reads the log's fields and the metrics' names** (`grafana/dashboard.py`).
Production logs JSON (`IPX_LOG_FORMAT=json`); the events' `ev`, `feed`, `new`, `bytes`, `msg`
(`log_event` in ipc.rs) and the metrics in metrics.rs (requests are
`ipx_http_request_duration_seconds`, #364) are what the panels query. Rename one and its panels
go blank without an error; regenerate the dashboard to match. Routine lines (a request that went
well, a scan's end) are debug: the admin page's Log view has them, Loki does not.
* `/api/settings` answering `200` does **not** mean the daemon is well — the web server is a
different task. `ipx status` checks the control socket and the database; to see the worker
getting through its jobs, watch for `scan complete` in the log.

1
crates/ipx/CHANGELOG.md
View File

@@ -14,6 +14,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
### Changed
- The log no longer has a line for every request that went well, over half its size: `/metrics` counts each request and its time by route and status as `ipx_http_request_duration_seconds`, a request that failed keeps its warning, and the admin page's log view still shows them all (#364).
- The log no longer has a line for every scan that finishes, a fifth of its lines; the metrics count scans, and the page's log view still shows them (#363).
### Fixed

57
crates/ipx/src/metrics.rs
View File

@@ -62,8 +62,17 @@ pub struct Stats {
job: std::sync::Mutex<Option<(&'static str, Instant)>>,
/// Jobs finished, by kind: how many, and their seconds all told.
jobs: std::sync::Mutex<BTreeMap<&'static str, (u64, f64)>>,
/// Requests answered, by method, route and status: how many within each of `HTTP_BUCKETS`,
/// how many all told, and their seconds. What the access log's lines were read for (#364).
http: std::sync::Mutex<BTreeMap<(&'static str, String, u16), Requests>>,
}
/// The upper bounds, in seconds, a request's time is counted under: most of ipx's answer in tens
/// of milliseconds, and a slow one, a host stalling, in seconds.
const HTTP_BUCKETS: [f64; 11] = [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0];
type Requests = ([u64; HTTP_BUCKETS.len()], u64, f64);
impl Stats {
pub const fn new() -> Self {
Self {
@@ -89,9 +98,26 @@ impl Stats {
people: std::sync::Mutex::new(BTreeMap::new()),
job: std::sync::Mutex::new(None),
jobs: std::sync::Mutex::new(BTreeMap::new()),
http: std::sync::Mutex::new(BTreeMap::new()),
}
}
/// Counts a request answered. `route` is the pattern matched, "" for none, so a scanner's
/// made-up paths are one row; a method outside the usual is "other", for the same reason.
pub fn request(&self, method: &str, route: &str, status: u16, secs: f64) {
let method = ["GET", "POST", "PUT", "PATCH", "DELETE", "HEAD", "OPTIONS"]
.into_iter()
.find(|m| *m == method)
.unwrap_or("other");
let mut http = self.http.lock().expect("a panic elsewhere poisoned this lock");
let (buckets, n, sum) = http.entry((method, route.to_owned(), status)).or_default();
for (b, le) in buckets.iter_mut().zip(HTTP_BUCKETS) {
*b += u64::from(secs <= le);
}
*n += 1;
*sum += secs;
}
/// Adds to what `who` used on `key` ("server" or "own"): items judged, fits, input and output
/// tokens.
pub fn bill(&self, who: &str, key: &'static str, used: [f64; 4]) {
@@ -308,6 +334,19 @@ fn work(out: &mut String, st: &Stats, event_queue: usize, retries: usize, art_li
"Web requests being answered.",
&[("", st.http_in_flight.load(Relaxed) as f64)],
);
let http = st.http.lock().expect("a panic elsewhere poisoned this lock").clone();
let name = "ipx_http_request_duration_seconds";
let _ = writeln!(
out,
"# HELP {name} Web requests answered and the seconds each took, by method, route and status.\n# TYPE {name} histogram"
);
for ((method, route, status), (buckets, n, sum)) in &http {
let l = format!("method=\"{method}\",route=\"{}\",status=\"{status}\"", label(route));
for (le, b) in HTTP_BUCKETS.iter().zip(buckets) {
let _ = writeln!(out, "{name}_bucket{{{l},le=\"{le}\"}} {b}");
}
let _ = writeln!(out, "{name}_bucket{{{l},le=\"+Inf\"}} {n}\n{name}_sum{{{l}}} {sum}\n{name}_count{{{l}}} {n}");
}
gauge(
out,
"ipx_scan_feeds_fetching",
@@ -512,6 +551,24 @@ mod tests {
assert!(out.contains("ipx_jev_tokens_total{kind=\"output\",user=\"a \\\"b\\\"\",key=\"own\"} 1\n"), "{out}");
// The library's counts are left out until the daemon has counted it.
assert!(!out.contains("ipx_feeds "));
for secs in [0.03, 0.04, 2.0] {
T.request("GET", "/api/feeds", 200, secs);
}
T.request("PROPFIND", "", 404, 0.001);
let mut out = String::new();
work(&mut out, &T, 0, 0, 0);
let l = "method=\"GET\",route=\"/api/feeds\",status=\"200\"";
for line in [
format!("ipx_http_request_duration_seconds_bucket{{{l},le=\"0.025\"}} 0\n"),
format!("ipx_http_request_duration_seconds_bucket{{{l},le=\"0.05\"}} 2\n"),
format!("ipx_http_request_duration_seconds_bucket{{{l},le=\"2.5\"}} 3\n"),
format!("ipx_http_request_duration_seconds_bucket{{{l},le=\"+Inf\"}} 3\n"),
format!("ipx_http_request_duration_seconds_count{{{l}}} 3\n"),
"ipx_http_request_duration_seconds_count{method=\"other\",route=\"\",status=\"404\"} 1\n".into(),
] {
assert!(out.contains(&line), "{line} in {out}");
}
}
#[test]

9
crates/ipx/src/web.rs
View File

@@ -2859,10 +2859,17 @@ async fn access_log(req: Request, next: Next) -> Response {
// 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();
// The event stream's time is its first byte, not the minutes it stays open.
if path != "/api/events" {
let secs = started.elapsed().as_secs_f64();
crate::metrics::STATS.request(method, route.as_deref().unwrap_or(""), status, secs);
}
// Inside the request's span, so the line carries its trace id and leads to its trace.
let _in = span.enter();
if resp.status().is_success() || resp.status().is_redirection() {
tracing::info!(target: "ipx::http", method, path, route, status, duration_ms, "{method} {path} -> {status} in {duration_ms}ms");
// Debug: the metric above counts it, Caddy's access log and the span have it too,
// and it was over half the log (#364). The page's log view keeps debug.
tracing::debug!(target: "ipx::http", method, path, route, status, duration_ms, "{method} {path} -> {status} in {duration_ms}ms");
} else {
tracing::warn!(target: "ipx::http", method, path, route, status, duration_ms, "{method} {path} -> {status} in {duration_ms}ms");
}

36
grafana/dashboard.py
View File

@@ -8,7 +8,7 @@ top-down as a request does: an overview, Tower, then each container (ipx-web, ip
worker and its process, the directory), then traces and logs. Prometheus scrapes ipx's /metrics
(job ipx, #194) and Tower's node exporter (job node); nothing scrapes the containers themselves,
so ipx-web and the directory are read from their logs. The log panels read fields: ipx's
(web.rs access_log, ipc.rs log_event), the directory's and Caddy's; renaming one has to be
(ipc.rs log_event), ipx's metrics (metrics.rs), the directory's and Caddy's; renaming one has to be
matched here. `dashboard.py queries` prints each Loki query, to try against Loki.
"""
import json, sys
@@ -18,11 +18,13 @@ TEMPO = {"type": "tempo", "uid": "${tempo}"}
PROM = {"type": "prometheus", "uid": "${prometheus}"}
SEL = '{container="iPX"}'
# ipx logs one JSON object a line (IPX_LOG_FORMAT=json). Each scan and download event carries its
# fields (ev, feed, new, bytes, msg, error.type, ...); each request its method, path, route, status
# and duration_ms. Events are logged under ipx::scan, the healthcheck's status under ipx::io, so
# the filter is on the ev field, not the target.
# fields (ev, feed, new, bytes, msg, error.type, ...); a failed request its method, path, route,
# status and duration_ms. Events are logged under ipx::scan, `ipx status`'s answer under ipx::io,
# so the filter is on the ev field, not the target.
EV = SEL + ' |= "\\"ev\\":\\"" | json | __error__="" | ev != ""'
HTTP = SEL + ' |= "\\"target\\":\\"ipx::http\\"" | json | __error__="" | path != "/api/events"'
# Each request ipx answers, the event stream aside, as a histogram (#364): its line in the log is
# debug, so only a failed request's is in Loki.
REQ = "ipx_http_request_duration_seconds"
BAD = SEL + ' | json | __error__="" | level =~ "WARN|ERROR"'
TEXT = ' | line_format "{{.level}} {{.target}}: {{.message}}"'
# Every production span: ipx-web's, ipx's and the directory's, one trace from the page to the
@@ -70,9 +72,11 @@ def loki(expr, ref="A", legend=None, instant=False, kind=None):
return t
def prom(expr, ref="A", legend=None):
def prom(expr, ref="A", legend=None, instant=False):
# ipx's /metrics (#194), scraped by Prometheus as job ipx.
t = {"refId": ref, "datasource": PROM, "expr": expr}
if instant:
t["instant"], t["range"], t["format"] = True, False, "table"
if legend:
t["legendFormat"] = legend
return t
@@ -105,7 +109,7 @@ def ts(title, targets, x, w=12, h=8, unit="short", bars=False, stack=False, desc
"tooltip": {"mode": "multi", "sort": "desc"}})
def table(title, targets, x, w=12, h=8, rename=None, sort=None, desc=""):
def table(title, targets, x, w=12, h=8, rename=None, sort=None, desc="", unit=None):
return panel("table", title, w, h, x, targets, description=desc,
transformations=[{"id": "labelsToFields", "options": {"mode": "columns"}},
{"id": "organize", "options": {
@@ -113,7 +117,7 @@ def table(title, targets, x, w=12, h=8, rename=None, sort=None, desc=""):
"service_name": True},
"renameByName": rename or {}}}],
options={"showHeader": True, "sortBy": sort or []},
fieldConfig={"defaults": {}, "overrides": []})
fieldConfig={"defaults": {"unit": unit} if unit else {}, "overrides": []})
GOOD_BAD = [{"color": "green", "value": None}, {"color": "orange", "value": 1}]
@@ -197,16 +201,16 @@ y += 8
# ---- ipx: the API it answers behind ipx-web
row("ipx: API")
ts("Requests by status", [loki(f'sum by (status) (count_over_time({HTTP} [$__interval]))', legend="{{status}}")],
ts("Requests by status", [prom(f'sum by (status) (increase({REQ}_count{{job="ipx"}}[$__interval]))', legend="{{status}}")],
0, bars=True, stack=True, desc="The event stream the page keeps open is left out.")
ts("Response time", [loki(f'quantile_over_time(0.5, {HTTP} | unwrap duration_ms [$__interval]) by ()', legend="median"),
loki(f'quantile_over_time(0.95, {HTTP} | unwrap duration_ms [$__interval]) by ()', ref="B", legend="95th percentile"),
loki(f'max_over_time({HTTP} | unwrap duration_ms [$__interval]) by ()', ref="C", legend="slowest")],
12, unit="ms")
ts("Response time", [prom(f'histogram_quantile(0.5, sum by (le) (rate({REQ}_bucket{{job="ipx"}}[$__rate_interval])))', legend="median"),
prom(f'histogram_quantile(0.95, sum by (le) (rate({REQ}_bucket{{job="ipx"}}[$__rate_interval])))', ref="B", legend="95th percentile"),
prom(f'histogram_quantile(0.99, sum by (le) (rate({REQ}_bucket{{job="ipx"}}[$__rate_interval])))', ref="C", legend="99th percentile")],
12, unit="s", desc="From ipx_http_request_duration_seconds, whose buckets run from 5 ms to 10 s; the slowest requests themselves are in Tempo.")
y += 8
table("Slowest routes", [loki(f'topk(15, avg_over_time({HTTP} | route != "" | unwrap duration_ms [$__range]) by (method, route))', instant=True)],
0, w=8, rename={"method": "Method", "route": "Route", "Value": "Average ms"}, sort=[{"displayName": "Average ms", "desc": True}])
table("Busiest routes", [loki(f'topk(15, sum by (method, route) (count_over_time({HTTP} | route != "" [$__range])))', instant=True)],
table("Slowest routes", [prom(f'topk(15, sum by (method, route) (increase({REQ}_sum{{job="ipx",route!=""}}[$__range])) / sum by (method, route) (increase({REQ}_count{{job="ipx",route!=""}}[$__range])))', instant=True)],
0, w=8, unit="s", rename={"method": "Method", "route": "Route", "Value": "Average"}, sort=[{"displayName": "Average", "desc": True}])
table("Busiest routes", [prom(f'topk(15, sum by (method, route) (increase({REQ}_count{{job="ipx",route!=""}}[$__range])))', instant=True)],
8, w=8, rename={"method": "Method", "route": "Route", "Value": "Requests"}, sort=[{"displayName": "Requests", "desc": True}])
ts("Open connections", [prom('max(ipx_http_requests_in_flight{job="ipx"})', legend="requests in flight"),
prom('max(ipx_event_listeners{job="ipx"})', ref="B", legend="live-update listeners"),