1 files changed, 75 insertions, 8 deletions
diff --git a/server/cmd/listend/main.go b/server/cmd/listend/main.go
index 1b746f1..d93325d 100644
--- a/server/cmd/listend/main.go
+++ b/server/cmd/listend/main.go
@@ -376,12 +376,18 @@ func (w *worker) pollOne(ctx context.Context, feedURL string) {
 // every poll would be work done for ever to reach the same answer -- and the refusal is itself
 // the record of which episodes speech recognition would have to do.
 func (w *worker) harvestTranscripts(ctx context.Context, show *store.Show, candidates []*store.Episode) {
-	taken, declined, spotted := 0, 0, 0
+	taken, declined, spotted, masters := 0, 0, 0, 0
 	for _, e := range candidates {
 		if ctx.Err() != nil {
 			return
 		}
-		if !e.Mirrored() || e.TranscriptExamined() || e.TranscriptURL == "" {
+		// A declined episode is examined and has no words, but its publisher's transcript is
+		// still the ad-free master and is worth fetching -- it is what Inserted subtracts.
+		// Episodes declined before masters were kept arrive here once.
+		if !e.Mirrored() || e.TranscriptURL == "" {
+			continue
+		}
+		if e.TranscriptExamined() && !e.NeedsMaster() {
 			continue
 		}
 		result, err := w.harvester.Harvest(ctx, transcript.Offer{
@@ -396,6 +402,15 @@ func (w *worker) harvestTranscripts(ctx context.Context, show *store.Show, candi
 			log.Printf("%s: transcript for %q: %v", show.Title, e.Title, err)
 			continue
 		}
+		if result.Master > 0 {
+			e.MasterCues = result.Master
+			e.MasterNote = ""
+			masters++
+		} else if e.NeedsMaster() {
+			// Offered, fetched, and not usable as a master either. Recorded so it is not
+			// fetched again on every poll for ever.
+			e.MasterNote = result.Note
+		}
 		switch {
 		case result.Stored:
 			e.TranscriptSource = string(transcript.SourcePublished)
@@ -410,11 +425,12 @@ func (w *worker) harvestTranscripts(ctx context.Context, show *store.Show, candi
 			declined++
 		}
 	}
-	if taken > 0 || declined > 0 {
+	if taken > 0 || declined > 0 || masters > 0 {
 		// The ad count is reported, not acted on. These are candidates read out of the words,
 		// and nothing publishes them as ranges to skip -- see transcript.Spot.
-		log.Printf("%s: transcripts -- took %d, declined %d, %d ad candidate(s) in the words",
-			show.Title, taken, declined, spotted)
+		log.Printf("%s: transcripts -- took %d, declined %d (%d kept as ad-free masters), "+
+			"%d ad candidate(s) in the words",
+			show.Title, taken, declined, masters, spotted)
 	}
 }
 
@@ -473,7 +489,7 @@ func (w *worker) transcribeSome(ctx context.Context) {
 			Source:       transcript.SourceASR,
 			LanguageCode: result.LanguageCode,
 			Cues:         result.Cues,
-			Ads:          transcript.Spot(result.Cues),
+			Ads:          w.adsIn(e, result.Cues),
 		}
 		if err := w.transcripts.Put(stored); err != nil {
 			log.Printf("transcribe %q: %v", e.Title, err)
@@ -499,8 +515,9 @@ func (w *worker) transcribeSome(ctx context.Context) {
 		done++
 		breaker.Success()
 		failing = nil
-		log.Printf("transcribed %q: %d lines, %d ad candidate(s), took %s",
-			e.Title, len(stored.Cues), len(stored.Ads), time.Since(started).Round(time.Second))
+		log.Printf("transcribed %q: %d lines, %s, took %s",
+			e.Title, len(stored.Cues), adAccounting(e, stored.Ads),
+			time.Since(started).Round(time.Second))
 		w.save()
 	}
 
@@ -510,6 +527,31 @@ func (w *worker) transcribeSome(ctx context.Context) {
 	}
 }
 
+/*
+adsIn works out which stretches of a recognised episode are advertising.
+
+By subtraction where the publisher's ad-free master is held, and by reading the ad copy where it
+is not. They are not close in quality and the choice is not a preference. Measured on Darknet
+Diaries' "Conti": the feed declares 59:17 and the file served runs 63:33, so 4:15 of advertising
+was inserted -- subtraction found 4:20 of it in three pods, each starting on the first word of
+an ad read and ending on the last, while reading the copy found 0:16. 102% against 6%.
+
+Subtraction wins because it is a measurement. The master says what the programme is, the
+recognised copy says what was played, and the difference is the advertising by definition --
+there is no phrase list to be wrong about, and no show whose hosts happen to talk like an
+advertisement.
+*/
+func (w *worker) adsIn(e *store.Episode, cues []transcript.Cue) []transcript.Candidate {
+	if e.MasterCues > 0 {
+		if master, err := w.transcripts.Master(e.ID); err == nil {
+			if found := transcript.Inserted(master.Cues, cues); len(found) > 0 {
+				return found
+			}
+		}
+	}
+	return transcript.Spot(cues)
+}
+
 // giveBackAttempts unmarks episodes that failed for a reason that was nothing to do with them,
 // so they are tried again rather than hidden for ever.
 func giveBackAttempts(episodes []*store.Episode) {
@@ -518,6 +560,31 @@ func giveBackAttempts(episodes []*store.Episode) {
 	}
 }
 
+/*
+adAccounting describes what was found against what the lengths say is there.
+
+The declared-versus-served gap comes from the feed and the file rather than from any detector,
+which makes it the one number able to contradict one. Every other readout in this project that
+reported only what it found turned out to be hiding something.
+*/
+func adAccounting(e *store.Episode, found []transcript.Candidate) string {
+	var total int64
+	for _, c := range found {
+		total += c.EndMs - c.StartMs
+	}
+	how := "read from the ad copy"
+	if e.MasterCues > 0 {
+		how = "by subtracting the publisher's master"
+	}
+	gap := e.DurationMs - e.DeclaredDurationMs
+	if gap <= 0 {
+		return fmt.Sprintf("%d ad candidate(s) %s, %s; nothing was inserted into this copy",
+			len(found), how, clock(total))
+	}
+	return fmt.Sprintf("%d ad candidate(s) %s, %s of the %s inserted (%d%%)",
+		len(found), how, clock(total), clock(gap), total*100/gap)
+}
+
 // pendingRecognition is every mirrored episode still without words, newest first.
 func (w *worker) pendingRecognition() []*store.Episode {
 	var pending []*store.Episode