fix(playout): differentiate FFmpeg crashes from clean exits and enrich health metrics

backend/playout/src/playlist.go

@@ -49,6 +49,8 @@ var (
 	lastSegmentSeq      uint64
 	lastR2PubTime       time.Time
 	consecutiveFails    int
+	lastFFmpegStartTime time.Time
+	lastFFmpegExitError error
 )
 
 const (
@@ -451,17 +453,22 @@ 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,
+		"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,
+		"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, "# HELP linearvoid_playout_crashes_total Total FFmpeg crashes (not clean completions).")
-		fmt.Fprintln(w, "# TYPE linearvoid_playout_restarts_total counter")
+		fmt.Fprintln(w, "# TYPE linearvoid_playout_crashes_total counter")
-		fmt.Fprintf(w, "linearvoid_playout_restarts_total %d\n", restartCount)
+		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
+		// After FFmpeg exits, sync remaining segments and publish manifest to R2.
-		restartCount++
+		// Do this before logging/restart logic so R2 is up to date regardless of exit cause.
-		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.
 		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)
 	}
 }