Restore concise transcode lifecycle logs

Author: tces1

internal/proxy/server.go

@@ -135,7 +135,8 @@ func (s *Server) observePlaybackCheckIn(kind string, r *http.Request) {
 	switch kind {
 	case "stopped":
 		stopped := s.transcodeManager.StopPlayback(event)
-		logging.Debugf("playback stopped item=%s play_session=%s stopped_sessions=%d", event.ItemID, event.PlaySessionID, stopped)
+		logging.Infof("playback stopped item=%s stopped_sessions=%d", event.ItemID, stopped)
+		logging.Debugf("playback stopped detail item=%s play_session=%s stopped_sessions=%d", event.ItemID, event.PlaySessionID, stopped)
 	case "playing", "progress":
 		updated := s.transcodeManager.RecordProgress(event)
 		logging.Debugf("playback %s item=%s play_session=%s position_ticks=%d paused=%t updated_sessions=%d", kind, event.ItemID, event.PlaySessionID, event.PositionTicks, event.IsPaused, updated)

internal/transcode/ffmpeg_args_test.go

@@ -153,3 +153,12 @@ func TestNewManagerFallsBackToSoftwareDecodeWhenHardwareProbeFails(t *testing.T)
 		t.Fatalf("expected runner to use software decode, options = %+v", runner.Options)
 	}
 }
+
+func TestFFmpegOptionsSummaryLabelsDecodeMode(t *testing.T) {
+	if got := ffmpegOptionsSummary(FFmpegOptions{}); got != "software" {
+		t.Fatalf("software summary = %q", got)
+	}
+	if got := ffmpegOptionsSummary(FFmpegOptions{HardwareDecode: "vaapi", HardwareDevice: "/dev/dri/renderD128"}); got != "vaapi:/dev/dri/renderD128" {
+		t.Fatalf("vaapi summary = %q", got)
+	}
+}

internal/transcode/handler.go

@@ -46,9 +46,11 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	var session *Session
 	var ok bool
 	if name == "master.m3u8" {
+		logging.Infof("playlist request id=%s start_ticks=%d", id, startTimeTicksFromRawQuery(r.URL.RawQuery))
 		traceSwitch("playlist_request id=%s start_ticks=%d query=%s elapsed=%s", id, startTimeTicksFromRawQuery(r.URL.RawQuery), redactURLString("?"+r.URL.RawQuery), time.Since(requestStarted))
 		if info, known := h.Manager.MediaInfo(id); known {
 			if playlist, ready := VirtualVODPlaylist(info, defaultSegmentTicks, r.URL.RawQuery); ready {
+				logging.Infof("playlist virtual id=%s duration=%s", id, formatTicks(info.RunTimeTicks))
 				traceSwitch("playlist_virtual id=%s duration=%s start_ticks=%d query=%s media=%s elapsed=%s", id, formatTicks(info.RunTimeTicks), startTimeTicksFromRawQuery(r.URL.RawQuery), redactURLString("?"+r.URL.RawQuery), info.Summary(), time.Since(requestStarted))
 				w.Header().Set("Content-Type", "application/vnd.apple.mpegurl")
 				w.Header().Set("Cache-Control", "no-store")
@@ -71,6 +73,7 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			http.Error(w, err.Error(), http.StatusBadGateway)
 			return
 		}
+		logging.Infof("playlist session id=%s elapsed=%s", id, time.Since(requestStarted))
 		traceSwitch("playlist_session_ready id=%s dir=%s input=%s elapsed=%s", id, session.Dir, redactURLString(inputURL), time.Since(requestStarted))
 	} else if segmentIndex, isSegment := segmentIndexFromName(name); isSegment {
 		var err error

internal/transcode/manager.go

@@ -764,8 +764,8 @@ func (r FFmpegRunner) Start(ctx context.Context, session *Session, request Reque
 	args := buildFFmpegArgs(session, request, r.Options)
 	playlist := filepath.Join(session.Dir, "master.m3u8")
 	logPath := filepath.Join(session.Dir, "ffmpeg.log")
-	logging.Infof("transcode start id=%s segment=%d", session.ID, session.SegmentStartIndex)
-	logging.Debugf("ffmpeg start id=%s item=%s media_source=%s start_ticks=%d segment_start=%d path=%s input=%s playlist=%s media=%s", session.ID, session.ItemID, session.MediaSourceID, session.StartTimeTicks, session.SegmentStartIndex, r.Path, redactURLString(request.InputURL), playlist, session.Media.Summary())
+	logging.Infof("transcode start id=%s segment=%d decode=%s audio=optional-aac log=%s", session.ID, session.SegmentStartIndex, ffmpegOptionsSummary(r.Options), logPath)
+	logging.Debugf("ffmpeg start id=%s item=%s media_source=%s start_ticks=%d segment_start=%d path=%s input=%s playlist=%s media=%s args=%s", session.ID, session.ItemID, session.MediaSourceID, session.StartTimeTicks, session.SegmentStartIndex, r.Path, redactURLString(request.InputURL), playlist, session.Media.Summary(), redactFFmpegArgs(args))
 	cmd := exec.CommandContext(ctx, r.Path, args...)
 	stdin, err := cmd.StdinPipe()
 	if err != nil {
@@ -781,7 +781,7 @@ func (r FFmpegRunner) Start(ctx context.Context, session *Session, request Reque
 		_ = logFile.Close()
 		return nil, fmt.Errorf("start ffmpeg: %w", err)
 	}
-	logging.Debugf("ffmpeg started id=%s pid=%d", session.ID, cmd.Process.Pid)
+	logging.Infof("ffmpeg started id=%s pid=%d decode=%s", session.ID, cmd.Process.Pid, ffmpegOptionsSummary(r.Options))
 	process := &execProcess{cmd: cmd, logFile: logFile, stdin: stdin, doneCh: make(chan struct{})}
 	go func() {
 		err := cmd.Wait()
@@ -799,6 +799,31 @@ func (r FFmpegRunner) Start(ctx context.Context, session *Session, request Reque
 	return process, nil
 }
 
+func ffmpegOptionsSummary(options FFmpegOptions) string {
+	mode := strings.ToLower(strings.TrimSpace(options.HardwareDecode))
+	if mode == "" || mode == "none" || mode == "off" || mode == "false" {
+		return "software"
+	}
+	device := strings.TrimSpace(options.HardwareDevice)
+	if device == "" {
+		return mode
+	}
+	return mode + ":" + device
+}
+
+func redactFFmpegArgs(args []string) string {
+	redacted := append([]string(nil), args...)
+	for i := 0; i < len(redacted)-1; i++ {
+		switch redacted[i] {
+		case "-i":
+			redacted[i+1] = redactURLString(redacted[i+1])
+		case "-headers":
+			redacted[i+1] = "REDACTED"
+		}
+	}
+	return strings.Join(redacted, " ")
+}
+
 func buildFFmpegArgs(session *Session, request Request, options ...FFmpegOptions) []string {
 	playlist := filepath.Join(session.Dir, "master.m3u8")
 	segmentPattern := filepath.Join(session.Dir, "segment_%05d.ts")