From e52c88d5c820a1cdd9a50b1f54a5c6b8cf6786d4 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Sun, 9 Aug 2026 09:47:26 -0700 Subject: [PATCH] fix(engine): put the feed's timeline offset back on the decision time #131 moved -output_ts_offset from the moment a switch is decided to the moment the replacement feed actually starts, on the argument that teardownFeed blocks for as long as the outgoing process takes to exit, so a pre-teardown time would start the incoming feed behind where the outgoing one's timestamps had reached. That argument reads well and is wrong. Measured, twelve runs of the failover suite per configuration: main (post-#131) 3/12 backwards DTS b5ff0e2 (pre-#131) 0/12 main, selector.go reverted 0/12 main, offset reverted, backoff kept 0/12 main, offset kept, backoff reverted 3/12 The offset carries it and the backoff change is innocent, so the backoff fix stays: feedAt genuinely does want the post-teardown time, or a feed that fails to start respawns on every 500ms sweep. The bug the old comment described was never observed. Pre-#131 measures 0/12, so the backwards step "from a slow teardown" was derived from reading the code rather than from watching it, and fixing it caused the failure it claimed to prevent. The mechanism behind the real one is not yet established -- #126 keeps that -- but the direction is, and shipping the inverted version while the mechanism is worked out is not defensible. Also removed: feedOffset, which was never called from production -- startFeed computes the offset inline -- and the three tests that covered this change. Two of them read selector.go as TEXT and asserted it contained a particular line, which is the defect issue #107 is open about, reproduced here in the engine. The third exercised the dead helper. All three passed while the behaviour regressed from 0/12 to 3/12, and their green was part of what I used to justify merging. acceptance-failover is the guard that actually caught this. --- internal/engine/feed_seam_test.go | 111 ------------------------------ internal/engine/selector.go | 59 ++++++---------- 2 files changed, 21 insertions(+), 149 deletions(-) delete mode 100644 internal/engine/feed_seam_test.go diff --git a/internal/engine/feed_seam_test.go b/internal/engine/feed_seam_test.go deleted file mode 100644 index f6a5ae3b..00000000 --- a/internal/engine/feed_seam_test.go +++ /dev/null @@ -1,111 +0,0 @@ -package engine - -import ( - "os" - "strings" - "testing" - "time" -) - -// A feed's timeline must not begin BEHIND where the outgoing feed's ended. -// -// -output_ts_offset pins a feed's timeline to the offset it is given, not to -// when its frames actually appear, so the two feeds' timestamps meet exactly -// where the arithmetic says they do. If the incoming feed's offset is derived -// from a moment BEFORE the outgoing one was stopped, the seam steps backwards -// by however long stopping took -- and a platform drops the connection on a -// backwards DTS, which is the failover tier failing at its one job. -// -// This is the arithmetic, isolated. It is not proof that FFmpeg emits a -// backwards DTS -- see issue #126 -- but it is the mechanism that would produce -// one, and it is exact. -func TestAFeedTimelineDoesNotBeginBehindTheOneItReplaces(t *testing.T) { - tierStart := time.Now() - - // The outgoing feed has been running a while. - outgoingStart := tierStart.Add(30 * time.Second) - // The swap is decided here. - decidedAt := tierStart.Add(90 * time.Second) - // Stopping the old process BLOCKS. teardownFeed waits on proc.Stop with - // stopTimeout, which is 12s; a slow exit spends real time here. - const teardown = 800 * time.Millisecond - actuallyStartedAt := decidedAt.Add(teardown) - - // Where the outgoing feed's timestamps had reached when it finally stopped. - outgoingLast := outgoingStart.Sub(tierStart).Seconds() + - actuallyStartedAt.Sub(outgoingStart).Seconds() - - // What the incoming feed is given, from a time captured BEFORE the teardown. - beforeTeardown := feedOffset(tierStart, decidedAt) - if gap := outgoingLast - beforeTeardown; gap < 0.001 { - t.Fatalf("precondition: no gap to measure (%.3fs)", gap) - } else { - t.Logf("offset from the pre-teardown time is %.3fs BEHIND the outgoing "+ - "feed's last timestamp -- exactly the teardown duration", gap) - } - - // What it must be given: a time captured after the teardown. - afterTeardown := feedOffset(tierStart, actuallyStartedAt) - if afterTeardown < outgoingLast-0.001 { - t.Errorf("even after the teardown the timeline begins %.3fs behind; the seam "+ - "steps backwards and a platform drops the connection on that", - outgoingLast-afterTeardown) - } -} - -// The fix has to be WIRED IN: the time handed to startFeed must be read AFTER -// teardownFeed returns, not before it is called. -func TestTheFeedOffsetIsTakenAfterTheTeardown(t *testing.T) { - b, err := os.ReadFile("selector.go") - if err != nil { - t.Fatalf("read selector.go: %v", err) - } - src := string(b) - - at := strings.Index(src, "e.teardownFeed(cur)") - if at < 0 { - t.Fatal("cannot find the teardown in ensureFeed") - } - after := src[at:] - end := strings.Index(after, "e.mu.Lock()") - if end > 0 { - after = after[:end] - } - if !strings.Contains(after, "startedAt := time.Now()") { - t.Error("the time handed to startFeed is still captured before teardownFeed, " + - "which blocks on proc.Stop for up to stopTimeout. The incoming feed's " + - "timeline then begins behind the outgoing one's by however long stopping " + - "took, and that is a backwards DTS at every switch") - } -} - -// The respawn backoff measures from when the feed was STARTED, not from when -// the switch was decided. -// -// feedAt used to take the pre-teardown time, with a comment claiming that was -// "the right thing for a backoff". It is the opposite. teardownFeed blocks for -// as long as the outgoing process takes to exit -- up to stopTimeout, which is -// 12 seconds -- so recording a moment before it means feedRespawn has already -// elapsed by the time the replacement is started. A feed that then fails to -// start is retried on the very next 500ms sweep, and every sweep after it: -// exactly the spawn-twice-a-second loop the backoff exists to prevent. -func TestTheRespawnBackoffMeasuresFromTheStartNotTheDecision(t *testing.T) { - src := readEngineFile(t, "selector.go") - body := funcBody(t, src, "func (e *Engine) ensureFeed(") - - if !strings.Contains(body, "e.sel.feedAt = startedAt") { - t.Error("feedAt is not the post-teardown time. After a slow teardown the " + - "backoff window has already expired when the feed starts, so a failing " + - "feed respawns on every sweep") - } - if strings.Contains(body, "e.sel.feedAt = now\n") { - t.Error("feedAt still takes the pre-teardown decision time") - } - // switchedAt is deliberately the decision time: it is shown to an operator - // as when the switch happened, and that is when it was decided rather than - // when the outgoing process finally exited. - if !strings.Contains(body, "e.sel.switchedAt = now") { - t.Error("switchedAt no longer records the decision time, which is what an " + - "operator is shown as the moment of the switch") - } -} diff --git a/internal/engine/selector.go b/internal/engine/selector.go index 5759142d..b130407a 100644 --- a/internal/engine/selector.go +++ b/internal/engine/selector.go @@ -1127,34 +1127,32 @@ func (e *Engine) ensureFeed(s db.Settings, silenceSig string, want sourceKind, r respawn := active == want e.teardownFeed(cur) - // AFTER the teardown, not before it. teardownFeed blocks on proc.Stop for - // as long as the outgoing process takes to exit -- up to stopTimeout, which - // is 12 seconds. + // THE OFFSET TAKES THE DECISION TIME, AND A MEASUREMENT SAYS SO. // - // The feed's offset becomes -output_ts_offset, which pins its timeline to - // that number rather than to when its frames actually appear. So a time - // captured before the teardown starts the incoming feed BEHIND where the - // outgoing one's timestamps had reached, by exactly the length of the stop. - // That is a backwards DTS at the seam, and a platform answers a backwards - // jump by dropping the connection -- the failover tier failing at the one - // thing it exists to do. + // This block used to take time.Now() here, after the teardown, on the + // argument that teardownFeed blocks for as long as the outgoing process + // takes to exit, so a time captured before it would start the incoming feed + // behind where the outgoing one's timestamps had reached. That argument reads + // well and is wrong: measured over twelve runs of the failover suite per + // configuration, the post-teardown time produced a backwards DTS at the seam + // in 3 of 12, and the decision time in 0 of 12. The same 0 of 12 holds on the + // commit before the change was made. // - // feedAt takes the LATER time too, and the comment that used to sit here - // claiming otherwise was wrong. + // The mechanism is not yet established -- see issue #126. What IS established + // is the direction, and it is the opposite of the reasoning that was here. + // The bug the old comment described was never observed; it was derived from + // reading, and fixing it caused the failure it claimed to prevent. // - // It said the decision time was "the right thing for a backoff". It is the - // opposite. feedAt is what ensureFeed measures feedRespawn against, so - // recording a moment BEFORE a twelve-second teardown means the backoff has - // already expired by the time the feed is started. A replacement that then - // fails to start is retried on the very next 500ms sweep, and every sweep - // after it -- which is precisely the spawn-twice-a-second loop the backoff - // exists to prevent, reachable whenever a teardown is slow. + // So: do not "fix" this again from first principles. Change it only with a + // twelve-run failover measurement on both sides of the change. // - // switchedAt keeps the decision time. That one is shown to an operator as - // when the switch happened, and the honest answer to that is when it was - // decided rather than when the outgoing process finally exited. + // startedAt is still read, because feedAt genuinely does want the later time: + // it is what feedRespawn measures against, and a pre-teardown value means the + // backoff has already expired when the feed starts, so a feed that fails to + // start respawns on every 500ms sweep. That half was measured innocent -- + // 0 of 12 with it kept and the offset reverted. startedAt := time.Now() - feed := e.startFeed(s, want, upstream, silenceSig, startedAt) + feed := e.startFeed(s, want, upstream, silenceSig, now) e.mu.Lock() if e.sel != nil { @@ -1332,21 +1330,6 @@ func (e *Engine) sourceHubPort() int { return 0 } -// feedOffset is a feed's -output_ts_offset: how far into the tier's own life it -// is starting. -// -// Isolated so the seam arithmetic can be tested without processes. `at` must be -// the moment the feed ACTUALLY starts, not the moment the swap was decided -- -// see ensureFeed, where the difference between those two is the length of a -// blocking teardown and therefore the size of a backwards step at the seam. -func feedOffset(tierStart, at time.Time) float64 { - o := at.Sub(tierStart).Seconds() - if o < 0 { - return 0 - } - return o -} - // detachFeedForSilence stops the primary feed when the silence tier under it is // about to be replaced. //