Handle transcoder logging differently to enable rotation. Closes #1745

core/transcoder/transcoder.go

@@ -7,8 +7,11 @@ import (
 	"os/exec"
 	"strconv"
 	"strings"
+	"time"
 
+	rotatelogs "github.com/lestrrat-go/file-rotatelogs"
 	log "github.com/sirupsen/logrus"
+
 	"github.com/teris-io/shortid"
 
 	"github.com/owncast/owncast/config"
@@ -24,6 +27,7 @@ var _commandExec *exec.Cmd
 type Transcoder struct {
 	input                string
 	stdin                *io.PipeReader
+	logwriter            *rotatelogs.RotateLogs
 	segmentOutputPath    string
 	playlistOutputPath   string
 	variants             []HLSVariant
@@ -112,6 +116,14 @@ func (t *Transcoder) Stop() {
 func (t *Transcoder) Start() {
 	_lastTranscoderLogMessage = ""
 
+	path := logging.GetTranscoderLogFilePath()
+	t.logwriter, _ = rotatelogs.New(
+		path+".%Y%m%d%H%M",
+		rotatelogs.WithLinkName(path),
+		rotatelogs.WithMaxAge(time.Duration(86400)*time.Second),
+		rotatelogs.WithRotationTime(time.Duration(604800)*time.Second),
+	)
+
 	command := t.getString()
 	log.Infof("Video transcoder started using %s with %d stream variants.", t.codec.DisplayName(), len(t.variants))
 	createVariantDirectories()
@@ -126,6 +138,7 @@ func (t *Transcoder) Start() {
 		_commandExec.Stdin = t.stdin
 	}
 
+	// ffmpeg logs to stderr, not stdout, so that's why this is weird.
 	stdout, err := _commandExec.StderrPipe()
 	if err != nil {
 		log.Fatalln(err)
@@ -140,6 +153,13 @@ func (t *Transcoder) Start() {
 		scanner := bufio.NewScanner(stdout)
 		for scanner.Scan() {
 			line := scanner.Text()
+
+			// Log to the transcoder.log file on disk
+			if _, err := t.logwriter.Write([]byte(line + "\n")); err != nil {
+				log.Errorln("error writing transcoder log file:", err)
+			}
+
+			// Log to our logger for optionally displaying in the console
 			handleTranscoderMessage(line)
 		}
 	}()
@@ -194,10 +214,9 @@ func (t *Transcoder) getString() string {
 		hlsOptionsString = "-hls_flags " + strings.Join(hlsOptionFlags, "+")
 	}
 	ffmpegFlags := []string{
-		fmt.Sprintf(`FFREPORT=file="%s":level=32`, logging.GetTranscoderLogFilePath()),
 		t.ffmpegPath,
 		"-hide_banner",
-		"-loglevel warning",
+		"-loglevel info",
 		t.codec.GlobalFlags(),
 		"-fflags +genpts", // Generate presentation time stamp if missing
 		"-i ", t.input,

core/transcoder/transcoder_nvenc_test.go

@@ -41,8 +41,7 @@ func TestFFmpegNvencCommand(t *testing.T) {
 
 	cmd := transcoder.getString()
 
-	expectedLogPath := filepath.Join("data", "logs", "transcoder.log")
+	expected := transcoder.ffmpegPath + ` -hide_banner -loglevel info -hwaccel cuda -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_nvenc -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30 -tune:v:0 ll -map a:0? -c:a:0 copy -preset p3 -map v:0 -c:v:1 h264_nvenc -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24 -tune:v:1 ll -map a:0? -c:a:1 copy -preset p5 -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset p1  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1  -pix_fmt yuv420p -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdoieGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
-	expected := `FFREPORT=file="` + expectedLogPath + `":level=32 ` + transcoder.ffmpegPath + ` -hide_banner -loglevel warning -hwaccel cuda -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_nvenc -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30 -tune:v:0 ll -map a:0? -c:a:0 copy -preset p3 -map v:0 -c:v:1 h264_nvenc -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24 -tune:v:1 ll -map a:0? -c:a:1 copy -preset p5 -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset p1  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1  -pix_fmt yuv420p -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdoieGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
 
 	if cmd != expected {
 		t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected)

core/transcoder/transcoder_omx_test.go

@@ -41,8 +41,7 @@ func TestFFmpegOmxCommand(t *testing.T) {
 
 	cmd := transcoder.getString()
 
-	expectedLogPath := filepath.Join("data", "logs", "transcoder.log")
+	expected := transcoder.ffmpegPath + ` -hide_banner -loglevel info  -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_omx -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30  -map a:0? -c:a:0 copy -preset veryfast -map v:0 -c:v:1 h264_omx -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24  -map a:0? -c:a:1 copy -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1 -tune zerolatency -pix_fmt yuv420p -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdFsdfzGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
-	expected := `FFREPORT=file="` + expectedLogPath + `":level=32 ` + transcoder.ffmpegPath + ` -hide_banner -loglevel warning  -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_omx -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30  -map a:0? -c:a:0 copy -preset veryfast -map v:0 -c:v:1 h264_omx -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24  -map a:0? -c:a:1 copy -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1 -tune zerolatency -pix_fmt yuv420p -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdFsdfzGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
 
 	if cmd != expected {
 		t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected)

core/transcoder/transcoder_vaapi_test.go

@@ -41,8 +41,7 @@ func TestFFmpegVaapiCommand(t *testing.T) {
 
 	cmd := transcoder.getString()
 
-	expectedLogPath := filepath.Join("data", "logs", "transcoder.log")
+	expected := transcoder.ffmpegPath + ` -hide_banner -loglevel info -vaapi_device /dev/dri/renderD128 -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_vaapi -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30  -map a:0? -c:a:0 copy -filter:v:0 "format=nv12,hwupload" -preset veryfast -map v:0 -c:v:1 h264_vaapi -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24  -map a:0? -c:a:1 copy -filter:v:1 "format=nv12,hwupload" -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1  -pix_fmt vaapi_vld -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdofFGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
-	expected := `FFREPORT=file="` + expectedLogPath + `":level=32 ` + transcoder.ffmpegPath + ` -hide_banner -loglevel warning -vaapi_device /dev/dri/renderD128 -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_vaapi -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30  -map a:0? -c:a:0 copy -filter:v:0 "format=nv12,hwupload" -preset veryfast -map v:0 -c:v:1 h264_vaapi -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24  -map a:0? -c:a:1 copy -filter:v:1 "format=nv12,hwupload" -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1  -pix_fmt vaapi_vld -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdofFGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
 
 	if cmd != expected {
 		t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected)

core/transcoder/transcoder_videotoolbox_test.go

@@ -41,8 +41,7 @@ func TestFFmpegVideoToolboxCommand(t *testing.T) {
 
 	cmd := transcoder.getString()
 
-	expectedLogPath := filepath.Join("data", "logs", "transcoder.log")
+	expected := transcoder.ffmpegPath + ` -hide_banner -loglevel info  -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_videotoolbox -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30 -realtime true -map a:0? -c:a:0 copy -preset veryfast -map v:0 -c:v:1 h264_videotoolbox -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24  -map a:0? -c:a:1 copy -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1  -pix_fmt nv12 -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdFsdfzGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
-	expected := `FFREPORT=file="` + expectedLogPath + `":level=32 ` + transcoder.ffmpegPath + ` -hide_banner -loglevel warning  -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 h264_videotoolbox -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30 -realtime true -map a:0? -c:a:0 copy -preset veryfast -map v:0 -c:v:1 h264_videotoolbox -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24  -map a:0? -c:a:1 copy -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1  -pix_fmt nv12 -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdFsdfzGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
 
 	if cmd != expected {
 		t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected)

core/transcoder/transcoder_x264_test.go

@@ -41,8 +41,7 @@ func TestFFmpegx264Command(t *testing.T) {
 
 	cmd := transcoder.getString()
 
-	expectedLogPath := filepath.Join("data", "logs", "transcoder.log")
+	expected := transcoder.ffmpegPath + ` -hide_banner -loglevel info  -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 libx264 -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30 -x264-params:v:0 "scenecut=0:open_gop=0" -bufsize:v:0 1088k -profile:v:0 high -map a:0? -c:a:0 copy -preset veryfast -map v:0 -c:v:1 libx264 -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24 -x264-params:v:1 "scenecut=0:open_gop=0" -bufsize:v:1 3572k -profile:v:1 high -map a:0? -c:a:1 copy -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1 -tune zerolatency -pix_fmt yuv420p -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdofFGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
-	expected := `FFREPORT=file="` + expectedLogPath + `":level=32 ` + transcoder.ffmpegPath + ` -hide_banner -loglevel warning  -fflags +genpts -i  fakecontent.flv  -map v:0 -c:v:0 libx264 -b:v:0 1008k -maxrate:v:0 1088k -g:v:0 90 -keyint_min:v:0 90 -r:v:0 30 -x264-params:v:0 "scenecut=0:open_gop=0" -bufsize:v:0 1088k -profile:v:0 high -map a:0? -c:a:0 copy -preset veryfast -map v:0 -c:v:1 libx264 -b:v:1 3308k -maxrate:v:1 3572k -g:v:1 72 -keyint_min:v:1 72 -r:v:1 24 -x264-params:v:1 "scenecut=0:open_gop=0" -bufsize:v:1 3572k -profile:v:1 high -map a:0? -c:a:1 copy -preset fast -map v:0 -c:v:2 copy -map a:0? -c:a:2 copy -preset ultrafast  -var_stream_map "v:0,a:0 v:1,a:1 v:2,a:2 " -f hls -hls_time 3 -hls_list_size 10 -hls_flags program_date_time+independent_segments+omit_endlist  -segment_format_options mpegts_flags=mpegts_copyts=1 -tune zerolatency -pix_fmt yuv420p -sc_threshold 0 -master_pl_name stream.m3u8 -hls_segment_filename http://127.0.0.1:8123/%v/stream-jdofFGg-%d.ts -max_muxing_queue_size 400 -method PUT http://127.0.0.1:8123/%v/stream.m3u8`
 
 	if cmd != expected {
 		t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected)

core/transcoder/utils.go

@@ -13,8 +13,10 @@ import (
 	log "github.com/sirupsen/logrus"
 )
 
-var _lastTranscoderLogMessage = ""
+var (
-var l = &sync.RWMutex{}
+	_lastTranscoderLogMessage = ""
+	l                         = &sync.RWMutex{}
+)
 
 var errorMap = map[string]string{
 	"Unrecognized option 'vaapi_device'":        "you are likely trying to utilize a vaapi codec, but your version of ffmpeg or your hardware doesn't support it. change your codec to libx264 and restart your stream",
@@ -60,8 +62,6 @@ var ignoredErrors = []string{
 }
 
 func handleTranscoderMessage(message string) {
-	log.Debugln(message)
-
 	l.Lock()
 	defer l.Unlock()
 
@@ -73,25 +73,26 @@ func handleTranscoderMessage(message string) {
 	}
 
 	// Convert specific transcoding messages to human-readable messages.
+	humanizedMessage := ""
 	for error, displayMessage := range errorMap {
 		if strings.Contains(message, error) {
-			message = displayMessage
+			humanizedMessage = displayMessage
 			break
 		}
 	}
 
-	if message == "" {
+	if humanizedMessage == "" {
 		return
 	}
 
 	// No good comes from a flood of repeated messages.
-	if message == _lastTranscoderLogMessage {
+	if humanizedMessage == _lastTranscoderLogMessage {
 		return
 	}
 
-	log.Error(message)
+	log.Error(humanizedMessage)
 
-	_lastTranscoderLogMessage = message
+	_lastTranscoderLogMessage = humanizedMessage
 }
 
 func createVariantDirectories() {