Log both copies' lengths when a second fetch lands

The first thing to look at when subtraction finds nothing in a refetched episode
is whether the two fetches differed at all. Two copies that came back the same
length probably carried the same campaign, and there is then nothing for
subtraction to see -- which is a different problem from the alignment failing,
and the readout should not make them look alike.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_018AwnALZL6bD4VBtATDVv3B

2 files changed, 71 insertions, 9 deletions

diff --git a/server/cmd/listend/main.go b/server/cmd/listend/main.go
index d8c9d0c..8620d0d 100644
--- a/server/cmd/listend/main.go
+++ b/server/cmd/listend/main.go
@@ -706,7 +706,7 @@ func (w *worker) refetchSome(ctx context.Context) {
 		if ctx.Err() != nil || time.Now().After(deadline) {
 			break
 		}
-		found, err := w.refetchOne(ctx, e)
+		found, secondMs, err := w.refetchOne(ctx, e)
 		if ctx.Err() != nil {
 			return
 		}
@@ -730,7 +730,11 @@ func (w *worker) refetchSome(ctx context.Context) {
 		breaker.Success()
 		failing = nil
 		done++
-		log.Printf("second copy of %q: %d lines, %s", e.Title, e.MasterCues, adAccounting(e, found))
+		// The two lengths are the first thing to look at when this finds nothing: two fetches
+		// that came back the same length probably carried the same campaign, and there is
+		// then nothing for subtraction to see.
+		log.Printf("second copy of %q: %s against the mirrored %s, %d lines, %s",
+			e.Title, clock(secondMs), clock(e.DurationMs), e.MasterCues, adAccounting(e, found))
 		w.save()
 	}
 	if done > 0 || failed > 0 {
@@ -741,18 +745,20 @@ func (w *worker) refetchSome(ctx context.Context) {
 
 // refetchOne downloads one episode again, recognises it, keeps the words and throws the audio
 // away.
-func (w *worker) refetchOne(ctx context.Context, e *store.Episode) ([]transcript.Candidate, error) {
+func (w *worker) refetchOne(
+	ctx context.Context, e *store.Episode,
+) ([]transcript.Candidate, int64, error) {
 	// Its own id and its own directory, so nothing can mistake this for the copy the phone
 	// plays even for the moment it exists.
 	second := &store.Episode{ID: e.ID + "-second", EnclosureURL: e.EnclosureURL}
 	if err := w.refetchMirror.Fetch(ctx, second); err != nil {
-		return nil, err
+		return nil, 0, err
 	}
 	defer func() { _ = w.refetchMirror.Prune(second) }()
 
 	result, err := w.recogniser.Transcribe(ctx, filepath.Join(w.refetchDir, second.Path))
 	if err != nil {
-		return nil, err
+		return nil, second.DurationMs, err
 	}
 	if err := w.transcripts.PutMaster(transcript.Transcript{
 		EpisodeID:    e.ID,
@@ -760,7 +766,7 @@ func (w *worker) refetchOne(ctx context.Context, e *store.Episode) ([]transcript
 		LanguageCode: result.LanguageCode,
 		Cues:         result.Cues,
 	}); err != nil {
-		return nil, err
+		return nil, second.DurationMs, err
 	}
 	e.MasterCues = len(result.Cues)
 	e.MasterSource = string(transcript.SourceRefetch)
@@ -769,13 +775,13 @@ func (w *worker) refetchOne(ctx context.Context, e *store.Episode) ([]transcript
 	// Re-derive this episode's advertising now that there is something to subtract it from.
 	held, err := w.transcripts.Get(e.ID)
 	if err != nil {
-		return nil, err
+		return nil, second.DurationMs, err
 	}
 	held.Ads = w.adsIn(e, held.Cues)
 	if err := w.transcripts.Put(held); err != nil {
-		return nil, err
+		return nil, second.DurationMs, err
 	}
-	return held.Ads, nil
+	return held.Ads, second.DurationMs, nil
 }
 
 /*
diff --git a/server/cmd/second-probe/main.go b/server/cmd/second-probe/main.go
new file mode 100644
index 0000000..1d2a840
--- /dev/null
+++ b/server/cmd/second-probe/main.go
@@ -0,0 +1,56 @@
+// Command second-probe subtracts a recognised second fetch from the mirrored copy. Throwaway.
+package main
+
+import (
+	"flag"
+	"fmt"
+	"os"
+	"path/filepath"
+
+	"github.com/terst/listen/server/internal/transcribe"
+	"github.com/terst/listen/server/internal/transcript"
+)
+
+func main() {
+	episode := flag.String("episode", "", "episode id")
+	secondFile := flag.String("second", "", "whisper -oj output for the second fetch")
+	servedMs := flag.Int64("served", 0, "")
+	declaredMs := flag.Int64("declared", 0, "")
+	show := flag.Bool("show", false, "")
+	flag.Parse()
+
+	store := transcript.Store{Dir: "/site/listen.terst.org/data/transcripts"}
+	mirrored, err := store.Get(*episode)
+	if err != nil {
+		panic(err)
+	}
+	raw, err := os.ReadFile(*secondFile)
+	if err != nil {
+		panic(err)
+	}
+	second, err := transcribe.ParseOutput(raw)
+	if err != nil {
+		panic(err)
+	}
+	fmt.Printf("mirrored %d cues, second %d cues\n", len(mirrored.Cues), len(second.Cues))
+
+	found := transcript.Inserted(second.Cues, mirrored.Cues)
+	var total int64
+	for _, c := range found {
+		total += c.EndMs - c.StartMs
+		fmt.Printf("  %s-%s (%s)\n", clock(c.StartMs), clock(c.EndMs), clock(c.EndMs-c.StartMs))
+		if *show {
+			for _, cue := range mirrored.Cues {
+				if cue.StartMs >= c.StartMs && cue.EndMs <= c.EndMs {
+					fmt.Printf("      %.88s\n", cue.Text)
+				}
+			}
+		}
+	}
+	gap := *servedMs - *declaredMs
+	fmt.Printf("\n%d pods, %s found of the %s inserted (%d%%)\n",
+		len(found), clock(total), clock(gap), total*100/gap)
+	_ = filepath.Join
+}
+
+func clock(ms int64) string { return fmt.Sprintf("%d:%02d", ms/1000/60, ms/1000%60) }