refactor: improve logging

plugins/ffmpeg_audio.rs

@@ -40,11 +40,15 @@ impl Plugin for PluginImpl {
         ]
     }
 
+    #[tracing::instrument(skip(self))]
     fn is_available(&self) -> bool {
-        std::process::Command::new("ffmpeg")
+        tracing::trace!("Checking availability of ffmpeg for ffmpeg_audio plugin");
+        let available = std::process::Command::new("ffmpeg")
             .arg("-version")
             .output()
-            .is_ok()
+            .is_ok();
+        tracing::debug!("ffmpeg_audio plugin available: {}", available);
+        available
     }
 
     fn familiarity(&self, _from: &str, to: &str) -> u8 {
@@ -82,6 +86,7 @@ impl Plugin for PluginImpl {
         }
     }
 
+    #[tracing::instrument(skip(self, input, temp_dir))]
     fn convert(
         &self,
         input: &[u8],
@@ -89,19 +94,30 @@ impl Plugin for PluginImpl {
         to: &str,
         temp_dir: &Path,
     ) -> Result<Vec<u8>, String> {
+        tracing::debug!("ffmpeg_audio starting conversion: {} -> {}", _from, to);
         let mut temp_in = tempfile::Builder::new()
             .suffix(&format!(".{}", _from))
             .tempfile_in(temp_dir)
-            .map_err(|e| e.to_string())?;
+            .map_err(|e| {
-        temp_in.write_all(input).map_err(|e| e.to_string())?;
+                tracing::error!("Failed to create temp input file: {}", e);
+                e.to_string()
+            })?;
+        temp_in.write_all(input).map_err(|e| {
+            tracing::error!("Failed to write to temp input file: {}", e);
+            e.to_string()
+        })?;
 
         let temp_out = tempfile::Builder::new()
             .suffix(&format!(".{}", to))
             .tempfile_in(temp_dir)
-            .map_err(|e| e.to_string())?;
+            .map_err(|e| {
+                tracing::error!("Failed to create temp output file: {}", e);
+                e.to_string()
+            })?;
         let temp_out_path = temp_out.into_temp_path();
 
         let in_path = temp_in.path().to_path_buf();
+        tracing::trace!("Temp files created. In: {:?}, Out: {:?}", in_path, temp_out_path);
 
         let mut raw_args = vec![];
         match to {
@@ -134,19 +150,35 @@ impl Plugin for PluginImpl {
             _ => raw_args.extend(vec!["-c:a", "copy"]),
         }
 
-        let rt = tokio::runtime::Runtime::new().map_err(|e| e.to_string())?;
+        tracing::debug!("Built ffmpeg arguments: {:?}", raw_args);
+
+        let rt = tokio::runtime::Runtime::new().map_err(|e| {
+            tracing::error!("Failed to create Tokio runtime: {}", e);
+            e.to_string()
+        })?;
         rt.block_on(async {
+            tracing::trace!("Executing FFmpegBuilder...");
             FFmpegBuilder::new()
-                .map_err(|e| e.to_string())?
+                .map_err(|e| {
+                    tracing::error!("Failed to init FFmpegBuilder: {}", e);
+                    e.to_string()
+                })?
                 .input_path(in_path)
                 .output_path(temp_out_path.to_path_buf())
                 .raw_args(raw_args)
                 .overwrite()
                 .run()
                 .await
-                .map_err(|e| e.to_string())
+                .map_err(|e| {
+                    tracing::error!("FFmpeg execution failed: {}", e);
+                    e.to_string()
+                })
         })?;
 
-        std::fs::read(&temp_out_path).map_err(|e| e.to_string())
+        tracing::debug!("FFmpeg execution succeeded. Reading output file...");
+        std::fs::read(&temp_out_path).map_err(|e| {
+            tracing::error!("Failed to read output file {:?}: {}", temp_out_path, e);
+            e.to_string()
+        })
     }
 }

plugins/ffmpeg_video.rs

@@ -38,11 +38,15 @@ impl Plugin for PluginImpl {
         ]
     }
 
+    #[tracing::instrument(skip(self))]
     fn is_available(&self) -> bool {
-        std::process::Command::new("ffmpeg")
+        tracing::trace!("Checking availability of ffmpeg for ffmpeg_video plugin");
+        let available = std::process::Command::new("ffmpeg")
             .arg("-version")
             .output()
-            .is_ok()
+            .is_ok();
+        tracing::debug!("ffmpeg_video plugin available: {}", available);
+        available
     }
 
     fn familiarity(&self, _from: &str, to: &str) -> u8 {
@@ -84,6 +88,7 @@ impl Plugin for PluginImpl {
         }
     }
 
+    #[tracing::instrument(skip(self, input, temp_dir))]
     fn convert(
         &self,
         input: &[u8],
@@ -91,19 +96,30 @@ impl Plugin for PluginImpl {
         to: &str,
         temp_dir: &Path,
     ) -> Result<Vec<u8>, String> {
+        tracing::debug!("ffmpeg_video starting conversion: {} -> {}", _from, to);
         let mut temp_in = tempfile::Builder::new()
             .suffix(&format!(".{}", _from))
             .tempfile_in(temp_dir)
-            .map_err(|e| e.to_string())?;
+            .map_err(|e| {
-        temp_in.write_all(input).map_err(|e| e.to_string())?;
+                tracing::error!("Failed to create temp input file: {}", e);
+                e.to_string()
+            })?;
+        temp_in.write_all(input).map_err(|e| {
+            tracing::error!("Failed to write to temp input file: {}", e);
+            e.to_string()
+        })?;
 
         let temp_out = tempfile::Builder::new()
             .suffix(&format!(".{}", to))
             .tempfile_in(temp_dir)
-            .map_err(|e| e.to_string())?;
+            .map_err(|e| {
+                tracing::error!("Failed to create temp output file: {}", e);
+                e.to_string()
+            })?;
         let temp_out_path = temp_out.into_temp_path();
 
         let in_path = temp_in.path().to_path_buf();
+        tracing::trace!("Temp files created. In: {:?}, Out: {:?}", in_path, temp_out_path);
 
         let mut raw_args = vec![];
         match to {
@@ -222,19 +238,35 @@ impl Plugin for PluginImpl {
             }
         }
 
-        let rt = tokio::runtime::Runtime::new().map_err(|e| e.to_string())?;
+        tracing::debug!("Built ffmpeg arguments: {:?}", raw_args);
+
+        let rt = tokio::runtime::Runtime::new().map_err(|e| {
+            tracing::error!("Failed to create Tokio runtime: {}", e);
+            e.to_string()
+        })?;
         rt.block_on(async {
+            tracing::trace!("Executing FFmpegBuilder...");
             FFmpegBuilder::new()
-                .map_err(|e| e.to_string())?
+                .map_err(|e| {
+                    tracing::error!("Failed to init FFmpegBuilder: {}", e);
+                    e.to_string()
+                })?
                 .input_path(in_path)
                 .output_path(temp_out_path.to_path_buf())
                 .raw_args(raw_args)
                 .overwrite()
                 .run()
                 .await
-                .map_err(|e| e.to_string())
+                .map_err(|e| {
+                    tracing::error!("FFmpeg execution failed: {}", e);
+                    e.to_string()
+                })
         })?;
 
-        std::fs::read(&temp_out_path).map_err(|e| e.to_string())
+        tracing::debug!("FFmpeg execution succeeded. Reading output file...");
+        std::fs::read(&temp_out_path).map_err(|e| {
+            tracing::error!("Failed to read output file {:?}: {}", temp_out_path, e);
+            e.to_string()
+        })
     }
 }

plugins/jpeg_to_png.rs

@@ -20,6 +20,12 @@ use std::path::Path;
 pub struct PluginImpl;
 
 impl Plugin for PluginImpl {
+    #[tracing::instrument(skip(self))]
+    fn is_available(&self) -> bool {
+        tracing::trace!("Checking availability for jpeg_to_png plugin (always true)");
+        true
+    }
+
     fn name(&self) -> &'static str {
         "jpeg_to_png"
     }
@@ -39,6 +45,7 @@ impl Plugin for PluginImpl {
         200
     }
 
+    #[tracing::instrument(skip(self, input, _temp_dir))]
     fn convert(
         &self,
         input: &[u8],
@@ -46,11 +53,26 @@ impl Plugin for PluginImpl {
         _to: &str,
         _temp_dir: &Path,
     ) -> Result<Vec<u8>, String> {
+        tracing::debug!("jpeg_to_png starting conversion");
+        tracing::trace!("Loading JPEG image from memory ({} bytes)", input.len());
         let img = image::load_from_memory_with_format(input, ImageFormat::Jpeg)
-            .map_err(|e| e.to_string())?;
+            .map_err(|e| {
-        let mut buf = Vec::new();
+                tracing::error!("Failed to decode JPEG image: {}", e);
-        img.write_to(&mut Cursor::new(&mut buf), ImageFormat::Png)
+                e.to_string()
-            .map_err(|e| e.to_string())?;
+            })?;
-        Ok(buf)
+
+        tracing::trace!("JPEG image loaded successfully. Dimensions: {}x{}", img.width(), img.height());
+
+        let mut output = Cursor::new(Vec::new());
+        tracing::trace!("Encoding image as PNG");
+        img.write_to(&mut output, ImageFormat::Png)
+            .map_err(|e| {
+                tracing::error!("Failed to encode image as PNG: {}", e);
+                e.to_string()
+            })?;
+
+        let out_bytes = output.into_inner();
+        tracing::debug!("jpeg_to_png conversion completed. Output size: {} bytes", out_bytes.len());
+        Ok(out_bytes)
     }
 }

plugins/png_to_jpeg.rs

@@ -13,13 +13,15 @@
 // along with this program.  If not, see <https://www.gnu.org/licenses/>.
 
 use crate::plugin::Plugin;
-use image::ImageFormat;
-use std::io::Cursor;
-use std::path::Path;
 
 pub struct PluginImpl;
 
 impl Plugin for PluginImpl {
+    #[tracing::instrument(skip(self))]
+    fn is_available(&self) -> bool {
+        tracing::trace!("Checking availability for png_to_jpeg plugin (always true)");
+        true
+    }
     fn name(&self) -> &'static str {
         "png_to_jpeg"
     }
@@ -39,18 +41,34 @@ impl Plugin for PluginImpl {
         220
     }
 
+    #[tracing::instrument(skip(self, input, _temp_dir))]
     fn convert(
         &self,
         input: &[u8],
         _from: &str,
         _to: &str,
-        _temp_dir: &Path,
+        _temp_dir: &std::path::Path,
     ) -> Result<Vec<u8>, String> {
-        let img = image::load_from_memory_with_format(input, ImageFormat::Png)
+        tracing::debug!("png_to_jpeg starting conversion");
-            .map_err(|e| e.to_string())?;
+        tracing::trace!("Loading PNG image from memory ({} bytes)", input.len());
-        let mut buf = Vec::new();
+        let img = image::load_from_memory_with_format(input, image::ImageFormat::Png)
-        img.write_to(&mut Cursor::new(&mut buf), ImageFormat::Jpeg)
+            .map_err(|e| {
-            .map_err(|e| e.to_string())?;
+                tracing::error!("Failed to decode PNG image: {}", e);
-        Ok(buf)
+                e.to_string()
+            })?;
+
+        tracing::trace!("PNG image loaded successfully. Dimensions: {}x{}", img.width(), img.height());
+
+        let mut output = std::io::Cursor::new(Vec::new());
+        tracing::trace!("Encoding image as JPEG");
+        img.write_to(&mut output, image::ImageFormat::Jpeg)
+            .map_err(|e| {
+                tracing::error!("Failed to encode image as JPEG: {}", e);
+                e.to_string()
+            })?;
+
+        let out_bytes = output.into_inner();
+        tracing::debug!("png_to_jpeg conversion completed. Output size: {} bytes", out_bytes.len());
+        Ok(out_bytes)
     }
 }

src/identifier.rs

@@ -15,11 +15,16 @@
 use crate::plugin::Plugin;
 use std::path::Path;
 
+#[tracing::instrument(skip(input, plugins))]
 pub fn identify_format(path: &str, input: &[u8], plugins: &[Box<dyn Plugin>]) -> Option<&'static str> {
+    tracing::trace!("Identifying format for path: {}", path);
     let mut ext_str_opt = None;
 
     if let Some(kind) = infer::get(input) {
+        tracing::trace!("infer detected file type: {:?}", kind.mime_type());
         ext_str_opt = Some(kind.extension());
+    } else if !input.is_empty() {
+        tracing::trace!("infer failed to detect file type from magic bytes.");
     }
 
     let p = Path::new(path);
@@ -33,23 +38,31 @@ pub fn identify_format(path: &str, input: &[u8], plugins: &[Box<dyn Plugin>]) ->
     }
 
     let mut ext_str = ext.as_deref().unwrap_or("");
-    if ext_str_opt.is_some() {
+    if let Some(magic_ext) = ext_str_opt {
-        ext_str = ext_str_opt.unwrap();
+        tracing::debug!("Using magic byte extension over path extension: {} -> {}", ext_str, magic_ext);
+        ext_str = magic_ext;
+    } else {
+        tracing::debug!("Using path extension: {}", ext_str);
     }
 
     let ext_str = match ext_str {
         "jpg" => "jpeg",
         other => other,
     };
+    tracing::trace!("Normalized extension to check plugins against: {}", ext_str);
 
     for plugin in plugins {
+        tracing::trace!("Checking plugin {} formats for support of {}", plugin.name(), ext_str);
         if let Some(&f) = plugin.from_formats().iter().find(|&&f| f == ext_str) {
+            tracing::debug!("Plugin {} supports {} as input.", plugin.name(), f);
             return Some(f);
         }
         if let Some(&f) = plugin.to_formats().iter().find(|&&f| f == ext_str) {
+            tracing::debug!("Plugin {} supports {} as output.", plugin.name(), f);
             return Some(f);
         }
     }
+    tracing::debug!("No plugin supports the format '{}'.", ext_str);
     None
 }
 

src/main.rs

@@ -28,6 +28,7 @@ use std::process;
 
 pub const VERSION: &str = include_str!(concat!(env!("OUT_DIR"), "/version.txt"));
 
+#[tracing::instrument]
 fn main() {
     let mut command = Args::command();
     command = command.version(VERSION);
@@ -55,6 +56,7 @@ fn main() {
         let mut formats_vec: Vec<_> = formats.into_iter().collect();
         formats_vec.sort();
 
+        tracing::info!("Listed {} supported formats", formats_vec.len());
         println!("Supported Formats:");
         for chunk in formats_vec.chunks(6) {
             let row = chunk.iter().map(|s| format!("{:<10}", s)).collect::<Vec<_>>().join(" ");
@@ -71,9 +73,14 @@ fn main() {
         }
     };
 
+    tracing::debug!("Input path specified: {}", input_path);
+
     // Read input file
     let input_bytes = match fs::read(input_path) {
-        Ok(b) => b,
+        Ok(b) => {
+            tracing::trace!("Read {} bytes from {}", b.len(), input_path);
+            b
+        }
         Err(e) => {
             tracing::error!("Error reading input file: {}", e);
             process::exit(1);
@@ -81,7 +88,10 @@ fn main() {
     };
 
     let from_format = match identifier::identify_format(input_path, &input_bytes, &plugins) {
-        Some(f) => f,
+        Some(f) => {
+            tracing::info!("Identified input format: {}", f);
+            f
+        }
         None => {
             tracing::error!("Unknown input format.");
             process::exit(1);
@@ -90,7 +100,10 @@ fn main() {
 
     let to_format = match &args.output_path {
         Some(out) => match identifier::identify_format(out, &[], &plugins) {
-            Some(f) => f,
+            Some(f) => {
+                tracing::info!("Identified output format from path: {}", f);
+                f
+            }
             None => {
                 tracing::error!("Unknown output format.");
                 process::exit(1);
@@ -106,7 +119,10 @@ fn main() {
                 }
             });
             match default_target {
-                Some(t) => t,
+                Some(t) => {
+                    tracing::info!("Auto-selected target format: {}", t);
+                    t
+                }
                 None => {
                     tracing::error!("No output path provided, and no available conversions found.");
                     process::exit(1);
@@ -116,8 +132,10 @@ fn main() {
     };
 
     let mut banned_plugins: Vec<&str> = Vec::new();
+    tracing::debug!("Starting pathfinding loop. from: {}, to: {}, priority: {}", from_format, to_format, args.priority);
 
     let output_bytes = loop {
+        tracing::trace!("Finding best path with banned plugins: {:?}", banned_plugins);
         let path = match pathfinder::find_best_path(&plugins, from_format, to_format, &args.priority, &banned_plugins) {
             Some(p) => p,
             None => {
@@ -134,6 +152,7 @@ fn main() {
 
         match runner::run_conversion(&path, &input_bytes, &args.temp_dir) {
             Ok(output_bytes) => {
+                tracing::info!("Conversion successful. Output size: {} bytes", output_bytes.len());
                 break output_bytes;
             }
             Err((e, plugin_name)) => {

src/pathfinder.rs

@@ -40,6 +40,7 @@ impl<'a> PathNode<'a> {
     }
 }
 
+#[tracing::instrument(skip(plugins))]
 pub fn find_best_path<'a>(
     plugins: &'a [Box<dyn Plugin>],
     from_format: &'a str,
@@ -49,7 +50,12 @@ pub fn find_best_path<'a>(
 ) -> Option<Vec<(&'a dyn Plugin, &'a str, &'a str)>> {
     let mut adj_list: HashMap<&str, Vec<&'a dyn Plugin>> = HashMap::new();
     for p in plugins {
-        if banned_plugins.contains(&p.name()) || !p.is_available() {
+        if banned_plugins.contains(&p.name()) {
+            tracing::trace!("Skipping banned plugin: {}", p.name());
+            continue;
+        }
+        if !p.is_available() {
+            tracing::trace!("Skipping unavailable plugin: {}", p.name());
             continue;
         }
         for &from in &p.from_formats() {
@@ -69,9 +75,11 @@ pub fn find_best_path<'a>(
 
     while let Some((curr_format, prev_node)) = queue.pop_front() {
         let current_depth = visited_depth.get(curr_format).copied().unwrap_or(0);
+        tracing::trace!("Visiting format node: {} at depth {}", curr_format, current_depth);
 
         if let Some(min_len) = min_length {
             if current_depth > min_len {
+                tracing::trace!("Pruning path exploration at depth {} (min_len={})", current_depth, min_len);
                 break; // We've moved beyond the shortest paths
             }
         }
@@ -114,13 +122,21 @@ pub fn find_best_path<'a>(
     }
 
     if best_paths.is_empty() {
+        tracing::debug!("No valid paths found from {} to {}.", from_format, to_format);
         return None;
     }
 
+    tracing::debug!("Found {} path(s) of minimum length {}. Evaluating priority: '{}'", best_paths.len(), min_length.unwrap_or(0), priority);
+
     // Evaluate based on priority (maximize score)
-    best_paths
+    let best = best_paths
         .into_iter()
-        .max_by(|path_a, path_b| compare_paths(path_a, path_b, priority))
+        .max_by(|path_a, path_b| compare_paths(path_a, path_b, priority));
+
+    if let Some(ref path) = best {
+        tracing::debug!("Selected path with length {}: {:?}", path.len(), path.iter().map(|p| p.0.name()).collect::<Vec<_>>());
+    }
+    best
 }
 
 fn compare_paths(

src/runner.rs

@@ -16,6 +16,7 @@ use crate::plugin::Plugin;
 use std::path::Path;
 use std::time::Instant;
 
+#[tracing::instrument(skip(path, input, temp_dir))]
 pub fn run_conversion(
     path: &[(&dyn Plugin, &str, &str)],
     input: &[u8],
@@ -43,6 +44,7 @@ pub fn run_conversion(
             plugin.quality(*from_format, *to_format),
             plugin.speed(*from_format, *to_format)
         );
+        tracing::debug!("[Plugin Log] Input data size: {} bytes", current_data.len());
 
         let start_time = Instant::now();
         current_data = match plugin.convert(&current_data, from_format, to_format, temp_dir) {
@@ -52,8 +54,8 @@ pub fn run_conversion(
         let elapsed = start_time.elapsed();
 
         tracing::info!(
-            "Step '{} -> {}' completed in {:?}",
+            "Step '{} -> {}' completed in {:?}. Output size: {} bytes",
-            from_format, to_format, elapsed
+            from_format, to_format, elapsed, current_data.len()
         );
     }