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.