Claude
c3635f0e7c
The nightly trimClientLogs cron fetched one page of 500 records older than 14 days and deleted those, while about 1275 rows arrive a day. Measured on production (read-only) on 2026-09-13: 30213 rows, 14420 of them past the cutoff, the oldest from 2026-08-19, so the backlog grew by roughly 775 rows a day and the documented 14-day retention never held. The job now deletes in batches of 2000 with plain SQL until a batch comes back short, so one run clears everything past the cutoff. Plain SQL instead of $app.delete() per record is safe here: client_logs has no file fields, no collection has a relation pointing at it and no hook watches its deletes, so the record path would only add a transaction and a cascade lookup per row. Batches keep each write lock short. The run logs "trimClientLogs" with the deleted count and the cutoff to PocketBase's logs, and a failure is logged instead of swallowed silently as before. scripts/test_client_logs_trim.py starts a throwaway PocketBase 0.39.6 with this repo's migrations and hooks, seeds stale and fresh rows, fires the job through POST /api/crons/trimClientLogs and checks what is left. Against the old hook it failed: 800 of 1300 stale rows left, no log line. With the fix: 0 of 1300 left, all 40 in-window rows kept (one just inside the cutoff), and 0 of 15000 stale rows left in 0.4 s at production scale. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
164 lines
9.7 KiB
Markdown
164 lines
9.7 KiB
Markdown
# Client diagnostics (`client_logs`)
|
|
|
|
Background diagnostics from prod devices (feedback 2 §4). The family runs Amber
|
|
on hardware that can't be debugged directly, so the app batches a low-volume
|
|
stream of events to the `client_logs` collection. Designed to be invisible on
|
|
the device (in-memory ring buffer, slow best-effort flush, never on a playback
|
|
thread) and safe (owner-create-only, superuser-read-only, redacted at source).
|
|
|
|
## Collection `client_logs`
|
|
Migration `1788000000_client_logs.js`. Fields: `user` (relation), `kind`,
|
|
`event`, `message`, `meta` (json), `appVersion`, `platform`, `device`, `ts`
|
|
(device clock), `created` (server clock).
|
|
|
|
Rules: `create` = owner (`user = @request.auth.id`); list/view/update/delete =
|
|
**null** (superusers only). Retention: `client_logs.pb.js` cron deletes every
|
|
row older than 14 days nightly at 04:00 UTC, all of them in one run, and logs
|
|
`trimClientLogs` with the count to PocketBase's logs. Until 2026-09-13 it
|
|
deleted only 500 a night, so rows reached back to 2026-08-19 before that fix.
|
|
`scripts/test_client_logs_trim.py` checks it.
|
|
|
|
## Event kinds
|
|
| kind | event | meta |
|
|
|-----------|---------------------|--------------------------------------------------|
|
|
| `error` | `uncaught` | `{library}` — Flutter framework errors |
|
|
| `player` | `exo_error` | `{host, anime}` — native player error |
|
|
| `player` | `av_delay_applied` | `{audioMs, host}` — user dialed in an audio offset (the "a track falls behind" signal) |
|
|
| `session` | `session_summary` | one row per playback — see below. **Written only by `SessionFeedbackService._write`.** |
|
|
| `error` | `session_hold_failed` | `{op, sessionId}` — an open session could not be held on disk; see [below](#a-session-the-app-never-saw-end-ended-unseen) |
|
|
| `qa` | `qa_session` | `{sid, lines[], truncated?}` — the QA decision log for one playback (issue #92), off by default |
|
|
| `source` | `source_select` | one row per source sheet — timings and counts, see below |
|
|
| `source` | `source_pick` | **what was chosen and what it beat** — see below |
|
|
|
|
`host` is only the stream's `scheme://host` — **never** a full signed URL or an
|
|
addon token (redacted client-side in `TelemetryService.redactUrl` before write).
|
|
|
|
**Rows from builds up to 1.3.0+38 can be stored twice.** Sending the app to the
|
|
background started two flushes at once (`onHide` and `onPause`), and both posted
|
|
the pending rows. Measured 2026-08-30 to 09-13: 17 of 438 sessions have two
|
|
`session_summary` rows, on six devices, each pair created within 0.23 s, and every
|
|
other kind is affected the same way. Count distinct `device` + `ts` + `event` (for
|
|
a summary, `device` + `meta.sessionId`), not rows. Builds after 1.3.0+38 run one
|
|
flush at a time.
|
|
|
|
### `source_pick` — the row that answers "why did it play that one"
|
|
|
|
Added 2026-09-09, because a real complaint could not be answered without it.
|
|
"Continue played a 1080p when a 4K was there" took an hour of reading the
|
|
ranker and reproducing its arithmetic in a test; `source_select` records how
|
|
long each stage took and how many candidates there were, and says nothing about
|
|
*which* one won.
|
|
|
|
One row per automatic pick:
|
|
|
|
| field | meaning |
|
|
|---|---|
|
|
| `stage` | `known` (a candidate was already probed) or the probing stage |
|
|
| `outcome` | `chosen` / `none` |
|
|
| `wonOn` | **the term it beat the runner-up on** — `language`, `resolutionMatch`, `quality`, `identity`… or `only_candidate` |
|
|
| `res`, `resMeasured` | the winner's height, and whether that was measured or read off the filename |
|
|
| `lang` | the winner's `SourceRanker.languageTier`: 5 confirmed primary audio · 4 claimed · 3 subtitles or fallback · 2 probed-unsuitable · 1 unprobed |
|
|
| `czech` | `dub` / `sub` / absent, as the addon tagged it |
|
|
| `quality`, `provider` | bitrate estimate; which addon it came from |
|
|
| `prefHeight` | **what the viewer asked for**, so the pick can be judged against their preference rather than an assumption |
|
|
| `alt*` | the best candidate it did NOT choose: `altRes`, `altResMeasured`, `altLang`, `altProbed` |
|
|
|
|
`altProbed=false` with a higher `altRes` is the signature of the whole class:
|
|
the better file existed and had not been measured yet, so it lost on `language`
|
|
(unprobed is tier 1) before resolution was ever consulted.
|
|
|
|
**It is not gated on QA logging**, unlike `qa_session`. It used to be, to save
|
|
re-scoring the field for the runner-up; that saving cost an hour of
|
|
reconstruction the first time somebody asked a question it would have answered.
|
|
The pass is arithmetic over a few dozen candidates, once per pick.
|
|
|
|
### `session_summary`, and the two numbers that are not the same
|
|
|
|
`{sessionId, title, probeKey, host, durationS, watchedS, positionS, stalls,
|
|
droppedFrames, renderedFrames, maxConsecutiveDropped, problemAtS[], promptOutcome,
|
|
rating?, ended, lastSeenAt?, playedOn?}` plus the player's provenance fields
|
|
(`forcedAudio`, `sideloadedSubs`, `resumed`, `seeks`, `seekStormMax`,
|
|
codec/height/bitrate). `ended` and the two after it are explained in
|
|
[A session the app never saw end](#a-session-the-app-never-saw-end-ended-unseen).
|
|
|
|
- **`watchedS` is elapsed watch-clock time. `positionS` is where playback got to.**
|
|
They differ whenever someone seeks, rewatches, or stares at a spinner — a session
|
|
that never started reads `watchedS: 48, positionS: 0`.
|
|
- **`sessionId` is on every row**, and is what joins a summary to its `qa_session`
|
|
lines and to the amber-api health record.
|
|
|
|
**Before 2026-08-07 this was written twice per Android playback**, by the native
|
|
player *and* by the feedback service, and the two disagreed: the extra row had no
|
|
`sessionId`, `title` or `probeKey`, and put the *position* in `watchedS`. In one
|
|
14-day window that was 542 rows of which only 294 were real. **Any aggregate over
|
|
this collection computed before that date counts Android sessions twice**, and
|
|
rows older than the fix still carry the duplicate. `sessionId:isset = true` is the
|
|
filter that excludes them.
|
|
|
|
### A session the app never saw end (`ended: unseen`)
|
|
|
|
Added 2026-09-13 (amber-app, first in the build after 1.3.0+38). Until then the
|
|
summary and the amber-api health row were written only when the player closed, and
|
|
a box whose television is switched off with the film on screen never closes it.
|
|
Measured on the kids' box `Xiaomi MIBOX4 · ff3bcf`: **13 of 13 films in 14 days
|
|
left no summary and no health row.** At the end of every one the 5 s position
|
|
save ran at full rate up to the last 45 s `api_usage` tick and then stopped, and
|
|
no row from the hide/pause flush arrived, then or at any later launch (0 of 3572
|
|
`api_usage` rows were delivered late). That box gives the app no callback, so a
|
|
write on `AppLifecycleState.paused` would have recovered none of them.
|
|
|
|
Now both players hold the open session on disk every 10 s
|
|
(`<appSupport>/open_sessions/<sessionId>.json`). A normal close writes as before
|
|
and deletes the copy once the summary is in the telemetry spool. The next launch
|
|
writes whatever is still held, through the same single writer, with:
|
|
|
|
| field | meaning |
|
|
|---|---|
|
|
| `ended` | `closed`: the player closed and wrote it. `unseen`: a later launch wrote it from the held copy. Absent on older builds. |
|
|
| `lastSeenAt` | `unseen` only. When the session was last held, device clock, UTC. The row's own `ts` and `created` are the later launch, often the next day. |
|
|
| `playedOn` | `unseen` only, and only when it differs: the `appVersion gitSha` that played it, because a row is stamped with the build that sends it. |
|
|
|
|
Reading an `unseen` row:
|
|
|
|
- The counters stop at `lastSeenAt`, at most 10 s before the end, and
|
|
`promptOutcome` is `notShown`.
|
|
- It does not say how the session ended (TV switched off, power cut, crash, killed
|
|
in the background), only that the app did not see it.
|
|
- It arrives when the box is next started. A complaint made before that start has
|
|
no row yet.
|
|
- Its amber-api health row is sent at the same moment, once. A session that was
|
|
held and then closed normally sends one health row, at the close.
|
|
- A session killed within its first 10 s was never held and still leaves nothing.
|
|
|
|
`kind: error`, `event: session_hold_failed`, `meta: {op, sessionId}` records a
|
|
hold that could not be written (`put`), let go of (`release`), read back
|
|
(`unreadable`, the copy is deleted) or listed (`recover`). One row per session per
|
|
op, so a full disk is one row, not one per tick.
|
|
|
|
## How Claude queries it
|
|
Superuser token (same as releases publishing), then filter/sort the collection:
|
|
|
|
```bash
|
|
TOKEN=$(...auth as superuser...)
|
|
# recent player errors + desync signals across the fleet, newest first
|
|
curl -s "$PB/api/collections/client_logs/records?perPage=100&sort=-created&filter=$(python3 -c '
|
|
import urllib.parse;print(urllib.parse.quote("kind='"'"'player'"'"'"))')" \
|
|
-H "Authorization: $TOKEN" | python3 -m json.tool
|
|
```
|
|
Useful filters: `kind='player'` (errors + desync), `event='av_delay_applied'`
|
|
(who's fighting sync and by how much — the reported "track falls behind" bug),
|
|
`kind='session' && meta.stalls > 3` (hitchy playback). Group by `device` /
|
|
`platform` / `appVersion` to see which hardware struggles.
|
|
|
|
## What it deliberately does NOT capture (yet)
|
|
True per-track A/V PTS drift needs native instrumentation on both players
|
|
(ExoPlayer exposes one clock; mpv would need `audio-pts`/`video-pts` sampling).
|
|
v1 uses **proxies**: buffering-stall counts and the manual audio-delay the user
|
|
applies to fix desync — which directly answers "is a track falling behind, on
|
|
which sources/devices, and by how much". Deeper PTS sampling is a follow-up if
|
|
the proxies point somewhere specific.
|
|
|
|
## Privacy / kill switch
|
|
On by default; a per-device Settings toggle ("Diagnostika") disables it and
|
|
drops the pending buffer. Only sends while signed in. No addon credential or
|
|
full stream URL ever leaves the device.
|