diff --git a/backend/playout/src/playlist.go b/backend/playout/src/playlist.go index 3fa21d9..2fd7cb5 100644 --- a/backend/playout/src/playlist.go +++ b/backend/playout/src/playlist.go @@ -44,11 +44,13 @@ var ( segSequence uint64 // Health endpoint detail (STREAMING.md contract) - activeItem string - playlistRevision string - lastSegmentSeq uint64 - lastR2PubTime time.Time - consecutiveFails int + activeItem string + playlistRevision string + lastSegmentSeq uint64 + lastR2PubTime time.Time + consecutiveFails int + lastFFmpegStartTime time.Time + lastFFmpegExitError error ) const ( @@ -451,18 +453,23 @@ func HealthHandler(w http.ResponseWriter, r *http.Request) { status = "unhealthy" } + lastExit := "" + if lastFFmpegExitError != nil { + lastExit = lastFFmpegExitError.Error() + } resp := map[string]any{ - "status": status, - "service": "playout", - "mode": playoutMode, - "restarts": restartCount, - "run_id": runID, - "active_item": activeItem, - "playlist_revision": playlistRevision, - "last_segment_seq": lastSegmentSeq, - "last_r2_pub": lastR2PubTime.UTC().Format(time.RFC3339), + "status": status, + "service": "playout", + "mode": playoutMode, + "crash_count": restartCount, + "run_id": runID, + "active_item": activeItem, + "playlist_revision": playlistRevision, + "last_segment_seq": lastSegmentSeq, + "last_r2_pub": lastR2PubTime.UTC().Format(time.RFC3339), "consecutive_failures": consecutiveFails, - "timestamp": time.Now().UTC().Format(time.RFC3339), + "last_exit_error": lastExit, + "timestamp": time.Now().UTC().Format(time.RFC3339), } json.NewEncoder(w).Encode(resp) } @@ -588,9 +595,9 @@ func main() { http.HandleFunc("/health", HealthHandler) http.HandleFunc("/metrics", func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "text/plain; version=0.0.4; charset=utf-8") - fmt.Fprintln(w, "# HELP linearvoid_playout_restarts_total Total FFmpeg restarts.") - fmt.Fprintln(w, "# TYPE linearvoid_playout_restarts_total counter") - fmt.Fprintf(w, "linearvoid_playout_restarts_total %d\n", restartCount) + fmt.Fprintln(w, "# HELP linearvoid_playout_crashes_total Total FFmpeg crashes (not clean completions).") + fmt.Fprintln(w, "# TYPE linearvoid_playout_crashes_total counter") + fmt.Fprintf(w, "linearvoid_playout_crashes_total %d\n", restartCount) fmt.Fprintln(w, "# HELP linearvoid_playout_mode Current playout mode (0=live, 1=slate, 2=degraded).") fmt.Fprintln(w, "# TYPE linearvoid_playout_mode gauge") modeVal := 0 @@ -633,7 +640,9 @@ func main() { go watchAndPublishSegments(watchCtx, hlsDir) } - fmt.Printf("[%s] Starting FFmpeg playout with browser-safe H.264/AAC HLS encoding...\n", time.Now().Format(time.RFC3339)) + lastFFmpegStartTime = time.Now() + fmt.Printf("[%s] Starting FFmpeg playout (run %s) with browser-safe H.264/AAC HLS encoding...\n", + lastFFmpegStartTime.UTC().Format(time.RFC3339), runID) cmd := exec.Command("ffmpeg", "-re", "-f", "concat", "-safe", "0", "-i", playlistPath, "-map", "0:v:0", "-map", "0:a:0?", @@ -652,34 +661,15 @@ func main() { filepath.Join(hlsDir, "playlist.m3u8")) runErr := cmd.Run() + runDuration := time.Since(lastFFmpegStartTime) + lastFFmpegExitError = runErr + if watchCancel != nil { watchCancel() // Stop the filesystem watcher } - // Track restart and check for slate escalation - restartCount++ - fmt.Printf("[%s] FFmpeg exited (restart #%d in window): %v\n", - time.Now().Format(time.RFC3339), restartCount, runErr) - - if shouldEscalateToSlate() { - fmt.Printf("[%s] CRITICAL: %d restarts in 60s — escalating to slate fallback\n", - time.Now().Format(time.RFC3339), restartCount) - if err := activateSlate(); err != nil { - fmt.Printf("[%s] Slate activation failed: %v — will retry\n", - time.Now().Format(time.RFC3339), err) - } - // Stay in slate mode, retry recovery after delay - time.Sleep(30 * time.Second) - continue - } - - // If we were in slate but FFmpeg ran successfully, we recovered - if playoutMode == "slate" { - deactivateSlate() - } - - // After FFmpeg run, publish remaining segments and atomic manifest to R2. - // Skipped when R2 is not configured. + // After FFmpeg exits, sync remaining segments and publish manifest to R2. + // Do this before logging/restart logic so R2 is up to date regardless of exit cause. if r2Client != nil { if err := syncLatestToR2(hlsDir); err != nil { fmt.Println("R2 sync warning:", err) @@ -692,7 +682,44 @@ func main() { } } - time.Sleep(5 * time.Second) + // Differentiate clean playlist completion from FFmpeg crash. + // A nil error means FFmpeg completed the playlist normally — not a crash. + if runErr == nil { + fmt.Printf("[%s] Playlist completed normally after %s. Looping...\n", + time.Now().UTC().Format(time.RFC3339), runDuration.Round(time.Second)) + // If we were in slate mode, a successful run means recovery + if playoutMode == "slate" { + deactivateSlate() + } + // Minimal delay for clean loop — just enough for watcher goroutine cleanup + time.Sleep(500 * time.Millisecond) + continue + } + + // FFmpeg exited with an error — this is a real crash + restartCount++ + fmt.Printf("[%s] FFmpeg CRASHED after %s (crash #%d in window): %v\n", + time.Now().UTC().Format(time.RFC3339), runDuration.Round(time.Second), restartCount, runErr) + + if shouldEscalateToSlate() { + fmt.Printf("[%s] CRITICAL: %d crashes in 60s — escalating to slate fallback\n", + time.Now().UTC().Format(time.RFC3339), restartCount) + if err := activateSlate(); err != nil { + fmt.Printf("[%s] Slate activation failed: %v — will retry\n", + time.Now().UTC().Format(time.RFC3339), err) + } + // Stay in slate mode, retry recovery after delay + time.Sleep(30 * time.Second) + continue + } + + // If we were in slate but FFmpeg ran long enough to be a recovery, deactivate slate + if playoutMode == "slate" && runDuration > 30*time.Second { + deactivateSlate() + } + + // Backoff delay after crash before retry + time.Sleep(2 * time.Second) } }