The page reports its errors and playback timings, and its requests carry a trace (#190)

Nothing the page did in the browser reached the logs: a DeadAir playback
failure on the phone was a toast and nothing more. POST /api/client takes
page errors, unhandled rejections, hls.js and media errors, the time from
play to sound and the length of a stall, and logs them as ev lines under
ipx::client, inside the request's span. Only those kinds are taken, the
text cut to 500 characters, and the page sends each at most once a minute.

The page's API requests send traceparent, a new trace id for each tap or
key, and the server's request span takes it as its parent, so one action's
requests are one trace in Tempo, the report included. The stub DOM the
smoke and native-bridge tests run in gains crypto and performance, which
every browser the page runs in has.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

.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

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).
 

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<LogQuery>) -> Result<Json<L
     Ok(Json(LogPage { lines, latest }))
 }
 
+/// What the page reports from the browser (#190): its errors and its player's, and how long play
+/// took to start or stalled for. Logged as `ev` lines under `ipx::client`, inside the request's
+/// span, so a line carries the trace of the action that led to it.
+#[derive(Deserialize)]
+struct ClientEvent {
+    ev: String,
+    msg: Option<String>,
+    src: Option<String>,
+    line: Option<u32>,
+    feed: Option<String>,
+    enclosure: Option<i64>,
+    deadair: Option<bool>,
+    ms: Option<u64>,
+}
+
+async fn client_event(user: crate::db::User, Json(e): Json<ClientEvent>) -> StatusCode {
+    // From the browser: only the kinds the page sends, and nothing long enough to fill the log.
+    let cut = |s: &Option<String>| s.as_deref().map(|s| s.chars().take(500).collect::<String>());
+    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<opentelemetry::Context> {
+    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());

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 },

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.

web/src/player.ts

@@ -27,7 +27,8 @@ function setSrc(url: string): Promise<void>|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;

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<string,number>();
+function report(ev: string, o: Record<string,any>={}){
+  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<any>{
-  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);