Compare commits

...
Author SHA1 Message Date
rxwatcher d8377a7345 docs: preserve local diagnostics evidence 2026-06-08 21:13:24 +02:00
5 changed files with 1521 additions and 0 deletions
@@ -0,0 +1,36 @@
ns18 Ceph jumbo failure proof 2026-06-06T12:26:36+02:00
Setting vmbr0.400 to 9000 temporarily for probe
--- vmbr0.400 ---
10: vmbr0.400@vmbr0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 9000 qdisc noqueue state UP mode DEFAULT group default qlen 20000
link/ether e4:43:4b:76:30:cc brd ff:ff:ff:ff:ff:ff promiscuity 0 allmulti 0 minmtu 0 maxmtu 65535
vlan protocol 802.1Q id 400 <REORDER_HDR> addrgenmode eui64 numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535 tso_max_size 65536 tso_max_segs 65535 gro_max_size 65536 gso_ipv4_max_size 65536 gro_ipv4_max_size 65536
--- matrix at mtu 9000 ---
=== 10.10.3.58 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.076/0.076/0.076/0.000 ms rc=0
payload=4000 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.152/0.152/0.152/0.000 ms rc=0
payload=8972 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.095/0.095/0.095/0.000 ms rc=0
=== 10.10.3.59 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.075/0.075/0.075/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.101/0.101/0.101/0.000 ms rc=0
=== 10.10.3.60 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.052/0.052/0.052/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.12 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.053/0.053/0.053/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.18 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.069/0.069/0.069/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.43 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.074/0.074/0.074/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.114/0.114/0.114/0.000 ms rc=0
Restoring vmbr0.400 to 1500
--- vmbr0.400 restored ---
10: vmbr0.400@vmbr0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP mode DEFAULT group default qlen 20000
link/ether e4:43:4b:76:30:cc brd ff:ff:ff:ff:ff:ff promiscuity 0 allmulti 0 minmtu 0 maxmtu 65535
vlan protocol 802.1Q id 400 <REORDER_HDR> addrgenmode eui64 numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535 tso_max_size 65536 tso_max_segs 65535 gro_max_size 65536 gso_ipv4_max_size 65536 gro_ipv4_max_size 65536
@@ -0,0 +1,43 @@
ns18 post-ceph-pve4 MTU 9000 test 2026-06-06T12:44:42+02:00
--- versions ---
ceph version 19.2.3 (d74d168b1c80fb01e1a30d5e4ca9a45b12bc145b) squid (stable)
ceph-common 19.2.3-pve4
ceph-fuse 19.2.3-pve4
libcephfs2 19.2.3-pve4
librados2 19.2.3-pve4
librbd1 19.2.3-pve4
librgw2 19.2.3-pve4
python3-ceph-common 19.2.3-pve4
python3-rados 19.2.3-pve4
python3-rbd 19.2.3-pve4
python3-rgw 19.2.3-pve4
--- set mtu 9000 ---
10: vmbr0.400@vmbr0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 9000 qdisc noqueue state UP mode DEFAULT group default qlen 20000\ link/ether e4:43:4b:76:30:cc brd ff:ff:ff:ff:ff:ff
--- jumbo matrix ---
=== 10.10.3.58 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.085/0.085/0.085/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.59 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.075/0.075/0.075/0.000 ms rc=0
payload=4000 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.075/0.075/0.075/0.000 ms rc=0
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.60 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.734/0.734/0.734/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.12 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.077/0.077/0.077/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.18 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.079/0.079/0.079/0.000 ms rc=0
payload=4000 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
=== 10.10.3.43 ===
payload=1472 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.062/0.062/0.062/0.000 ms rc=0
payload=4000 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.058/0.058/0.058/0.000 ms rc=0
payload=8972 1 packets transmitted, 0 received, 100% packet loss, time 0ms rc=1
failures=10
--- restore mtu 1500 ---
10: vmbr0.400@vmbr0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP mode DEFAULT group default qlen 20000\ link/ether e4:43:4b:76:30:cc brd ff:ff:ff:ff:ff:ff
+345
View File
@@ -0,0 +1,345 @@
# NS18 Ceph VLAN 400 MTU Investigation
Date: June 6, 2026
## Summary
Silo playback startup on `silo-new` / CT135 was slow because cold reads from CephFS on host `ns18` were extremely slow or timing out. The same read pattern on `ns11` was fast.
The investigation found that `ns18` had an inconsistent jumbo-frame path on VLAN 400, the Ceph storage network. Small packets worked, but larger DF packets failed to some Ceph peers. This caused CephFS reads to stall depending on which Ceph peers/OSDs were involved.
A temporary mitigation was applied on `ns18`: force the Ceph VLAN interface `vmbr0.400` to MTU 1500. After that, host and container Ceph reads dropped from 35-second timeouts to under 1 second.
This is a mitigation, not the final network fix. The desired final state is for `ns18` to pass jumbo frames on VLAN 400 end-to-end like `ns11`.
## Affected Systems
- Host: `ns18.wave-ninja.eu`
- Container: CT135, `silo-new`
- Application: Silo native debug service
- Storage path: CephFS mounted under `/mnt/sharedrives/zd-storage-ceph`
- Network: VLAN 400, Ceph storage network
## Symptoms
Playback startup for transcoded media was slow, often around 9 to 10 seconds or worse.
Application-side playback investigation showed that ffmpeg and app-level restart behavior were no longer the main cause. Hot-cache ffmpeg startup was fast, but cold media reads from CephFS on `ns18` were slow.
Host-level cold read tests from `ns18` showed 64 MB direct reads timing out at 35 seconds. The same style of test on `ns11` completed in about 0.8 to 1.0 seconds.
## Important Ruling-Out
The issue was not caused by:
- Silo application code
- ffmpeg transcode command selection
- CT135 / LXC bind mount behavior
- Ceph client key/caps alone
Evidence for the key/caps point: `ns18` was temporarily mounted using the same Ceph client key used on `ns11`, and reads still timed out.
Stopping CT135 also did not resolve the host-level read problem, so CT135 workload was not the cause.
## Host Comparison Findings
`ns11` and `ns18` are now similar in several important ways:
- Same OS family: Debian 13 / trixie
- Same Proxmox kernel: `7.0.2-6-pve`
- Same CephFS monitor addresses
- Similar CephFS mount options
- Same general VLAN 400 storage network
They were not identical before the June 6 package alignment:
- `ns11` had Ceph packages at `19.2.3-pve4`.
- `ns18` had Ceph packages at `19.2.3-pve2`.
- `ns11` was using the Proxmox Ceph Squid no-subscription repo.
- `ns18` did not have the Ceph Squid no-subscription source enabled, so `19.2.3-pve4` was not visible as a candidate.
- `ns18` NIC counters showed `rx_missed_errors=992`; `ns11` showed `0`
- Most importantly, `ns18` had an inconsistent jumbo-frame path on VLAN 400
The Ceph package/source mismatch has now been fixed on `ns18`. The jumbo-frame failure remains.
The MTU finding is the strongest match for the observed behavior.
## NS11 vs NS18 Side-by-Side
| Area | NS11 | NS18 | Notes |
| --- | --- | --- | --- |
| Hostname | `ns11.wave-ninja.eu` | `ns18.wave-ninja.eu` | Compared as working vs slow host |
| OS | Debian GNU/Linux 13 / trixie | Debian GNU/Linux 13 / trixie | Same OS family |
| Kernel | `7.0.2-6-pve` | `7.0.2-6-pve` | Same Proxmox kernel |
| Ceph monitors | `10.10.3.58`, `10.10.3.59`, `10.10.3.60` | `10.10.3.58`, `10.10.3.59`, `10.10.3.60` | Same monitor set |
| CephFS mount style | Kernel CephFS mounts under `/mnt/sharedrives/zd-storage-ceph` | Kernel CephFS mounts under `/mnt/sharedrives/zd-storage-ceph` | Same overall mount model |
| CephFS mount options | `rw,noatime`, `ms_mode=secure`, `noshare`, `recover_session=clean`, `rasize=67108864`, `caps_wanted_delay_max=30`, `readdir_max_entries=32768`, `readdir_max_bytes=33554432` | Same effective options | Mount options were effectively aligned |
| Media client key | `c0e33113...` | `a0c4c4f...` | Different as expected |
| Alternate key test | Native key was already fast | `ns18` was tested with `ns11` key and remained slow | Rules out key/caps as the primary cause |
| Ceph packages | `19.2.3-pve4` | `19.2.3-pve4` after June 6 package alignment | Now matches |
| Ceph repo source | Proxmox Ceph Squid no-subscription repo | Proxmox Ceph Squid no-subscription repo after June 6 package alignment | Now matches |
| Active storage NIC | `eno1np0` | `nic2` | Both are `i40e` |
| NIC firmware | `9.56 0x80010165 25.0.4` | `9.56 0x80010159 25.0.4` | Slight firmware/build identifier difference |
| NIC errors | `rx_missed_errors=0` | `rx_missed_errors=992` | Not necessarily causal, but another difference |
| VLAN 400 runtime MTU before mitigation | 9000 | 9000 inherited before mitigation | Both appeared configured for jumbo |
| Jumbo DF ping behavior | Passed 8972-byte DF pings to tested Ceph peers | Failed jumbo DF pings to several Ceph peers | Primary behavioral difference |
| 64 MB direct cold read behavior before mitigation | About `0.84s` to `0.99s` | Timed out at 35s on repeated samples | Matches playback startup symptoms |
| Current mitigation | None needed | `vmbr0.400 mtu 1500` | Makes reads reliable, but not identical config |
| 64 MB direct read behavior after mitigation | Not changed | About `0.76s` to `0.92s` on host, `0.77s` to `0.89s` in CT135 | Confirms MTU workaround fixed read stalls |
Bottom line: `ns11` and `ns18` are no longer configured identically because `ns18` is intentionally forced to MTU 1500 as a workaround. They are now aligned from a reliability/read-performance perspective, but the final infrastructure fix is still to make `ns18` pass jumbo frames on VLAN 400 like `ns11`.
## Ceph Client Version Alignment Completed
On June 6, 2026, `ns18` was updated to use the same Proxmox Ceph Squid no-subscription repository as `ns11`:
```text
Types: deb
URIs: http://download.proxmox.com/debian/ceph-squid
Suites: trixie
Components: no-subscription
Signed-By: /usr/share/keyrings/proxmox-archive-keyring.gpg
```
The following packages now match between `ns11` and `ns18`:
```text
ceph-common 19.2.3-pve4
ceph-fuse 19.2.3-pve4
libcephfs2 19.2.3-pve4
librados2 19.2.3-pve4
libradosstriper1 19.2.3-pve4
librbd1 19.2.3-pve4
librgw2 19.2.3-pve4
python3-ceph-argparse 19.2.3-pve4
python3-ceph-common 19.2.3-pve4
python3-cephfs 19.2.3-pve4
python3-rados 19.2.3-pve4
python3-rbd 19.2.3-pve4
python3-rgw 19.2.3-pve4
```
Both hosts now report the same Ceph version:
```text
ceph version 19.2.3 (d74d168b1c80fb01e1a30d5e4ca9a45b12bc145b) squid (stable)
```
After this package alignment, a controlled MTU 9000 test was run again on `ns18`. Jumbo-frame failures remained:
```text
Test file: /root/ns18-post-ceph-pve4-mtu9000-test-20260606-124442.txt
Result: 10 jumbo test failures
```
This confirms the remaining mismatch is not the Ceph userspace package version. The remaining mismatch is the VLAN 400 jumbo-frame path.
## Jumbo Frame Evidence
When `ns18` was temporarily set back to MTU 9000 on `vmbr0.400`, the following DF ping matrix was collected.
Payload sizes:
- `1472` byte payload: standard 1500 MTU test
- `4000` byte payload: mid-size jumbo test
- `8972` byte payload: near-9000 MTU jumbo test
Results from `ns18` with `vmbr0.400` at MTU 9000:
```text
=== 10.10.3.58 ===
payload=1472 pass
payload=4000 pass
payload=8972 pass
=== 10.10.3.59 ===
payload=1472 pass
payload=4000 fail
payload=8972 pass
=== 10.10.3.60 ===
payload=1472 pass
payload=4000 fail
payload=8972 fail
=== 10.10.3.12 ===
payload=1472 pass
payload=4000 fail
payload=8972 fail
=== 10.10.3.18 ===
payload=1472 pass
payload=4000 fail
payload=8972 fail
=== 10.10.3.43 ===
payload=1472 pass
payload=4000 fail
payload=8972 pass
```
By comparison, `ns11` passed 8972-byte DF pings to the same tested Ceph peers.
This pattern shows that:
- `ns18` can send/receive normal 1500-byte traffic on VLAN 400.
- `ns18` can send jumbo traffic to some peers.
- `ns18` cannot send jumbo traffic reliably to all Ceph peers.
- The failure is peer/path-dependent, not a simple local host setting issue.
Proof file on `ns18`:
```text
/root/ns18-ceph-jumbo-failure-proof-20260606-122636.txt
```
## Mitigation Applied
The Ceph VLAN interface on `ns18` was forced to MTU 1500.
Runtime change:
```bash
ip link set vmbr0.400 mtu 1500
```
Persistent config changed in:
```text
/etc/network/interfaces
```
Backup created before the persistent edit:
```text
/etc/network/interfaces.backup-before-ceph-mtu-1500-20260606-122703
```
Current `vmbr0.400` stanza:
```text
auto vmbr0.400
iface vmbr0.400 inet static
address 10.10.7.213/21
mtu 1500
dns-nameservers 10.10.0.1
dns-search cephstorage.local
#VLAN 400 - Ceph storage network
```
This keeps `ns18` from attempting jumbo packets on the broken path.
## Result After Mitigation
After forcing `vmbr0.400` to MTU 1500, 64 MB direct Ceph reads completed quickly.
Host `ns18` read tests:
```text
elapsed=0.87
elapsed=0.92
elapsed=0.90
elapsed=0.76
elapsed=0.77
```
CT135 / `silo-new` read tests:
```text
elapsed=0.88
elapsed=0.82
elapsed=0.77
elapsed=0.89
elapsed=0.80
```
Before mitigation, comparable `ns18` reads timed out at 35 seconds or took far too long.
## Current Application State
CT135 is running.
The Docker Silo application container is stopped to avoid port conflicts:
```text
silo-server-silo-1 Exited
```
The native debug service is running:
```text
silo-native.service active
```
Listeners:
```text
Silo HTTP: :8080
Jellyfin compat API: :8096
```
Smoke checks passed:
```text
http://127.0.0.1:8080/ 200
http://127.0.0.1:8096/System/Info/Public 200
```
## What Changed On NS18
1. `vmbr0.400` MTU changed from inherited jumbo/9000 behavior to explicit MTU 1500.
2. `/etc/network/interfaces` was updated to persist `mtu 1500` for `vmbr0.400`.
3. CT135 was restarted after host-level testing.
4. GNU `time` was installed inside CT135 for read timing tests.
5. Docker Silo app container was stopped.
6. Native debug service `silo-native.service` was created/started to run `/opt/silo-native/silo`.
## Network Team Request
Please investigate VLAN 400 jumbo-frame handling on the `ns18` path end-to-end.
The target final state is:
```text
ns18 should pass 8972-byte DF pings to the same Ceph peers that ns11 can.
```
Areas to verify:
- Switch port connected to `ns18`
- VLAN 400 trunk/native VLAN configuration
- MTU on all relevant switch ports
- MTU on any port-channel, LACP, MLAG, bridge, or intermediate switching path
- Any ACL, storm-control, QoS, or fabric policy that could affect larger frames
- Ceph peer paths for `10.10.3.58`, `10.10.3.59`, `10.10.3.60`, `10.10.3.12`, `10.10.3.18`, and `10.10.3.43`
The key point is that small packets work from `ns18`, but jumbo packets fail inconsistently depending on destination. That is why normal connectivity checks can pass while CephFS cold reads still stall badly.
## Suggested Validation Commands
Run from `ns18` after restoring jumbo MTU for testing:
```bash
ip link set vmbr0.400 mtu 9000
for h in 10.10.3.58 10.10.3.59 10.10.3.60 10.10.3.12 10.10.3.18 10.10.3.43; do
echo "=== $h ==="
ping -c 2 -M do -s 1472 -W 1 "$h"
ping -c 2 -M do -s 4000 -W 1 "$h"
ping -c 2 -M do -s 8972 -W 1 "$h"
done
```
If testing disrupts performance, return to the current mitigation:
```bash
ip link set vmbr0.400 mtu 1500
```
Expected final result after network remediation:
```text
1472-byte DF pings pass to all tested Ceph peers.
4000-byte DF pings pass to all tested Ceph peers.
8972-byte DF pings pass to all tested Ceph peers.
```
@@ -0,0 +1,918 @@
# Diagnostic Spine Implementation Plan
> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking.
**Goal:** Build the first diagnostic spine slice so playback startup delays and catalog/UI refresh loops can be explained from correlated events instead of ad hoc SSH log spelunking.
**Architecture:** Add a small diagnostics package that stores bounded in-memory event timelines and exposes helpers for request trace IDs, catalog activity, and playback timelines. Backend handlers and middleware record structured events; the frontend adds a client trace header and records catalog refetch reasons. Admin-only diagnostics endpoints return recent activity without adding a required external observability platform.
**Tech Stack:** Go, chi middleware, pgx-backed API handlers, slog structured logs, React, TanStack Query, Vitest.
---
## File Structure
- Create `internal/diagnostics/context.go`: request/client trace helpers and header constants.
- Create `internal/diagnostics/recorder.go`: bounded in-memory recorder for catalog and playback diagnostic events.
- Create `internal/diagnostics/recorder_test.go`: recorder behavior and bounds tests.
- Modify `internal/api/middleware/request_logger.go`: include client trace ID in request logs.
- Modify `internal/api/handlers/catalog.go`: classify context cancellation as a cancellation diagnostic, not an internal catalog error.
- Modify `internal/api/router.go`: wire diagnostics recorder and admin endpoints.
- Create `internal/api/handlers/diagnostics.go`: admin-only diagnostics endpoints.
- Create `internal/api/handlers/diagnostics_test.go`: endpoint JSON and partial-data tests.
- Modify `internal/playback/transcode.go`: record first-segment and segment-gap diagnostics through an optional recorder hook.
- Modify `internal/api/handlers/playback.go`: attach playback diagnostics recorder to transcode sessions.
- Modify `web/src/api/client.ts`: attach `X-Silo-Client-Trace-ID` to API requests.
- Create `web/src/lib/clientTrace.ts`: browser trace ID helper.
- Create `web/src/lib/diagnostics/catalogActivity.ts`: frontend ring buffer for catalog refetch reasons.
- Modify `web/src/components/RealtimeEventsProvider.tsx`: record realtime catalog event/refetch reasons and avoid broad active catalog refetch when a catalog event has a different `library_id` than active catalog queries.
- Modify `web/src/hooks/queries/catalog.ts`: record query start/complete/cancel reasons.
- Add focused tests under `web/src/**.test.ts(x)` for trace header and catalog refetch filtering.
---
### Task 1: Backend Trace Context And Recorder
**Files:**
- Create: `internal/diagnostics/context.go`
- Create: `internal/diagnostics/recorder.go`
- Test: `internal/diagnostics/recorder_test.go`
- [ ] **Step 1: Write recorder tests**
Create `internal/diagnostics/recorder_test.go`:
```go
package diagnostics
import (
"net/http"
"testing"
"time"
)
func TestClientTraceIDFromRequestPrefersHeader(t *testing.T) {
req, err := http.NewRequest(http.MethodGet, "/api/v1/catalog", nil)
if err != nil {
t.Fatal(err)
}
req.Header.Set(ClientTraceHeader, "client-trace-123")
if got := ClientTraceIDFromRequest(req); got != "client-trace-123" {
t.Fatalf("ClientTraceIDFromRequest() = %q, want header value", got)
}
}
func TestRecorderKeepsNewestCatalogEvents(t *testing.T) {
rec := NewRecorder(2)
rec.RecordCatalog(CatalogEvent{Kind: "catalog.query.started", RequestID: "old"})
rec.RecordCatalog(CatalogEvent{Kind: "catalog.query.completed", RequestID: "middle"})
rec.RecordCatalog(CatalogEvent{Kind: "catalog.query.cancelled", RequestID: "new"})
events := rec.CatalogEvents()
if len(events) != 2 {
t.Fatalf("len(events) = %d, want 2", len(events))
}
if events[0].RequestID != "middle" || events[1].RequestID != "new" {
t.Fatalf("events = %+v, want newest two in order", events)
}
}
func TestRecorderKeepsPlaybackEventsBySession(t *testing.T) {
rec := NewRecorder(10)
now := time.Now()
rec.RecordPlayback(PlaybackEvent{Kind: "playback.ffmpeg.spawned", SessionID: "s1", At: now})
rec.RecordPlayback(PlaybackEvent{Kind: "playback.first_segment.ready", SessionID: "s2", At: now})
rec.RecordPlayback(PlaybackEvent{Kind: "playback.first_segment.ready", SessionID: "s1", At: now})
events := rec.PlaybackEvents("s1")
if len(events) != 2 {
t.Fatalf("len(events) = %d, want 2", len(events))
}
if events[0].Kind != "playback.ffmpeg.spawned" || events[1].Kind != "playback.first_segment.ready" {
t.Fatalf("events = %+v, want s1 events only in order", events)
}
}
```
- [ ] **Step 2: Run tests to verify they fail**
Run:
```bash
go test ./internal/diagnostics -count=1
```
Expected: FAIL because `internal/diagnostics` does not exist.
- [ ] **Step 3: Implement diagnostics context and recorder**
Create `internal/diagnostics/context.go`:
```go
package diagnostics
import (
"crypto/rand"
"encoding/hex"
"net/http"
"strings"
)
const ClientTraceHeader = "X-Silo-Client-Trace-ID"
func ClientTraceIDFromRequest(r *http.Request) string {
if r == nil {
return ""
}
return sanitizeTraceID(r.Header.Get(ClientTraceHeader))
}
func NewTraceID() string {
var b [16]byte
if _, err := rand.Read(b[:]); err != nil {
return ""
}
return hex.EncodeToString(b[:])
}
func sanitizeTraceID(value string) string {
value = strings.TrimSpace(value)
if len(value) > 128 {
value = value[:128]
}
return value
}
```
Create `internal/diagnostics/recorder.go`:
```go
package diagnostics
import (
"slices"
"sync"
"time"
)
const DefaultEventLimit = 500
type CatalogEvent struct {
At time.Time `json:"at"`
Kind string `json:"kind"`
RequestID string `json:"request_id,omitempty"`
ClientTraceID string `json:"client_trace_id,omitempty"`
Route string `json:"route,omitempty"`
Source string `json:"source,omitempty"`
LibraryID int `json:"library_id,omitempty"`
Status string `json:"status,omitempty"`
Reason string `json:"reason,omitempty"`
DurationMS int64 `json:"duration_ms,omitempty"`
}
type PlaybackEvent struct {
At time.Time `json:"at"`
Kind string `json:"kind"`
SessionID string `json:"session_id"`
PlaybackID string `json:"playback_session_id,omitempty"`
Segment string `json:"segment,omitempty"`
ElapsedMS int64 `json:"elapsed_ms,omitempty"`
FFmpegPID int `json:"ffmpeg_pid,omitempty"`
RestartCount int `json:"restart_count,omitempty"`
Reason string `json:"reason,omitempty"`
SizeBytes int64 `json:"size_bytes,omitempty"`
OutputDir string `json:"output_dir,omitempty"`
TargetVideo string `json:"target_video_codec,omitempty"`
TargetAudio string `json:"target_audio_codec,omitempty"`
HardwareAccel string `json:"hw_accel,omitempty"`
}
type Recorder struct {
mu sync.RWMutex
limit int
catalog []CatalogEvent
playback []PlaybackEvent
}
func NewRecorder(limit int) *Recorder {
if limit <= 0 {
limit = DefaultEventLimit
}
return &Recorder{limit: limit}
}
func (r *Recorder) RecordCatalog(event CatalogEvent) {
if r == nil {
return
}
if event.At.IsZero() {
event.At = time.Now().UTC()
}
r.mu.Lock()
defer r.mu.Unlock()
r.catalog = appendBounded(r.catalog, event, r.limit)
}
func (r *Recorder) CatalogEvents() []CatalogEvent {
if r == nil {
return nil
}
r.mu.RLock()
defer r.mu.RUnlock()
return slices.Clone(r.catalog)
}
func (r *Recorder) RecordPlayback(event PlaybackEvent) {
if r == nil {
return
}
if event.At.IsZero() {
event.At = time.Now().UTC()
}
r.mu.Lock()
defer r.mu.Unlock()
r.playback = appendBounded(r.playback, event, r.limit)
}
func (r *Recorder) PlaybackEvents(sessionID string) []PlaybackEvent {
if r == nil {
return nil
}
r.mu.RLock()
defer r.mu.RUnlock()
var out []PlaybackEvent
for _, event := range r.playback {
if event.SessionID == sessionID {
out = append(out, event)
}
}
return out
}
func appendBounded[T any](values []T, next T, limit int) []T {
values = append(values, next)
if len(values) <= limit {
return values
}
return values[len(values)-limit:]
}
```
- [ ] **Step 4: Run tests to verify they pass**
Run:
```bash
go test ./internal/diagnostics -count=1
```
Expected: PASS.
- [ ] **Step 5: Commit**
```bash
git add internal/diagnostics
git commit -m "feat: add diagnostic event recorder"
```
---
### Task 2: Request And Catalog Cancellation Diagnostics
**Files:**
- Modify: `internal/api/middleware/request_logger.go`
- Modify: `internal/api/handlers/catalog.go`
- Test: `internal/api/handlers/catalog_test.go`
- [ ] **Step 1: Write cancellation classification test**
Add this test to `internal/api/handlers/catalog_test.go`:
```go
func TestCatalogErrorStatusTreatsContextCancellationAsClientCancel(t *testing.T) {
code, errorCode, message, isCancel := catalogErrorStatus(context.Canceled)
if code != 499 {
t.Fatalf("status = %d, want 499", code)
}
if errorCode != "client_cancelled" {
t.Fatalf("errorCode = %q, want client_cancelled", errorCode)
}
if message == "" {
t.Fatal("message is empty")
}
if !isCancel {
t.Fatal("isCancel = false, want true")
}
}
```
- [ ] **Step 2: Run test to verify it fails**
Run:
```bash
go test ./internal/api/handlers -run TestCatalogErrorStatusTreatsContextCancellationAsClientCancel -count=1
```
Expected: FAIL because `catalogErrorStatus` does not exist.
- [ ] **Step 3: Implement cancellation status and trace fields**
In `internal/api/handlers/catalog.go`, import `context` and add this helper near `HandleGetCatalog`:
```go
func catalogErrorStatus(err error) (status int, code string, message string, cancelled bool) {
if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) {
return 499, "client_cancelled", "Catalog request was cancelled", true
}
if errors.Is(err, catalog.ErrInvalidCatalogRequest) {
return http.StatusBadRequest, "bad_request", err.Error(), false
}
if errors.Is(err, catalog.ErrCatalogSourceNotFound) {
return http.StatusNotFound, "not_found", "Catalog source not found", false
}
return http.StatusInternalServerError, "internal_error", "Failed to resolve catalog", false
}
```
Replace the current error ladder in `HandleGetCatalog` with:
```go
status, code, message, cancelled := catalogErrorStatus(err)
if cancelled {
slog.Info("catalog: resolve cancelled",
"err_msg", err.Error(),
"client_trace_id", diagnostics.ClientTraceIDFromRequest(r),
)
} else if status == http.StatusInternalServerError {
slog.Error("catalog: resolve failed", "err_msg", err.Error())
}
writeError(w, status, code, message)
return
```
In `internal/api/middleware/request_logger.go`, add `client_trace_id` to the request log attributes:
```go
if clientTraceID := diagnostics.ClientTraceIDFromRequest(r); clientTraceID != "" {
attrs = append(attrs, slog.String("client_trace_id", clientTraceID))
}
```
Use the existing local attribute variable names in the middleware; do not rewrite the middleware structure.
- [ ] **Step 4: Run handler and middleware tests**
Run:
```bash
go test ./internal/api/handlers ./internal/api/middleware -count=1
```
Expected: PASS.
- [ ] **Step 5: Commit**
```bash
git add internal/api/handlers/catalog.go internal/api/handlers/catalog_test.go internal/api/middleware/request_logger.go
git commit -m "feat: record catalog cancellations with trace context"
```
---
### Task 3: Frontend Client Trace And Catalog Refetch Reasons
**Files:**
- Create: `web/src/lib/clientTrace.ts`
- Create: `web/src/lib/diagnostics/catalogActivity.ts`
- Modify: `web/src/api/client.ts`
- Modify: `web/src/hooks/queries/catalog.ts`
- Modify: `web/src/components/RealtimeEventsProvider.tsx`
- Test: `web/src/lib/clientTrace.test.ts`
- Test: `web/src/lib/diagnostics/catalogActivity.test.ts`
- [ ] **Step 1: Write frontend diagnostics tests**
Create `web/src/lib/clientTrace.test.ts`:
```ts
import { describe, expect, it } from "vitest";
import { getClientTraceId } from "./clientTrace";
describe("getClientTraceId", () => {
it("returns one stable id per page lifetime", () => {
const first = getClientTraceId();
const second = getClientTraceId();
expect(first).toBe(second);
expect(first.length).toBeGreaterThan(8);
});
});
```
Create `web/src/lib/diagnostics/catalogActivity.test.ts`:
```ts
import { describe, expect, it } from "vitest";
import { getCatalogActivity, recordCatalogActivity, resetCatalogActivity } from "./catalogActivity";
describe("catalogActivity", () => {
it("keeps recent events in insertion order", () => {
resetCatalogActivity();
recordCatalogActivity({ kind: "catalog.query.started", route: "/catalog", libraryId: 1 });
recordCatalogActivity({ kind: "catalog.refetch.triggered", reason: "realtime", libraryId: 1 });
expect(getCatalogActivity()).toMatchObject([
{ kind: "catalog.query.started", route: "/catalog", libraryId: 1 },
{ kind: "catalog.refetch.triggered", reason: "realtime", libraryId: 1 },
]);
});
});
```
- [ ] **Step 2: Run tests to verify they fail**
Run:
```bash
cd web && pnpm vitest run src/lib/clientTrace.test.ts src/lib/diagnostics/catalogActivity.test.ts
```
Expected: FAIL because the modules do not exist.
- [ ] **Step 3: Implement frontend trace helpers**
Create `web/src/lib/clientTrace.ts`:
```ts
let clientTraceId: string | null = null;
export function getClientTraceId() {
if (clientTraceId) return clientTraceId;
const cryptoObj = globalThis.crypto;
clientTraceId =
cryptoObj && "randomUUID" in cryptoObj
? cryptoObj.randomUUID()
: `trace-${Date.now().toString(36)}-${Math.random().toString(36).slice(2)}`;
return clientTraceId;
}
```
Create `web/src/lib/diagnostics/catalogActivity.ts`:
```ts
export interface CatalogActivityEvent {
at: string;
kind: string;
route?: string;
reason?: string;
libraryId?: number;
source?: string;
status?: string;
}
const MAX_EVENTS = 200;
const events: CatalogActivityEvent[] = [];
export function recordCatalogActivity(event: Omit<CatalogActivityEvent, "at"> & { at?: string }) {
events.push({
at: event.at ?? new Date().toISOString(),
kind: event.kind,
route: event.route,
reason: event.reason,
libraryId: event.libraryId,
source: event.source,
status: event.status,
});
if (events.length > MAX_EVENTS) {
events.splice(0, events.length - MAX_EVENTS);
}
}
export function getCatalogActivity() {
return [...events];
}
export function resetCatalogActivity() {
events.splice(0, events.length);
}
```
- [ ] **Step 4: Add header and query activity recording**
In `web/src/api/client.ts`, add the header:
```ts
headers.set("X-Silo-Client-Trace-ID", getClientTraceId());
```
Import `getClientTraceId` from `@/lib/clientTrace`. Preserve existing auth and content-type headers.
In `web/src/hooks/queries/catalog.ts`, record:
```ts
recordCatalogActivity({
kind: "catalog.query.started",
route: "/catalog",
source: state.source,
libraryId: state.library_id,
});
```
Wrap `fetchCatalogPage` calls in the query functions so completion and cancellation can be recorded:
```ts
try {
const result = await fetchCatalogPage(state, limit, offset, { signal }, includeTotal, snapshot);
recordCatalogActivity({ kind: "catalog.query.completed", route: "/catalog", source: state.source, libraryId: state.library_id });
return result;
} catch (error) {
recordCatalogActivity({
kind: error instanceof DOMException && error.name === "AbortError" ? "catalog.query.cancelled" : "catalog.query.failed",
route: "/catalog",
source: state.source,
libraryId: state.library_id,
});
throw error;
}
```
Apply the same pattern for page 0 and remaining pages.
- [ ] **Step 5: Scope realtime catalog refetches**
In `web/src/components/RealtimeEventsProvider.tsx`, before broad refetch, record:
```ts
recordCatalogActivity({
kind: "realtime.catalog.event.received",
reason: message.event,
libraryId: typeof message.data === "object" && message.data && "library_id" in message.data ? Number((message.data as { library_id?: unknown }).library_id) : undefined,
});
```
Change the active catalog refetch call in `invalidateCatalogState` to skip active catalog list queries whose `library_id` does not match the event library ID when an event library ID is present. Implement a helper:
```ts
function activeCatalogQueryMatchesLibrary(queryKey: unknown, libraryId?: number) {
if (!libraryId || !Array.isArray(queryKey)) return true;
const params = queryKey[2] as { library_id?: number } | undefined;
return params?.library_id == null || params.library_id === libraryId;
}
```
Then use `predicate` with `refetchQueries` and record `catalog.refetch.triggered` only for matching active queries.
- [ ] **Step 6: Run frontend tests**
Run:
```bash
cd web && pnpm vitest run src/lib/clientTrace.test.ts src/lib/diagnostics/catalogActivity.test.ts
```
Expected: PASS.
- [ ] **Step 7: Commit**
```bash
git add web/src/api/client.ts web/src/hooks/queries/catalog.ts web/src/components/RealtimeEventsProvider.tsx web/src/lib/clientTrace.ts web/src/lib/clientTrace.test.ts web/src/lib/diagnostics/catalogActivity.ts web/src/lib/diagnostics/catalogActivity.test.ts
git commit -m "feat: trace frontend catalog refetch activity"
```
---
### Task 4: Playback Diagnostics Endpoint
**Files:**
- Create: `internal/api/handlers/diagnostics.go`
- Create: `internal/api/handlers/diagnostics_test.go`
- Modify: `internal/api/router.go`
- Modify: `internal/playback/transcode.go`
- Modify: `internal/api/handlers/playback.go`
- [ ] **Step 1: Write endpoint test**
Create `internal/api/handlers/diagnostics_test.go`:
```go
package handlers
import (
"encoding/json"
"net/http"
"net/http/httptest"
"testing"
"github.com/Silo-Server/silo-server/internal/diagnostics"
)
func TestDiagnosticsHandlerReturnsPlaybackTimeline(t *testing.T) {
rec := diagnostics.NewRecorder(10)
rec.RecordPlayback(diagnostics.PlaybackEvent{Kind: "playback.ffmpeg.spawned", SessionID: "session-1", FFmpegPID: 123})
rec.RecordPlayback(diagnostics.PlaybackEvent{Kind: "playback.first_segment.ready", SessionID: "session-1", Segment: "seg_00000.m4s", ElapsedMS: 13500})
handler := NewDiagnosticsHandler(rec)
req := httptest.NewRequest(http.MethodGet, "/api/v1/admin/diagnostics/playback/session-1", nil)
rr := httptest.NewRecorder()
handler.HandlePlayback(rr, req)
if rr.Code != http.StatusOK {
t.Fatalf("status = %d, want 200", rr.Code)
}
var body struct {
SessionID string `json:"session_id"`
Events []diagnostics.PlaybackEvent `json:"events"`
}
if err := json.Unmarshal(rr.Body.Bytes(), &body); err != nil {
t.Fatal(err)
}
if body.SessionID != "session-1" || len(body.Events) != 2 {
t.Fatalf("body = %+v, want session timeline", body)
}
}
```
- [ ] **Step 2: Run test to verify it fails**
Run:
```bash
go test ./internal/api/handlers -run TestDiagnosticsHandlerReturnsPlaybackTimeline -count=1
```
Expected: FAIL because `NewDiagnosticsHandler` does not exist.
- [ ] **Step 3: Implement diagnostics handler**
Create `internal/api/handlers/diagnostics.go`:
```go
package handlers
import (
"net/http"
"github.com/Silo-Server/silo-server/internal/diagnostics"
"github.com/go-chi/chi/v5"
)
type DiagnosticsHandler struct {
recorder *diagnostics.Recorder
}
func NewDiagnosticsHandler(recorder *diagnostics.Recorder) *DiagnosticsHandler {
return &DiagnosticsHandler{recorder: recorder}
}
func (h *DiagnosticsHandler) HandlePlayback(w http.ResponseWriter, r *http.Request) {
sessionID := chi.URLParam(r, "session_id")
if sessionID == "" {
sessionID = pathTail(r.URL.Path)
}
writeJSON(w, http.StatusOK, map[string]any{
"session_id": sessionID,
"events": h.recorder.PlaybackEvents(sessionID),
})
}
func (h *DiagnosticsHandler) HandleCatalogActivity(w http.ResponseWriter, r *http.Request) {
writeJSON(w, http.StatusOK, map[string]any{
"events": h.recorder.CatalogEvents(),
})
}
func pathTail(path string) string {
for i := len(path) - 1; i >= 0; i-- {
if path[i] == '/' {
return path[i+1:]
}
}
return path
}
```
- [ ] **Step 4: Wire handler in router**
In `internal/api/router.go`, create one recorder during router construction:
```go
diagnosticsRecorder := diagnostics.NewRecorder(diagnostics.DefaultEventLimit)
diagnosticsHandler := handlers.NewDiagnosticsHandler(diagnosticsRecorder)
```
Wire admin routes:
```go
r.Route("/admin/diagnostics", func(r chi.Router) {
r.Get("/playback/{session_id}", diagnosticsHandler.HandlePlayback)
r.Get("/catalog/activity", diagnosticsHandler.HandleCatalogActivity)
})
```
Pass `diagnosticsRecorder` into playback/catalog handlers through new optional fields. Keep routes behind existing admin middleware in the admin route group.
- [ ] **Step 5: Record playback events**
In `internal/playback/transcode.go`, add an optional callback field on the transcode session/config:
```go
type DiagnosticRecorder interface {
RecordPlayback(diagnostics.PlaybackEvent)
}
```
Record `playback.ffmpeg.spawned` when ffmpeg starts and `playback.first_segment.ready` when `seg_00000.m4s` is first observed. Use the existing segment monitor added during playback debugging.
- [ ] **Step 6: Run backend tests**
Run:
```bash
go test ./internal/diagnostics ./internal/api/handlers ./internal/playback -count=1
```
Expected: PASS.
- [ ] **Step 7: Commit**
```bash
git add internal/api/handlers/diagnostics.go internal/api/handlers/diagnostics_test.go internal/api/router.go internal/playback/transcode.go internal/api/handlers/playback.go
git commit -m "feat: expose playback diagnostics timeline"
```
---
### Task 5: Catalog Activity Endpoint And Scanner State
**Files:**
- Modify: `internal/api/handlers/diagnostics.go`
- Modify: `internal/scanqueue/service.go`
- Modify: `internal/api/router.go`
- Test: `internal/api/handlers/diagnostics_test.go`
- [ ] **Step 1: Extend diagnostics endpoint test**
Add this test to `internal/api/handlers/diagnostics_test.go`:
```go
func TestDiagnosticsHandlerReturnsCatalogActivity(t *testing.T) {
rec := diagnostics.NewRecorder(10)
rec.RecordCatalog(diagnostics.CatalogEvent{Kind: "catalog.query.cancelled", Route: "/catalog", LibraryID: 1, Reason: "client_cancelled"})
handler := NewDiagnosticsHandler(rec)
req := httptest.NewRequest(http.MethodGet, "/api/v1/admin/diagnostics/catalog/activity", nil)
rr := httptest.NewRecorder()
handler.HandleCatalogActivity(rr, req)
if rr.Code != http.StatusOK {
t.Fatalf("status = %d, want 200", rr.Code)
}
var body struct {
Events []diagnostics.CatalogEvent `json:"events"`
}
if err := json.Unmarshal(rr.Body.Bytes(), &body); err != nil {
t.Fatal(err)
}
if len(body.Events) != 1 || body.Events[0].Kind != "catalog.query.cancelled" {
t.Fatalf("body = %+v, want catalog activity", body)
}
}
```
- [ ] **Step 2: Run test**
Run:
```bash
go test ./internal/api/handlers -run 'TestDiagnosticsHandlerReturns(CatalogActivity|PlaybackTimeline)' -count=1
```
Expected: PASS if Task 4 handler already returns catalog events; FAIL if catalog endpoint was not implemented.
- [ ] **Step 3: Record catalog events in handler**
In `internal/api/handlers/catalog.go`, add an optional recorder field to `CatalogHandler` and record:
```go
h.Diagnostics.RecordCatalog(diagnostics.CatalogEvent{
Kind: "catalog.query.started",
RequestID: requestIDFromContext(r.Context()),
ClientTraceID: diagnostics.ClientTraceIDFromRequest(r),
Route: "/catalog",
Source: req.Source,
LibraryID: firstLibraryID(req.Query.LibraryIDs),
})
```
On success, record `catalog.query.completed` with duration. On context cancellation, record `catalog.query.cancelled` with reason `client_cancelled`.
- [ ] **Step 4: Add scan progress snapshots**
In `internal/scanqueue/service.go`, where `scan queue: progress` is logged, also record or expose the latest progress through a small `LatestRuns()` method. Return bounded state:
```go
type DiagnosticScanState struct {
ScanID string `json:"scan_id"`
LibraryID int `json:"library_id"`
Phase string `json:"phase"`
Message string `json:"message"`
ProcessedFiles int `json:"processed_files"`
TotalFiles int `json:"total_files"`
MatchedFiles int `json:"matched_files"`
RetriedItems int `json:"retried_items"`
}
```
Add this state to `GET /api/v1/admin/diagnostics/catalog/activity` under `active_scans`.
- [ ] **Step 5: Run tests**
Run:
```bash
go test ./internal/api/handlers ./internal/scanqueue -count=1
```
Expected: PASS.
- [ ] **Step 6: Commit**
```bash
git add internal/api/handlers/catalog.go internal/api/handlers/diagnostics.go internal/api/handlers/diagnostics_test.go internal/scanqueue/service.go internal/api/router.go
git commit -m "feat: expose catalog and scan diagnostic activity"
```
---
### Task 6: Remote Build And Live Verification
**Files:**
- No new source files unless previous tasks reveal compile fixes.
- [ ] **Step 1: Run focused local tests**
Run:
```bash
go test ./internal/diagnostics ./internal/api/handlers ./internal/api/middleware ./internal/playback ./internal/scanqueue -count=1
cd web && pnpm vitest run src/lib/clientTrace.test.ts src/lib/diagnostics/catalogActivity.test.ts
```
Expected: all tests pass.
- [ ] **Step 2: Build server**
Run:
```bash
go build ./cmd/silo
```
Expected: build exits 0.
- [ ] **Step 3: Install on `silo-new` native runtime**
Use the existing native install flow:
```bash
rsync -az --delete --exclude .git /Users/jimcole/projects/silo/silo-server/ root@silo-new:/tmp/silo-server-build/
ssh root@silo-new 'cd /tmp/silo-server-build && go test ./internal/diagnostics ./internal/api/handlers ./internal/api/middleware ./internal/playback ./internal/scanqueue -count=1 && go build -ldflags "-X main.buildVersion=diagnostic-spine" -o /opt/silo-native/silo ./cmd/silo && old=$(cat /opt/silo-native/silo.pid 2>/dev/null || true); [ -n "$old" ] && kill "$old" || true; nohup /opt/silo-native/run-host.sh >/opt/silo-native/logs/silo.log 2>&1 &'
```
Expected: remote tests pass, binary builds, native server restarts.
- [ ] **Step 4: Verify health**
Run:
```bash
ssh root@silo-new 'for i in $(seq 1 30); do curl -fsS http://127.0.0.1:8090/api/v1/health && exit 0; sleep 1; done; exit 1'
```
Expected: health JSON is returned.
- [ ] **Step 5: Verify diagnostics during reproduction**
While the user opens Movies and starts playback, run:
```bash
ssh root@silo-new 'tail -n 500 /opt/silo-native/logs/silo.log | grep -E "catalog.query|catalog.refetch|realtime.catalog|playback.ffmpeg|playback.first_segment|client_trace_id" | tail -n 120'
```
Expected: logs show why catalog queries/refetches happen and show playback first-segment timing with session IDs.
---
## Self-Review
- Spec coverage: correlation context is covered in Tasks 1-3; catalog cancellation/refetch diagnostics in Tasks 2-3 and 5; playback diagnostics endpoint in Task 4; scanner state in Task 5; remote verification in Task 6.
- Deferred intentionally: external Sentry/OpenTelemetry export and full metrics endpoint are not implemented in this first plan. The spec says to evaluate Sentry after context is in place, and metrics can follow once event fields are stable.
- Placeholder scan: no open-ended implementation steps remain.
- Type consistency: diagnostics event names and JSON field names match the design spec.
## Rollback Note
2026-06-06: Behavior-changing mitigations were intentionally rolled back so the next live test can reproduce and diagnose the original symptoms. Kept: diagnostics recorder, request/client trace IDs, catalog activity timeline, playback ffmpeg/segment timeline, and admin diagnostics endpoints. Rolled back: longer playback segment wait/restart gating, library-scoped realtime catalog refetch filtering, and catalog cancellation HTTP reclassification from 500 to 499.
@@ -0,0 +1,179 @@
# Diagnostic Spine Design
## Context
Two live issues showed that Silo can produce enough logs to debug a problem, but the evidence is too scattered:
- Playback startup can sit for 9-14 seconds before the first transcoded segment. The latest trace showed ffmpeg blocked in kernel file-read wait on `/mnt/sharedrives/zd-storage-ceph` while the scanner was active and host I/O wait was high.
- The Movies library page can repeatedly refresh while Movies International is scanning. Logs showed a frontend/API loop with many `/api/v1/catalog` requests and many client-cancelled catalog requests.
The goal is to make these failure modes obvious during normal operation, without adding a large observability platform dependency as a prerequisite.
## Goals
- Correlate frontend actions, API requests, catalog queries, playback sessions, ffmpeg processes, scan runs, and logs.
- Explain why a catalog query or playback request happened, not only that it happened.
- Add low-cardinality metrics for the problem areas we already know matter.
- Provide admin-only diagnostic views/endpoints that consolidate evidence for playback, catalog refresh loops, and active scans.
- Keep instrumentation portable so Silo can later send the same data to Sentry, OpenTelemetry, Grafana, or another backend.
## Non-Goals
- Do not build a full hosted/self-hosted observability stack in this step.
- Do not replace existing structured logs.
- Do not add high-cardinality metric labels such as raw paths, content IDs, query fingerprints, or playback session IDs.
- Do not expose diagnostic data to non-admin users.
## Architecture
### Correlation Context
Introduce a lightweight diagnostic context that can carry:
- `request_id`
- `trace_id`
- `user_id`
- `profile_id`
- `library_id`
- `content_id`
- `playback_session_id`
- `scan_id`
- `ffmpeg_pid`
- `route`
The request logger already has some of this data. The implementation should extend existing middleware and helper APIs rather than creating a parallel logging system.
Frontend requests should include a stable client-side action/request correlation header when practical, for example `X-Silo-Client-Trace-ID`. Backend logs should echo it when present and generate one when missing.
### Diagnostic Events
Add structured domain events for the places where "why did this happen?" matters:
- `catalog.query.started`
- `catalog.query.completed`
- `catalog.query.cancelled`
- `catalog.query.invalidated`
- `catalog.refetch.triggered`
- `realtime.catalog.event.received`
- `playback.ffmpeg.spawned`
- `playback.first_segment.ready`
- `playback.segment_gap.detected`
- `scanner.progress`
- `scanner.completed`
- `scanner.io_pressure.snapshot`
These events should be regular structured logs at first. Later they can be mirrored into Sentry breadcrumbs or OpenTelemetry spans/events.
### Metrics
Add minimal metrics with bounded labels:
- `silo_catalog_requests_total{route,status,source,library_id}`
- `silo_catalog_cancelled_total{route,source,library_id}`
- `silo_catalog_request_duration_ms{route,source,library_id}`
- `silo_playback_startup_ms{mode,video_codec,audio_codec,hw_accel}`
- `silo_playback_first_segment_ms{mode,video_codec,audio_codec,hw_accel}`
- `silo_scanner_files_processed_total{library_id,phase}`
- `silo_scanner_active{library_id}`
- `silo_host_iowait_percent`
Metric labels should use library IDs and coarse codec/mode values, never raw file paths or query JSON.
### Playback Diagnostics
Add an admin-only playback diagnostics endpoint:
`GET /api/v1/admin/diagnostics/playback/{session_id}`
It should return:
- session identity and content/library IDs
- ffmpeg command summary
- ffmpeg PID if still running
- process start time
- first segment observed time
- segment production timeline
- restart count
- startup wait/recovery decisions
- stderr tail when available
- recent host pressure snapshot if available
This endpoint should assemble existing in-memory/session state plus the new segment monitor data. It does not need to scrape old log files.
### Catalog Diagnostics
Add admin-only diagnostics for catalog/UI loops:
`GET /api/v1/admin/diagnostics/catalog/activity`
It should return recent activity for the current node:
- recent catalog queries
- query status: started, completed, cancelled
- route/source/library ID
- request ID and client trace ID
- invalidation/refetch reason when known
- active scan library IDs
- recent realtime catalog events
The frontend should also expose a development/admin diagnostics panel showing:
- active route
- active React Query catalog keys
- last catalog refetch triggers
- last realtime catalog events
- current scan libraries
- recent API cancellation counts
### Scanner Diagnostics
Surface active scanner state in one place:
- active scan ID
- library ID
- phase
- current scope
- processed/total files
- files per second
- matched/retried counters
- whether playback is currently reading from the same mount family when that can be inferred
This should reuse scan queue progress state rather than polling scanner internals separately.
## Error Handling
- Context cancellation should not be logged as a backend error when the client intentionally aborted the request. It should be recorded as a cancellation event/counter.
- Diagnostic endpoints must tolerate missing data and return partial results with clear fields instead of failing.
- If telemetry export fails in the future, normal Silo behavior must continue.
## Privacy And Security
- Admin diagnostics only.
- Avoid raw media paths in metrics and frontend diagnostic panels.
- Keep full ffmpeg command and raw paths restricted to admin endpoints and structured server logs.
- Redact tokens and authorization headers from any captured frontend/backend telemetry.
## Rollout Plan
1. Add correlation context and improve request/catalog cancellation logging.
2. Add playback diagnostic state and the playback diagnostics endpoint.
3. Add catalog invalidation/refetch reason logging in the frontend and backend request logs.
4. Add scanner state to admin diagnostics.
5. Add minimal metrics exports.
6. Evaluate hosted Sentry for frontend errors/session replay and backend traces once the diagnostic context is in place.
## Testing
- Unit test correlation extraction and propagation helpers.
- Unit test catalog cancellation classification so client aborts are not counted as internal server failures.
- Unit test playback diagnostic timeline assembly.
- Add frontend tests for catalog refetch reason recording and visible-range stability.
- Add integration-style tests for admin diagnostics endpoints with partial/missing data.
## Success Criteria
- A slow playback start can be explained from one session ID without SSHing into the host.
- A catalog refresh loop shows the trigger that caused each refetch.
- Scanning one library does not silently force unrelated active catalog views to refetch without a recorded reason.
- Context-cancelled catalog requests are visible as cancellations rather than noisy internal errors.
- Sentry or OpenTelemetry can be added later without rewriting the instrumentation surface.