From e0bafff4901884e5ddd6178d97b436aabaa0f6a5 Mon Sep 17 00:00:00 2001 From: Gabe Kangas Date: Sat, 26 Feb 2022 16:19:27 -0800 Subject: [PATCH] Handle transcoder logging differently to enable rotation. Closes #1745 --- core/transcoder/transcoder.go | 23 +++++++++++++++++-- core/transcoder/transcoder_nvenc_test.go | 3 +-- core/transcoder/transcoder_omx_test.go | 3 +-- core/transcoder/transcoder_vaapi_test.go | 3 +-- .../transcoder_videotoolbox_test.go | 3 +-- core/transcoder/transcoder_x264_test.go | 3 +-- core/transcoder/utils.go | 19 +++++++-------- 7 files changed, 36 insertions(+), 21 deletions(-) diff --git a/core/transcoder/transcoder.go b/core/transcoder/transcoder.go index fe162353b..4b62d8282 100644 --- a/core/transcoder/transcoder.go +++ b/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, diff --git a/core/transcoder/transcoder_nvenc_test.go b/core/transcoder/transcoder_nvenc_test.go index 45f41f7bb..0ce9ba7ed 100644 --- a/core/transcoder/transcoder_nvenc_test.go +++ b/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 := `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` + 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` if cmd != expected { t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected) diff --git a/core/transcoder/transcoder_omx_test.go b/core/transcoder/transcoder_omx_test.go index 30e0692d4..1336694af 100644 --- a/core/transcoder/transcoder_omx_test.go +++ b/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 := `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` + 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` if cmd != expected { t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected) diff --git a/core/transcoder/transcoder_vaapi_test.go b/core/transcoder/transcoder_vaapi_test.go index d85c27174..40a655069 100644 --- a/core/transcoder/transcoder_vaapi_test.go +++ b/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 := `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` + 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` if cmd != expected { t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected) diff --git a/core/transcoder/transcoder_videotoolbox_test.go b/core/transcoder/transcoder_videotoolbox_test.go index f500a0397..06cf42e58 100644 --- a/core/transcoder/transcoder_videotoolbox_test.go +++ b/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 := `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` + 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` if cmd != expected { t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected) diff --git a/core/transcoder/transcoder_x264_test.go b/core/transcoder/transcoder_x264_test.go index c779ee9ee..8c1f3e181 100644 --- a/core/transcoder/transcoder_x264_test.go +++ b/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 := `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` + 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` if cmd != expected { t.Errorf("ffmpeg command does not match expected.\nGot %s\n, want: %s", cmd, expected) diff --git a/core/transcoder/utils.go b/core/transcoder/utils.go index d89cbfe9d..feb0f3078 100644 --- a/core/transcoder/utils.go +++ b/core/transcoder/utils.go @@ -13,8 +13,10 @@ import ( log "github.com/sirupsen/logrus" ) -var _lastTranscoderLogMessage = "" -var l = &sync.RWMutex{} +var ( + _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() {