diff --git a/.claude/skills/ipx-prod-check/SKILL.md b/.claude/skills/ipx-prod-check/SKILL.md index 1923b36..3753eb6 100644 --- a/.claude/skills/ipx-prod-check/SKILL.md +++ b/.claude/skills/ipx-prod-check/SKILL.md @@ -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 ``` + 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. diff --git a/CLAUDE.md b/CLAUDE.md index bf57325..0ee1b8d 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -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. diff --git a/crates/ipx/CHANGELOG.md b/crates/ipx/CHANGELOG.md index b95d059..5f9a3e8 100644 --- a/crates/ipx/CHANGELOG.md +++ b/crates/ipx/CHANGELOG.md @@ -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 diff --git a/crates/ipx/src/metrics.rs b/crates/ipx/src/metrics.rs index 062a0e5..a725f2a 100644 --- a/crates/ipx/src/metrics.rs +++ b/crates/ipx/src/metrics.rs @@ -62,8 +62,17 @@ pub struct Stats { job: std::sync::Mutex>, /// Jobs finished, by kind: how many, and their seconds all told. jobs: std::sync::Mutex>, + /// 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>, } +/// 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] diff --git a/crates/ipx/src/web.rs b/crates/ipx/src/web.rs index 129a656..bd79b9a 100644 --- a/crates/ipx/src/web.rs +++ b/crates/ipx/src/web.rs @@ -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::().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"); } diff --git a/grafana/dashboard.py b/grafana/dashboard.py index 1a1deef..9f60621 100644 --- a/grafana/dashboard.py +++ b/grafana/dashboard.py @@ -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"),