From dd0f50418ce00c12b6d57d20c932e2e7a4c90e16 Mon Sep 17 00:00:00 2001
From: Emil Ernerfeldt <emil.ernerfeldt@gmail.com>
Date: Wed, 9 Oct 2024 13:24:58 +0200
Subject: [PATCH] Improve log output and thread names

---
 .../re_video/src/decode/async_decoder.rs      |  2 +-
 crates/store/re_video/src/decode/ffmpeg.rs    | 60 ++++++++++++++++---
 2 files changed, 52 insertions(+), 10 deletions(-)

diff --git a/crates/store/re_video/src/decode/async_decoder.rs b/crates/store/re_video/src/decode/async_decoder.rs
index bdabde53a2c6e..c9165245d8baa 100644
--- a/crates/store/re_video/src/decode/async_decoder.rs
+++ b/crates/store/re_video/src/decode/async_decoder.rs
@@ -57,7 +57,7 @@ impl AsyncDecoder {
         let comms = Comms::default();
 
         let thread = std::thread::Builder::new()
-            .name("av1_decoder".into())
+            .name(format!("decoer thread for {debug_name}"))
             .spawn({
                 let comms = comms.clone();
                 move || {
diff --git a/crates/store/re_video/src/decode/ffmpeg.rs b/crates/store/re_video/src/decode/ffmpeg.rs
index 90b99bc9c5cce..61ec07e581be8 100644
--- a/crates/store/re_video/src/decode/ffmpeg.rs
+++ b/crates/store/re_video/src/decode/ffmpeg.rs
@@ -31,6 +31,12 @@ pub enum Error {
 
     #[error("Bad video data: {0}")]
     BadVideoData(String),
+
+    #[error("FFMPEG error: {0}")]
+    Ffmpeg(String),
+
+    #[error("FFMPEG IPC error: {0}")]
+    FfmpegSidecar(String),
 }
 
 /// ffmpeg does not tell us the timestamp/duration of a given frame, so we need to remember it.
@@ -43,7 +49,6 @@ struct FrameInfo {
 }
 
 /// Decode H.264 video via ffmpeg over CLI
-
 pub struct FfmpegCliH264Decoder {
     /// Monotonically increasing
     frame_num: u32,
@@ -61,6 +66,8 @@ pub struct FfmpegCliH264Decoder {
 }
 
 impl FfmpegCliH264Decoder {
+    // TODO: make this robust against `pkill ffmpeg` somehow.
+    // Maybe `AsyncDecoder` can auto-restart us, or we wrap ourselves in a new struct that restarts us on certain errors?
     pub fn new(avcc: re_mp4::Avc1Box) -> Result<Self, Error> {
         re_tracing::profile_function!();
 
@@ -108,23 +115,51 @@ fn read_ffmpeg_output(
     frame_info_rx: &Receiver<FrameInfo>,
     frame_tx: &Sender<super::Result<Frame>>,
 ) {
+    /// Ignore some common output from ffmpeg:
+    fn should_ignore_log_msg(msg: &str) -> bool {
+        let patterns = [
+            "Duration: N/A, bitrate: N/A",
+            "frame=    0 fps=0.0 q=0.0 size=       0kB time=N/A bitrate=N/A speed=N/A",
+            "Metadata:",
+            "No accelerated colorspace conversion found from yuv420p to rgb24",
+            "Stream mapping:",
+        ];
+
+        for pattern in patterns {
+            if msg.contains(pattern) {
+                return true;
+            }
+        }
+
+        false
+    }
+
     for event in ffmpeg_iterator {
         #[allow(clippy::match_same_arms)]
         match event {
             FfmpegEvent::Log(LogLevel::Info, msg) => {
-                re_log::debug!("{msg}");
+                if !should_ignore_log_msg(&msg) {
+                    re_log::debug!("{msg}");
+                }
             }
 
             FfmpegEvent::Log(LogLevel::Warning, msg) => {
-                if !msg.contains("No accelerated colorspace conversion found from yuv420p to rgb24")
-                {
+                if !should_ignore_log_msg(&msg) {
                     re_log::warn_once!("{msg}");
                 }
             }
 
             FfmpegEvent::Log(LogLevel::Error, msg) => {
-                // TODO: report errors
-                re_log::error_once!("{msg}");
+                frame_tx.send(Err(Error::Ffmpeg(msg).into())).ok();
+            }
+
+            FfmpegEvent::LogEOF => {
+                // This event proceeds `FfmpegEvent::Done`.
+                // This happens on `pkill ffmpeg`, for instance.
+            }
+
+            FfmpegEvent::Error(error) => {
+                frame_tx.send(Err(Error::FfmpegSidecar(error).into())).ok();
             }
 
             // Usefuless info in these:
@@ -143,7 +178,9 @@ fn read_ffmpeg_output(
                     ..
                 } = stream;
 
-                re_log::debug!("ParsedInputStream {stream_type} {format} {pix_fmt} {width}x{height} @ {fps} FPS");
+                re_log::debug!(
+                    "Input: {stream_type} {format} {pix_fmt} {width}x{height} @ {fps} FPS"
+                );
 
                 debug_assert_eq!(stream_type.to_ascii_lowercase(), "video");
             }
@@ -160,7 +197,9 @@ fn read_ffmpeg_output(
                     ..
                 } = stream;
 
-                re_log::debug!("ParsedOutputStream {stream_type} {format} {pix_fmt} {width}x{height} @ {fps} FPS");
+                re_log::debug!(
+                    "Output: {stream_type} {format} {pix_fmt} {width}x{height} @ {fps} FPS"
+                );
 
                 debug_assert_eq!(stream_type.to_ascii_lowercase(), "video");
             }
@@ -226,9 +265,11 @@ fn read_ffmpeg_output(
             }
 
             FfmpegEvent::Done => {
+                // This happens on `pkill ffmpeg`, for instance.
                 re_log::debug!("ffmpeg is Done");
                 return;
             }
+
             // TODO: handle all events
             event => re_log::debug!("Event: {event:?}"),
         }
@@ -350,7 +391,7 @@ fn write_avc_chunk_to_nalu_stream(
     let mut buffer_offset: usize = 0;
     let sample_end = chunk.data.len();
     while buffer_offset < sample_end && !should_stop.load(Ordering::Relaxed) {
-        re_tracing::profile_scope!("nalu");
+        re_tracing::profile_scope!("write_nalu");
 
         // Each NAL unit in mp4 is prefixed with a length prefix.
         // In Annex B this doesn't exist.
@@ -402,6 +443,7 @@ fn write_avc_chunk_to_nalu_stream(
         // Note that we don't have to insert "emulation prevention bytes" since mp4 NALU still use them.
         // (unlike the NAL start code, the presentation bytes are part of the NAL spec!)
 
+        re_tracing::profile_scope!("write_bytes", data.len().to_string());
         nalu_stream
             .write_all(data)
             .map_err(Error::FailedToWriteToFfmpeg)?;