diff options
| -rw-r--r-- | CLAUDE.md | 13 | ||||
| -rw-r--r-- | docs/detection-findings.md | 83 | ||||
| -rw-r--r-- | server/cmd/listend/main.go | 18 | ||||
| -rw-r--r-- | server/internal/store/store.go | 31 | ||||
| -rw-r--r-- | server/internal/store/store_test.go | 82 |
5 files changed, 223 insertions, 4 deletions
@@ -296,6 +296,19 @@ by default and correct; it is simply waiting for a publisher who marks breaks. 71% and 105%. First time in this project that detection has been checked against external ground truth and agreed. + **Detection runs once per batch, not once per poll.** `Show.DetectedBatch` holds the set of + episode ids the last completed pass examined; `pollOne` skips detection when the batch is + unchanged. Without it the server re-derived identical results every cycle -- 4.5 hours of work + against a two-hour poll interval, so it never idled. The batch is the unit because every + result depends on which other episodes it was compared against, so one arrival or one pruning + must re-run all of them. `Episode.DetectedAtUnix` cannot serve as this gate: it is only set + for episodes that appear in `result.Offsets`. + + **Do not filter breaks by partner count or run length.** It looks obviously right -- 40% of + breaks have one partner and a 5s median -- and it is wrong: measured against the declared + length gap it drops agreement from 67% to 43%. Detection already under-reports. Table in + `docs/detection-findings.md`. + Breaks are published as ranges into `episode_midrolls`, which `MidrollSkip` and `PlayheadPolicy` already read -- no playback changes, no migration. Two guards publish nothing rather than something wrong: an episode whose matches cover over 35% of it, and any single diff --git a/docs/detection-findings.md b/docs/detection-findings.md index 35c4525..c821062 100644 --- a/docs/detection-findings.md +++ b/docs/detection-findings.md @@ -668,3 +668,86 @@ Found by reading the journal after a restart, not by a test: State is also saved after every feed now, so a restart costs one feed's progress rather than a whole cycle's. + +## Detection re-ran forever, and what the first full corpus then showed + +The first complete pass over Peter's 42 feeds finished on 2026-10-06: 322 episodes mirrored, +286 publishing ad breaks. It then kept going over the same unchanged files, producing results +identical to the digit -- Radiolab reported "53:29 of 59:39" four separate times in one day. + +`pollOne` called `detect` unconditionally, and the mirror skips files it already has, so nothing +had changed between passes. One cycle is ~6.5 minutes a show, 4.5 hours for 42 shows, against a +two-hour poll interval: the machine never finished a cycle and never idled -- 13h42m of CPU in +11h of wall clock. Roughly 60% of that was the intro/outro search whose results are deliberately +not published. + +`Episode.DetectedAtUnix` existed but could not be used as the gate: it is only set for episodes +that appear in `result.Offsets`, so an episode nothing was found in never got a timestamp and +the gate would never close. The unit is the batch anyway -- every offset and every break is +found by comparing an episode against the others fetched alongside it, so one arrival or one +pruning legitimately changes all of them. `Show.DetectedBatch` records the set of episode ids +the last completed pass examined, order-independent because feeds are not reliably sorted. +Recorded only after a pass completes, so a cancelled or failed one is retried. + +Deployed 2026-10-07 with the field backfilled for the 42 shows already examined, which saved an +immediate 4.5-hour redundant cycle. Verified in production: 31 feeds polled in five minutes with +exactly one detection running -- The Ezra Klein Show, which had genuinely gained an episode. + +### Filtering by partner count or run length is wrong, and the length gap proves it + +The obvious cleanup is to drop weakly-supported breaks. 635 of 1574 published breaks (40%) have +`partners == 1`, with a median length of 5.0s against 19.0s for `partners >= 4` -- they look +exactly like correlation noise, and 270 of them sit at `MinRunSamples`, the 4-second floor. + +Measured against the declared-versus-served length gap -- the one figure the detector does not +produce -- every such filter makes agreement **worse**: + +| filter | median found/inserted | within 75-125% | skipping on shows with no gap | +|---|---|---|---| +| none (current) | 67% | 31% | 164 min | +| `partners >= 2` | 43% | 17% | 141 min | +| `partners >= 3` | 39% | 13% | 127 min | +| length >= 8s | 58% | 24% | 141 min | +| both | 41% | 13% | 130 min | + +Detection already **under**-reports -- a 67% median means a third of the advertising is missed -- +so removing breaks moves away from the truth, and it barely dents the unverifiable skipping it +was meant to clean up. The single-partner short runs are mostly real advertising. Hypothesis +disproven; the thresholds stay as they are. + +### What is worth fixing is fragmentation + +45% of the gaps between consecutive breaks are under ten seconds, and **152 of 262** multi-break +episodes contain at least one such gap -- which plays as a skip, one to nine seconds of audible +advertisement, then another skip. `merge` only folds breaks that overlap or touch. + +Merging across a tolerance both cleans that up and moves agreement the right way, because the +bridged gap was advertising too: + +| merge tolerance | median found/inserted | within 75-125% | total breaks | +|---|---|---|---| +| 0s (current) | 69% | 32% | 1240 | +| 2s | 70% | 33% | 973 | +| 5s | 70% | 34% | 885 | +| 10s | 73% | 34% | 820 | +| 15s | 73% | 35% | 786 | + +### Sleepy History was not eating the programme + +Reported on 2026-10-06 as finding 117:42 of "advertising" in a show whose feed declares no +inserted ads at all. That reading was wrong: it was a show-level sum, and almost all of it sat +inside the two episodes the 35% guard **already refused** -- a 3h08m Rosa Parks compilation that +literally contains other episodes (53:41 matched) and Antarctica (22:30). + +The six episodes that do publish skip 0:34 to 4:33 each, under 10% of their runtime, and the +largest block in each is a genuine closing segment shared by every episode in the batch -- +`48:20-51:36 partners=22`, `46:19-49:19 partners=26`. That is the show's own outro, which is what +intro/outro detection was supposed to find in the first place. The rest is 4-second floor noise. + +Across the whole corpus only 4 of 279 published episodes skip more than 20% of their runtime, and +all but one are corroborated by the length gap to within a minute. The exception is The Trip +(3:54 of 14:51, no declared gap), which is the one show worth watching. + +Sleepy History also serves files consistently **shorter** than declared -- 50:59 declared against +49:23 served, about 1:36 short on every episode -- so `Accounting` reports a zero gap for it. A +feed can be wrong in that direction too, and when it is there is no external check available. diff --git a/server/cmd/listend/main.go b/server/cmd/listend/main.go index 04c933f..3e5c65a 100644 --- a/server/cmd/listend/main.go +++ b/server/cmd/listend/main.go @@ -278,6 +278,7 @@ func (w *worker) pollOne(ctx context.Context, feedURL string) { // over weeks and lost it whenever retention reclaimed the file it was holding. func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*store.Episode) { var episodes []skips.Episode + var ids []string byID := map[string]*store.Episode{} for _, e := range candidates { if !e.Mirrored() { @@ -288,11 +289,15 @@ func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*sto Path: filepath.Join(w.mirror.AudioDir, e.Path), DeclaredDurationMs: e.DeclaredDurationMs, }) + ids = append(ids, e.ID) byID[e.ID] = e } if len(episodes) < skips.DefaultConfirmThreshold || ctx.Err() != nil { return } + if !show.NeedsDetection(ids) { + return + } started := time.Now() result, err := skips.Detect(ctx, w.decoder, episodes, skips.DefaultConfig()) @@ -323,7 +328,9 @@ func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*sto result.OutroConfirmedOn, len(episodes), checkNote(result.OutroCheck), time.Since(started).Round(time.Second)) - w.detectAds(ctx, show, episodes, byID) + if w.detectAds(ctx, show, episodes, byID) { + show.RecordDetected(ids) + } } // detectAds finds the advertising a batch of episodes shares, which is what simultaneous @@ -334,20 +341,22 @@ func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*sto // is how it came to confirm an advertisement as an intro. This uses that dependence rather than // being defeated by it -- and reports what it found against the declared-versus-served length // gap, a figure it did not produce and which can therefore contradict it. +// Reports whether the scan completed, so an interrupted or failed pass is examined again rather +// than written off as done. func (w *worker) detectAds( ctx context.Context, show *store.Show, episodes []skips.Episode, byID map[string]*store.Episode, -) { +) bool { if ctx.Err() != nil { - return + return false } started := time.Now() ads, err := skips.DetectAds(ctx, w.decoder, episodes, skips.DefaultAdConfig()) if err != nil { log.Printf("%s: ad scan failed: %v", show.Title, err) - return + return false } var withBreaks, refused int @@ -381,6 +390,7 @@ func (w *worker) detectAds( log.Printf("%s: ads on %d/%d episode(s)%s, accounted %s of %s inserted, took %s", show.Title, withBreaks, len(episodes), refusedNote(refused), clock(foundTotal), clock(insertedTotal), time.Since(started).Round(time.Second)) + return true } func refusedNote(refused int) string { diff --git a/server/internal/store/store.go b/server/internal/store/store.go index a67e637..51e4ed7 100644 --- a/server/internal/store/store.go +++ b/server/internal/store/store.go @@ -75,6 +75,10 @@ type Show struct { // says so instead of silently having nothing. LastPolledUnix int64 `json:"lastPolledUnix,omitempty"` LastError string `json:"lastError,omitempty"` + + // DetectedBatch is the set of episodes the last detection pass examined. Stored as the + // plain ids rather than a hash so the state file says what was actually done. + DetectedBatch string `json:"detectedBatch,omitempty"` } // Partition splits a show's episodes into the newest keep and everything else, newest first. @@ -316,3 +320,30 @@ func matchIn(show *Show, guid, enclosureURL, title string) *Episode { } return nil } + +// NeedsDetection reports whether this batch of episodes still has to be examined. +// +// The batch is the unit, not the episode: every offset and every ad break is found by comparing +// an episode against the others fetched alongside it, so one arrival or one pruning legitimately +// changes all of them. An unchanged batch, though, produces results identical to the digit -- +// and re-deriving them cost four minutes a show against a two-hour poll interval, which for +// forty-two shows meant the machine never finished a cycle and never idled. +func (s *Show) NeedsDetection(episodeIDs []string) bool { + return s.DetectedBatch != batchKey(episodeIDs) +} + +// RecordDetected notes that this exact batch has been examined. +// +// Called only after a pass completes, so a cancelled or failed one is retried rather than +// written off. +func (s *Show) RecordDetected(episodeIDs []string) { + s.DetectedBatch = batchKey(episodeIDs) +} + +// batchKey identifies a set of episodes irrespective of order, which matters because feeds are +// not reliably sorted: the same eight episodes arriving shuffled must not read as a change. +func batchKey(episodeIDs []string) string { + ordered := append([]string(nil), episodeIDs...) + sort.Strings(ordered) + return strings.Join(ordered, " ") +} diff --git a/server/internal/store/store_test.go b/server/internal/store/store_test.go index cd5cf6f..0540fbf 100644 --- a/server/internal/store/store_test.go +++ b/server/internal/store/store_test.go @@ -237,3 +237,85 @@ func TestSaveIsAtomic(t *testing.T) { } } } + +// Detection is the expensive thing this server does -- four minutes a show -- and it used to +// re-run on every poll over episodes that had not changed, producing results identical to the +// digit. Forty-two shows at ~6.5 minutes each is 4.5 hours of work against a two-hour poll +// interval, so the machine never finished a cycle and never idled. +// +// The batch is what has to match, not the individual episode: every answer depends on which +// other episodes it was compared against, so one new episode legitimately changes all of them. + +func TestAShowNotYetExaminedNeedsDetection(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", []feed.Episode{ep("g1", "One", "https://cdn/1.mp3", 100)}) + + if !show.NeedsDetection([]string{"a", "b"}) { + t.Fatal("a show that has never been examined should need detection") + } +} + +func TestTheSameBatchIsNotExaminedTwice(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + + show.RecordDetected([]string{"a", "b", "c"}) + + if show.NeedsDetection([]string{"a", "b", "c"}) { + t.Fatal("re-examining an unchanged batch; this is the rerun that pegged the server") + } +} + +func TestANewEpisodeInTheBatchNeedsDetectionAgain(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + show.RecordDetected([]string{"a", "b", "c"}) + + if !show.NeedsDetection([]string{"a", "b", "c", "d"}) { + t.Fatal("a new episode changes what every other episode is compared against") + } +} + +func TestAPrunedEpisodeNeedsDetectionAgain(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + show.RecordDetected([]string{"a", "b", "c"}) + + if !show.NeedsDetection([]string{"b", "c"}) { + t.Fatal("losing an episode changes the comparison too") + } +} + +// Feeds are not reliably ordered, and Partition sorts by publish date, so the same eight +// episodes can arrive in a different order. Treating that as a change would never close +// the gate. +func TestTheOrderOfTheBatchDoesNotMatter(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + show.RecordDetected([]string{"a", "b", "c"}) + + if show.NeedsDetection([]string{"c", "a", "b"}) { + t.Fatal("the same batch in a different order is the same batch") + } +} + +// Otherwise every restart redoes every show -- which at 4.5 hours a cycle is most of a day. +func TestWhatHasBeenExaminedSurvivesARestart(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "state.json") + + s := New() + s.Merge("https://f", "A Show", nil) + s.Show("https://f").RecordDetected([]string{"a", "b"}) + if err := s.Save(path); err != nil { + t.Fatalf("save: %v", err) + } + + loaded, err := Load(path) + if err != nil { + t.Fatalf("load: %v", err) + } + if loaded.Show("https://f").NeedsDetection([]string{"a", "b"}) { + t.Fatal("a restart would redo every show") + } +} |