diff --git a/.claude/skills/ipx-prod-check/SKILL.md b/.claude/skills/ipx-prod-check/SKILL.md index a882dff..1ebde9f 100644 --- a/.claude/skills/ipx-prod-check/SKILL.md +++ b/.claude/skills/ipx-prod-check/SKILL.md @@ -35,6 +35,7 @@ lines had no trace id, the access log's time was `ms`, and each event was logged | `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` | message, sometimes fields | start-up, shutdown, account and config messages | +| `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) and `stall` (ms waiting mid-play) 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 diff --git a/CHANGELOG.md b/CHANGELOG.md index 4418408..4d5108d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- The page reports its errors, the player's, how long play takes to start and how long it stalls to the server's log, and the requests one tap sets off share a trace (#190). - Saving an episode from a show with DeadAir on saves it without its dead air, at your breathing room (#186). - Choose the pause DeadAir leaves where it cuts a silence, from 0.2 to 0.5 seconds, for each show in its settings, as its breathing room, on a slider from brisk to relaxed. It is 0.3 seconds unless you change it, up from 0.2, which made speech sound rushed (#182, #183). diff --git a/src/web.rs b/src/web.rs index 676b7d4..7ffd99a 100644 --- a/src/web.rs +++ b/src/web.rs @@ -67,6 +67,7 @@ pub fn router(state: WebState) -> Router { .route("/api/users", get(list_users).post(add_user)) .route("/api/users/{id}", patch(patch_user).delete(remove_user)) .route("/api/logs", get(logs)) + .route("/api/client", post(client_event)) .route("/api/events", get(events)) .route("/admin", get(admin_page)) .route("/admin.js", get(admin_js)) @@ -1322,6 +1323,37 @@ mod tests { assert_eq!(got, ["kid", "plain"], "the OPML as its feeds; a private feed and its shows never"); } + #[test] + fn a_requests_trace_is_the_pages_from_its_traceparent() { + use opentelemetry::trace::TraceContextExt; + let with = |v: &str| { + let mut h = HeaderMap::new(); + h.insert("traceparent", v.parse().unwrap()); + remote_parent(&h) + }; + let cx = with("00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01").expect("parsed"); + assert_eq!(cx.span().span_context().trace_id().to_string(), "4bf92f3577b34da6a3ce929d0e0e4736"); + assert!(cx.span().span_context().is_remote()); + // Anything else from the browser starts a trace of its own. + for bad in ["", "00-xyz-00f067aa0ba902b7-01", "01-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01", + "00-00000000000000000000000000000000-00f067aa0ba902b7-01", "00-4bf92f3577b34da6a3ce929d0e0e4736"] { + assert!(with(bad).is_none(), "{bad}"); + } + assert!(remote_parent(&HeaderMap::new()).is_none()); + } + + #[tokio::test] + async fn the_page_reports_only_what_it_is_meant_to() { + let u = crate::db::User { id: 1, name: "dee".into(), pass_hash: None, is_admin: false, created: None, last_login: None }; + let e = |ev: &str| ClientEvent { + ev: ev.into(), msg: Some("x".repeat(10_000)), src: None, line: None, feed: None, enclosure: None, deadair: None, ms: Some(5), + }; + for ev in ["page_error", "rejection", "player_error", "play_start", "stall"] { + assert_eq!(client_event(u.clone(), Json(e(ev))).await, StatusCode::NO_CONTENT, "{ev}"); + } + assert_eq!(client_event(u, Json(e("anything"))).await, StatusCode::BAD_REQUEST); + } + #[test] fn only_the_last_admin_is_protected() { let u = |id, is_admin| crate::db::User { @@ -2389,6 +2421,60 @@ async fn logs(user: crate::db::User, Query(q): Query) -> Result, + src: Option, + line: Option, + feed: Option, + enclosure: Option, + deadair: Option, + ms: Option, +} + +async fn client_event(user: crate::db::User, Json(e): Json) -> StatusCode { + // From the browser: only the kinds the page sends, and nothing long enough to fill the log. + let cut = |s: &Option| s.as_deref().map(|s| s.chars().take(500).collect::()); + let (msg, src, feed) = (cut(&e.msg), cut(&e.src), cut(&e.feed)); + let (ev, line, enclosure, deadair, ms, user) = (e.ev.as_str(), e.line, e.enclosure, e.deadair, e.ms, user.name.as_str()); + match ev { + "page_error" | "rejection" | "player_error" => tracing::warn!( + target: "ipx::client", ev, msg, src, line, feed, enclosure, deadair, user, + "{user}'s page: {ev}: {}", msg.as_deref().unwrap_or("") + ), + "play_start" | "stall" => tracing::info!( + target: "ipx::client", ev, ms, feed, enclosure, deadair, user, + "{user}'s page: {ev} {} ms", ms.unwrap_or(0) + ), + _ => return StatusCode::BAD_REQUEST, + } + StatusCode::NO_CONTENT +} + +/// The trace a request from the page belongs to, from its `traceparent` (#190), so the requests +/// one action sets off are one trace. None for a missing or malformed one. +fn remote_parent(headers: &HeaderMap) -> Option { + use opentelemetry::trace::{SpanContext, SpanId, TraceContextExt, TraceFlags, TraceId, TraceState}; + let v = headers.get("traceparent")?.to_str().ok()?; + let mut parts = v.split('-'); + let (version, trace, span) = (parts.next()?, parts.next()?, parts.next()?); + if version != "00" || trace.len() != 32 || span.len() != 16 { + return None; + } + let sc = SpanContext::new( + TraceId::from_hex(trace).ok()?, + SpanId::from_hex(span).ok()?, + TraceFlags::SAMPLED, + true, + TraceState::default(), + ); + sc.is_valid().then(|| opentelemetry::Context::new().with_remote_span_context(sc)) +} + /// Names a request's trace by its route, `POST /api/entries/{feed_id}/{guid}/flags`, once routing /// has found it. Named by the path `access_log` sees, every item's GUID was a trace name of its /// own, and nothing grouped. A route layer, because only one runs after routing. Renamed on the @@ -2428,6 +2514,10 @@ async fn access_log(req: Request, next: Next) -> Response { http.response.status_code = tracing::field::Empty, ) }; + if let Some(parent) = remote_parent(req.headers()) { + use tracing_opentelemetry::OpenTelemetrySpanExt; + let _ = span.set_parent(parent); + } let started = std::time::Instant::now(); let resp = tracing::Instrument::instrument(next.run(req), span.clone()).await; span.record("http.response.status_code", resp.status().as_u16()); diff --git a/tests/dom-stub.js b/tests/dom-stub.js index 742c286..d317944 100644 --- a/tests/dom-stub.js +++ b/tests/dom-stub.js @@ -47,7 +47,7 @@ function makeContext(html, script, { media = false } = {}) { }; const ctx = { - document, console, + document, console, crypto: require("crypto").webcrypto, performance, window: { isSecureContext: false, addEventListener(){} }, localStorage: { getItem: () => null, setItem(){}, removeItem(){} }, navigator: { clipboard: undefined, sendBeacon(){}, mediaSession: undefined }, diff --git a/tests/ui/app.spec.js b/tests/ui/app.spec.js index a335a55..ce94a7c 100644 --- a/tests/ui/app.spec.js +++ b/tests/ui/app.spec.js @@ -1804,8 +1804,14 @@ test('DeadAir is off until turned on for a show, then plays it shortened, with y // Played through DeadAir's playlist (#181), by hls.js in Chromium, with the switch beside the // speed pressed. The element's own src is then hls.js's blob: address. + // How long it took to start goes to the server's log, under the trace of the tap (#190). + const started = page.waitForRequest(r => r.url().endsWith('/api/client') && r.postDataJSON()?.ev === 'play_start'); await row.locator('[data-a=play]').click(); await expect.poll(() => page.evaluate(() => player.src)).toMatch(/\/deadair\.m3u8$/); + const report = await started; + expect(report.postDataJSON()).toMatchObject({ deadair: true }); + expect(report.postDataJSON().ms).toBeGreaterThan(0); + expect(report.headers().traceparent).toMatch(/^00-[0-9a-f]{32}-[0-9a-f]{16}-01$/); await expect.poll(() => page.evaluate(() => document.querySelector('#audio').currentTime), { timeout: 15_000 }).toBeGreaterThan(0.5); await expect(page.locator('#pdead')).toHaveAttribute('aria-pressed', 'true'); // Off from the player: the original, from the same place. diff --git a/web/src/player.ts b/web/src/player.ts index f09ec05..d9ed69c 100644 --- a/web/src/player.ts +++ b/web/src/player.ts @@ -27,7 +27,8 @@ function setSrc(url: string): Promise|null{ }); return ready.then(()=>{ hls=new w.Hls(); - hls.on(w.Hls.Events.ERROR,(_,d)=>{ if(d.fatal) toast('Playback failed: '+d.details,true); }); + hls.on(w.Hls.Events.ERROR,(_,d)=>{ if(d.fatal){ toast('Playback failed: '+d.details,true); + report('player_error',{msg:`hls.js: ${d.type} ${d.details}`,feed:player.feed,enclosure:player.enc}); } }); hls.loadSource(url); hls.attachMedia(audio); }); } @@ -137,6 +138,20 @@ function syncPlayButtons(){ } for(const ev of ['play','pause','timeupdate']) audio.addEventListener(ev,syncListening); window.addEventListener('beforeunload',savePos); + +/// For the server's log (#190): how long play takes to start, how long it stalls for, and what +/// the browser says when it cannot play a file at all. +let asked=0, waited=0; +const playing=()=>({feed:player.feed,enclosure:player.enc,deadair:!!player.src?.endsWith('.m3u8')}); +audio.addEventListener('play',()=>{ asked=performance.now(); }); +audio.addEventListener('waiting',()=>{ if(!asked) waited=performance.now(); }); +audio.addEventListener('playing',()=>{ + const now=performance.now(); + if(asked) report('play_start',{ms:Math.round(now-asked),...playing()}); + else if(waited && now-waited>=500) report('stall',{ms:Math.round(now-waited),...playing()}); + asked=0; waited=0; +}); +audio.addEventListener('error',()=>{ if(audio.error) report('player_error',{msg:`media error ${audio.error.code}: ${audio.error.message}`,...playing()}); }); $('#pplay').onclick=()=>audio.paused?audio.play():audio.pause(); $('#pback').onclick=()=>audio.currentTime-=15; $('#pfwd').onclick=()=>audio.currentTime+=30; diff --git a/web/src/util.ts b/web/src/util.ts index 0954a5d..73f32b6 100644 --- a/web/src/util.ts +++ b/web/src/util.ts @@ -70,8 +70,30 @@ function spanText(secs){ const h=Math.floor(secs/3600), m=Math.floor(secs%3600/60); return h?`${h} h ${m} min`:m?`${m} min`:`${secs} s`; } +/// One trace for each thing you do (#190): the requests a tap or a key sets off share a trace id, +/// sent as traceparent, so Tempo shows them together. getRandomValues, not randomUUID, which a +/// LAN address over plain HTTP does not have. +let traceId=''; +const hex=(n: number)=>Array.from(crypto.getRandomValues(new Uint8Array(n)),b=>b.toString(16).padStart(2,'0')).join(''); +for(const t of ['pointerdown','keydown']) window.addEventListener(t,()=>{ traceId=hex(16); },{capture:true,passive:true}); +function traceparent(){ return `00-${traceId||=hex(16)}-${hex(8)}-01`; } + +/// Something that went wrong, or how long something took, in the browser, for the server's log +/// (#190). The same thing at most once a minute: a failure in a loop would otherwise send a line +/// a frame. +const reported=new Map(); +function report(ev: string, o: Record={}){ + const key=ev+(o.msg||''), now=Date.now(); + if(o.msg==='signed out' || now-(reported.get(key)||0)<60_000) return; + reported.set(key,now); + fetch('/api/client',{method:'POST',keepalive:true,headers:{'Content-Type':'application/json',traceparent:traceparent()}, + body:JSON.stringify({ev,...o})}).catch(()=>{}); +} +window.addEventListener('error',e=>report('page_error',{msg:String(e.message||e.error||'error'),src:e.filename,line:e.lineno})); +window.addEventListener('unhandledrejection',e=>report('rejection',{msg:String(e.reason?.message||e.reason)})); + async function api(url: string, opts?: RequestInit): Promise{ - const r = await fetch(url,{headers:{'Content-Type':'application/json'},...opts}); + const r = await fetch(url,{headers:{'Content-Type':'application/json',traceparent:traceparent()},...opts}); if(r.status===401){ location.href='/login'; throw new Error('signed out'); } if(!r.ok) throw new Error(await r.text().catch(()=>'')||String(r.status)); return r.status===204?null:r.json().catch(()=>null);