feat: implement protocol v2 for plugin system and add comprehensive tracing support

src/args.rs

@@ -21,14 +21,14 @@ pub struct Args {
     #[arg(
         long,
         help = "List formats supported by installed plugins.",
-        exclusive = true
+        conflicts_with = "list_plugins"
     )]
     pub list_formats: bool,
 
     #[arg(
         long,
         help = "List installed and known official plugins.",
-        exclusive = true
+        conflicts_with = "list_formats"
     )]
     pub list_plugins: bool,
 

src/catalog.rs

@@ -56,6 +56,11 @@ const MAGICK_IMAGES: &[&str] = &[
 ];
 
 fn all_pairs(formats: &[&str], scores: (u8, u8, u8)) -> Vec<Conversion> {
+    tracing::trace!(
+        format_count = formats.len(),
+        ?scores,
+        "building all-pairs conversion catalog"
+    );
     formats
         .iter()
         .flat_map(|from| {
@@ -68,6 +73,12 @@ fn all_pairs(formats: &[&str], scores: (u8, u8, u8)) -> Vec<Conversion> {
 }
 
 fn cross_pairs(inputs: &[&str], outputs: &[&str], scores: (u8, u8, u8)) -> Vec<Conversion> {
+    tracing::trace!(
+        input_count = inputs.len(),
+        output_count = outputs.len(),
+        ?scores,
+        "building cross-pair conversion catalog"
+    );
     inputs
         .iter()
         .flat_map(|from| {
@@ -85,6 +96,12 @@ fn metadata(
     description: &str,
     conversions: Vec<Conversion>,
 ) -> PluginMetadata {
+    tracing::trace!(
+        id,
+        package,
+        conversion_count = conversions.len(),
+        "building official plugin metadata"
+    );
     PluginMetadata {
         id: id.to_owned(),
         package: package.to_owned(),
@@ -95,6 +112,7 @@ fn metadata(
 }
 
 pub fn official_plugins() -> Vec<PluginMetadata> {
+    tracing::trace!("building official plugin catalog");
     let mut plugins = vec![
         metadata(
             "ffmpeg-audio",
@@ -195,13 +213,23 @@ pub fn official_plugins() -> Vec<PluginMetadata> {
         help: "Override frame rate; folders without metadata default to 30".into(),
         default: None,
     }];
+    tracing::trace!(
+        plugin_count = plugins.len(),
+        "official plugin catalog built"
+    );
     plugins
 }
 
 pub fn recommend_packages(from: &str, to: &str) -> Vec<String> {
+    tracing::debug!(
+        from,
+        to,
+        "searching official catalog for package recommendation"
+    );
     let plugins = official_plugins();
     let mut edges: HashMap<&str, Vec<(usize, &str)>> = HashMap::new();
     for (index, plugin) in plugins.iter().enumerate() {
+        tracing::trace!(plugin = %plugin.id, conversion_count = plugin.conversions.len(), "adding official plugin to recommendation graph");
         for conversion in &plugin.conversions {
             edges
                 .entry(&conversion.from)
@@ -212,26 +240,41 @@ pub fn recommend_packages(from: &str, to: &str) -> Vec<String> {
     let mut queue = VecDeque::from([(from, Vec::<usize>::new())]);
     let mut visited = HashSet::from([from]);
     while let Some((current, path)) = queue.pop_front() {
+        tracing::trace!(
+            current,
+            depth = path.len(),
+            queue_length = queue.len(),
+            "visiting package recommendation state"
+        );
         if current == to {
             let mut packages = Vec::new();
             for index in path {
                 let package = plugins[index].package.clone();
                 if !packages.contains(&package) {
+                    tracing::trace!(package, "adding package to recommendation");
                     packages.push(package);
                 }
             }
+            tracing::debug!(?packages, "found package recommendation");
             return packages;
         }
         if let Some(next_edges) = edges.get(current) {
             for &(plugin, next) in next_edges {
+                tracing::trace!(current, next, plugin = %plugins[plugin].id, "considering recommendation graph edge");
                 if visited.insert(next) {
                     let mut next_path = path.clone();
                     next_path.push(plugin);
                     queue.push_back((next, next_path));
+                    tracing::trace!(
+                        next,
+                        queue_length = queue.len(),
+                        "queued package recommendation state"
+                    );
                 }
             }
         }
     }
+    tracing::debug!(from, to, "official catalog has no package recommendation");
     Vec::new()
 }
 

src/identifier.rs

@@ -24,55 +24,78 @@ pub struct DetectedFormat {
 }
 
 fn normalized(format: &str) -> String {
-    match format.to_ascii_lowercase().as_str() {
+    let normalized = match format.to_ascii_lowercase().as_str() {
         "jpg" => "jpeg".to_owned(),
         "htm" => "html".to_owned(),
         "txt" | "ascii" => "text".to_owned(),
         other => other.to_owned(),
-    }
+    };
+    tracing::trace!(
+        input = format,
+        output = normalized,
+        "normalized format name"
+    );
+    normalized
 }
 
 pub fn requested_format(path: Option<&Path>, explicit: Option<&str>) -> Option<String> {
-    explicit.map(normalized).or_else(|| {
+    tracing::trace!(path = ?path, explicit, "resolving requested format");
+    let requested = explicit.map(normalized).or_else(|| {
         path.and_then(Path::extension)
             .and_then(|value| value.to_str())
             .map(normalized)
-    })
+    });
+    tracing::trace!(?requested, "resolved requested format");
+    requested
 }
 
 pub fn identify_path(path: &Path, explicit: Option<&str>) -> Result<DetectedFormat, String> {
+    tracing::debug!(path = %path.display(), explicit, is_directory = path.is_dir(), "starting path identification");
     if path.is_dir() {
+        tracing::trace!(path = %path.display(), "identifying directory artifact");
         if explicit.is_some_and(|format| normalized(format) != "frames") {
             return Err("directory inputs currently support only the 'frames' format".to_owned());
         }
         let manifest = path.join(".convertis-frames.json");
+        tracing::trace!(manifest = %manifest.display(), exists = manifest.exists(), "checking frame manifest");
         if manifest.exists() {
-            let value: serde_json::Value = serde_json::from_slice(
-                &fs::read(&manifest)
-                    .map_err(|error| format!("could not read {}: {error}", manifest.display()))?,
-            )
-            .map_err(|error| format!("invalid frame manifest: {error}"))?;
-            if value
+            tracing::trace!(manifest = %manifest.display(), "reading frame manifest");
+            let bytes = fs::read(&manifest)
+                .map_err(|error| format!("could not read {}: {error}", manifest.display()))?;
+            tracing::trace!(manifest = %manifest.display(), byte_count = bytes.len(), "parsing frame manifest");
+            let value: serde_json::Value = serde_json::from_slice(&bytes)
+                .map_err(|error| format!("invalid frame manifest: {error}"))?;
+            let schema_version = value
                 .get("schema_version")
-                .and_then(serde_json::Value::as_u64)
-                != Some(1)
-            {
+                .and_then(serde_json::Value::as_u64);
+            tracing::trace!(?schema_version, "read frame manifest schema version");
+            if schema_version != Some(1) {
                 return Err("unsupported frame manifest schema".to_owned());
             }
         } else {
+            tracing::trace!(path = %path.display(), "scanning directory for recognizable frames");
             let mut detected = None;
-            for entry in fs::read_dir(path)
-                .map_err(|error| error.to_string())?
-                .flatten()
-            {
+            for entry in fs::read_dir(path).map_err(|error| error.to_string())? {
+                let entry = match entry {
+                    Ok(entry) => entry,
+                    Err(error) => {
+                        tracing::trace!(%error, "could not inspect frame-directory entry");
+                        continue;
+                    }
+                };
+                tracing::trace!(entry = %entry.path().display(), "inspecting frame-directory entry");
                 if !entry.path().is_file() {
+                    tracing::trace!(entry = %entry.path().display(), "skipping non-file frame-directory entry");
                     continue;
                 }
                 let bytes = fs::read(entry.path()).map_err(|error| error.to_string())?;
+                tracing::trace!(entry = %entry.path().display(), byte_count = bytes.len(), "read potential frame file");
                 let Some(format) = identify_bytes(&bytes) else {
+                    tracing::trace!(entry = %entry.path().display(), "frame candidate was not recognizable");
                     continue;
                 };
                 if format.media_kind != MediaKind::Image {
+                    tracing::trace!(entry = %entry.path().display(), media_kind = ?format.media_kind, "frame candidate was not a still image");
                     continue;
                 }
                 if detected
@@ -83,6 +106,7 @@ pub fn identify_path(path: &Path, explicit: Option<&str>) -> Result<DetectedForm
                         "frame directories without metadata must use one image format".to_owned(),
                     );
                 }
+                tracing::trace!(entry = %entry.path().display(), format = %format.format, "accepted frame candidate");
                 detected = Some(format.format);
             }
             if detected.is_none() {
@@ -91,6 +115,7 @@ pub fn identify_path(path: &Path, explicit: Option<&str>) -> Result<DetectedForm
                 );
             }
         }
+        tracing::debug!(path = %path.display(), "identified frames directory");
         return Ok(DetectedFormat {
             format: "frames".to_owned(),
             mime: "application/vnd.convertis.frames+json".to_owned(),
@@ -98,51 +123,109 @@ pub fn identify_path(path: &Path, explicit: Option<&str>) -> Result<DetectedForm
             artifact_kind: ArtifactKind::Directory,
         });
     }
+    tracing::trace!(path = %path.display(), "reading file for content identification");
     let bytes =
         fs::read(path).map_err(|error| format!("could not read {}: {error}", path.display()))?;
+    tracing::trace!(path = %path.display(), byte_count = bytes.len(), "read file for identification");
     if let Some(format) = explicit {
-        return Ok(from_format(&normalized(format), &bytes));
+        let format = normalized(format);
+        tracing::debug!(path = %path.display(), format, "using explicit input format");
+        return Ok(from_format(&format, &bytes));
     }
-    identify_bytes(&bytes)
-        .ok_or_else(|| format!("could not identify {} from its contents", path.display()))
+    let identified = identify_bytes(&bytes)
+        .ok_or_else(|| format!("could not identify {} from its contents", path.display()))?;
+    tracing::debug!(path = %path.display(), format = %identified.format, "identified file contents");
+    Ok(identified)
 }
 
 pub fn identify_bytes(bytes: &[u8]) -> Option<DetectedFormat> {
+    tracing::trace!(
+        byte_count = bytes.len(),
+        "starting content signature identification"
+    );
     if bytes.starts_with(&[0, 0, 1, 0]) {
+        tracing::trace!(rule = "ico-header", "matched content signature");
         return Some(from_format("ico", bytes));
     }
+    tracing::trace!(
+        rule = "ico-header",
+        matched = false,
+        "checked content signature"
+    );
     if bytes.starts_with(b"<!DOCTYPE html") || bytes.starts_with(b"<html") {
+        tracing::trace!(rule = "html-prefix", "matched content signature");
         return Some(from_format("html", bytes));
     }
+    tracing::trace!(
+        rule = "html-prefix",
+        matched = false,
+        "checked content signature"
+    );
     if bytes.windows(4).any(|window| window == b"M4A ") {
+        tracing::trace!(rule = "m4a-brand", "matched content signature");
         return Some(from_format("m4a", bytes));
     }
+    tracing::trace!(
+        rule = "m4a-brand",
+        matched = false,
+        "checked content signature"
+    );
     if bytes.starts_with(b"OggS") {
+        tracing::trace!(rule = "ogg-header", "matched content signature");
         if bytes.windows(8).any(|window| window == b"OpusHead") {
+            tracing::trace!(rule = "opus-header", "matched Ogg subtype signature");
             return Some(from_format("opus", bytes));
         }
         if bytes.windows(6).any(|window| window == b"theora") {
+            tracing::trace!(rule = "theora-header", "matched Ogg subtype signature");
             return Some(from_format("ogv", bytes));
         }
+        tracing::trace!("no Ogg subtype signature matched; using generic Ogg format");
         return Some(from_format("ogg", bytes));
     }
+    tracing::trace!(
+        rule = "ogg-header",
+        matched = false,
+        "checked content signature"
+    );
     if let Some(kind) = infer::get(bytes) {
-        return Some(from_format(&normalized(kind.extension()), bytes));
+        let format = normalized(kind.extension());
+        tracing::trace!(
+            infer_extension = kind.extension(),
+            mime = kind.mime_type(),
+            format,
+            "matched infer signature database"
+        );
+        return Some(from_format(&format, bytes));
     }
+    tracing::trace!("infer signature database did not match");
     let text = std::str::from_utf8(bytes).ok()?;
+    tracing::trace!(
+        utf8 = true,
+        character_count = text.chars().count(),
+        "content is valid UTF-8"
+    );
     if !text.contains('\0') {
+        tracing::trace!(rule = "utf8-without-nul", "classified content as text");
         return Some(from_format("text", bytes));
     }
+    tracing::trace!("content did not match any supported identification rule");
     None
 }
 
 fn from_format(format: &str, bytes: &[u8]) -> DetectedFormat {
+    tracing::trace!(
+        format,
+        byte_count = bytes.len(),
+        "deriving media details from format"
+    );
     let animation = match format {
         "webp" => bytes.len() > 20 && &bytes[12..16] == b"VP8X" && bytes[20] & 0x02 != 0,
         "png" | "apng" => bytes.windows(4).any(|window| window == b"acTL"),
         "gif" => gif_is_animated(bytes),
         _ => false,
     };
+    tracing::trace!(format, animation, "determined animation state");
     let media_kind = if animation {
         MediaKind::Animation
     } else if matches!(
@@ -194,6 +277,7 @@ fn from_format(format: &str, bytes: &[u8]) -> DetectedFormat {
     } else {
         format.to_owned()
     };
+    tracing::trace!(format, mime, ?media_kind, "derived media details");
     DetectedFormat {
         format,
         mime: mime.to_owned(),
@@ -203,18 +287,27 @@ fn from_format(format: &str, bytes: &[u8]) -> DetectedFormat {
 }
 
 fn gif_is_animated(bytes: &[u8]) -> bool {
+    tracing::trace!(byte_count = bytes.len(), "checking GIF animation state");
     let mut options = gif::DecodeOptions::new();
     options.set_color_output(gif::ColorOutput::Indexed);
     let Ok(mut decoder) = options.read_info(std::io::Cursor::new(bytes)) else {
+        tracing::trace!("GIF decoder rejected content while checking animation");
         return false;
     };
     let mut frames = 0;
     while let Ok(Some(_)) = decoder.read_next_frame() {
         frames += 1;
+        tracing::trace!(frames, "decoded GIF frame while checking animation");
         if frames > 1 {
+            tracing::trace!(frames, animated = true, "GIF has multiple frames");
             return true;
         }
     }
+    tracing::trace!(
+        frames,
+        animated = false,
+        "GIF has fewer than two decodable frames"
+    );
     false
 }
 

src/main.rs

@@ -33,38 +33,70 @@ use std::{
 const VERSION: &str = include_str!(concat!(env!("OUT_DIR"), "/version.txt"));
 
 fn fail(message: impl std::fmt::Display) -> ! {
+    tracing::trace!("entering fatal error path");
     tracing::error!("{message}");
+    tracing::trace!(exit_code = 1, "terminating process");
     process::exit(1)
 }
 
 fn parse_options(values: &[String]) -> Result<BTreeMap<String, String>, String> {
+    tracing::trace!(value_count = values.len(), "parsing plugin options");
     let mut options = BTreeMap::new();
-    for value in values {
+    for (index, value) in values.iter().enumerate() {
+        tracing::trace!(index, raw_length = value.len(), "parsing plugin option");
         let (key, value) = value
             .split_once('=')
             .ok_or_else(|| format!("invalid option '{value}'; expected KEY=VALUE"))?;
+        tracing::trace!(
+            index,
+            key,
+            value_length = value.len(),
+            "split plugin option"
+        );
         if key.is_empty() || options.insert(key.to_owned(), value.to_owned()).is_some() {
             return Err(format!("invalid or duplicate option '{key}'"));
         }
     }
+    tracing::trace!(option_count = options.len(), "plugin options parsed");
     Ok(options)
 }
 
 fn should_overwrite(args: &Args, output: &Path) -> bool {
-    if !output.exists() {
+    let exists = output.exists();
+    tracing::trace!(
+        output = %output.display(),
+        exists,
+        yes = args.yes,
+        no = args.no,
+        quiet = args.quiet,
+        stdin_terminal = io::stdin().is_terminal(),
+        "evaluating output overwrite policy"
+    );
+    if !exists {
+        tracing::trace!("output is absent; overwrite is allowed");
         return true;
     }
     if args.yes {
+        tracing::trace!("overwrite accepted by --yes");
         return true;
     }
     if args.no || args.quiet || !io::stdin().is_terminal() {
+        tracing::trace!("overwrite declined without prompting");
         return false;
     }
+    tracing::trace!("prompting for overwrite confirmation");
     print!("'{}' exists. Replace it? [y/N]: ", output.display());
     let _ = io::stdout().flush();
     let mut answer = String::new();
-    io::stdin().read_line(&mut answer).is_ok()
-        && matches!(answer.trim().to_ascii_lowercase().as_str(), "y" | "yes")
+    let read = io::stdin().read_line(&mut answer);
+    let accepted =
+        read.is_ok() && matches!(answer.trim().to_ascii_lowercase().as_str(), "y" | "yes");
+    tracing::trace!(
+        read_success = read.is_ok(),
+        accepted,
+        "processed overwrite response"
+    );
+    accepted
 }
 
 fn main() {
@@ -76,15 +108,30 @@ fn main() {
         tracing::Level::from(args.verbose).into()
     };
     tracing_subscriber::fmt().with_max_level(level).init();
+    tracing::debug!(
+        version = env!("CARGO_PKG_VERSION"),
+        target = env!("CONVERTIS_TARGET"),
+        rustc = env!("CONVERTIS_RUSTC_VERSION"),
+        ?level,
+        "Convertis engine started"
+    );
+    tracing::trace!(?args, "parsed command-line arguments");
 
     let registry = plugin::PluginRegistry::load(&args.plugin_dirs, !args.no_default_plugins);
+    tracing::trace!(
+        plugin_count = registry.plugins.len(),
+        diagnostic_count = registry.diagnostics.len(),
+        "plugin registry is ready"
+    );
     for diagnostic in &registry.diagnostics {
         tracing::warn!("{diagnostic}");
     }
 
     if args.list_plugins {
+        tracing::debug!("listing official plugins");
         println!("Official plugins:");
         for metadata in catalog::official_plugins() {
+            tracing::trace!(plugin = %metadata.id, package = %metadata.package, "checking official plugin state");
             let installed = registry
                 .plugins
                 .iter()
@@ -94,17 +141,23 @@ fn main() {
                 Some(Err(error)) => format!("unavailable: {error}"),
                 None => "not installed".to_owned(),
             };
+            tracing::trace!(plugin = %metadata.id, state, "resolved official plugin state");
             println!(
                 "  {:32} {:28} {}",
                 metadata.package, state, metadata.description
             );
         }
+        tracing::debug!("finished listing official plugins");
         return;
     }
     if args.list_formats {
+        tracing::debug!("collecting formats from installed plugins");
         let mut formats = HashSet::new();
         for plugin in &registry.plugins {
-            for conversion in plugin.metadata().conversions {
+            let metadata = plugin.metadata();
+            tracing::trace!(plugin = %metadata.id, conversion_count = metadata.conversions.len(), "collecting plugin formats");
+            for conversion in metadata.conversions {
+                tracing::trace!(plugin = %metadata.id, from = %conversion.from, to = %conversion.to, "collecting conversion formats");
                 formats.insert(conversion.from);
                 formats.insert(conversion.to);
             }
@@ -116,6 +169,7 @@ fn main() {
         } else {
             println!("{}", formats.join("\n"));
         }
+        tracing::debug!(format_count = formats.len(), "finished listing formats");
         return;
     }
 
@@ -123,30 +177,52 @@ fn main() {
         .input_path
         .as_deref()
         .unwrap_or_else(|| fail("an input path is required"));
+    tracing::debug!(input = %input.display(), explicit_format = ?args.from_format, "identifying input");
     let detected = identifier::identify_path(input, args.from_format.as_deref())
         .unwrap_or_else(|error| fail(error));
-    tracing::info!("detected {} ({:?})", detected.format, detected.media_kind);
+    tracing::info!(
+        format = %detected.format,
+        mime = %detected.mime,
+        media_kind = ?detected.media_kind,
+        artifact_kind = ?detected.artifact_kind,
+        "input identified"
+    );
+    tracing::trace!(output = ?args.output_path, explicit_target = ?args.to_format, "resolving requested target format");
     let mut target =
         identifier::requested_format(args.output_path.as_deref(), args.to_format.as_deref())
             .unwrap_or_else(|| {
                 fail("a target is required; provide an output extension or --to FORMAT")
             });
+    tracing::trace!(target, "resolved initial target format");
     if matches!(
         detected.media_kind,
         convertis_plugin_api::MediaKind::Video
             | convertis_plugin_api::MediaKind::Animation
             | convertis_plugin_api::MediaKind::Frames
     ) {
+        let original_target = target.clone();
         target = match target.as_str() {
             "gif" => "animated-gif".to_owned(),
             "webp" => "animated-webp".to_owned(),
             _ => target,
         };
+        tracing::trace!(
+            original_target,
+            normalized_target = target,
+            "normalized animated target format"
+        );
     }
     let options = parse_options(&args.options).unwrap_or_else(|error| fail(error));
     let mut banned = Vec::new();
 
     let result = loop {
+        tracing::debug!(
+            from = %detected.format,
+            to = %target,
+            priority = %args.priority,
+            banned = ?banned,
+            "searching for a conversion route"
+        );
         let Some(route) = pathfinder::find_best_path(
             &registry.plugins,
             &detected.format,
@@ -154,7 +230,9 @@ fn main() {
             &args.priority,
             &banned,
         ) else {
+            tracing::debug!("no installed conversion route was found");
             let packages = catalog::recommend_packages(&detected.format, &target);
+            tracing::trace!(?packages, "resolved package recommendations");
             if packages.is_empty() {
                 fail(format!(
                     "no conversion path from {} to {} is known",
@@ -189,7 +267,9 @@ fn main() {
                 packages.join(" ")
             ));
         };
+        tracing::debug!(step_count = route.len(), "selected conversion route");
         for key in options.keys() {
+            tracing::trace!(key, "validating option against selected route");
             let recognized = route.iter().any(|step| {
                 let metadata = step.plugin.metadata();
                 let option_name = key
@@ -205,37 +285,55 @@ fn main() {
                     "option '{key}' is not supported by the selected conversion route"
                 ));
             }
+            tracing::trace!(key, "option is supported by selected route");
         }
         let route_names: Vec<_> = route.iter().map(|step| step.plugin.metadata().id).collect();
+        tracing::info!(route = %route_names.join(" -> "), "conversion route selected");
         if args.test {
+            tracing::debug!("test mode requested; skipping conversion");
             println!("{}", route_names.join(" -> "));
             return;
         }
+        tracing::debug!("executing conversion route");
         match runner::run_conversion(&route, input, &args.temp_dir, &options) {
-            Ok(result) => break result,
+            Ok(result) => {
+                tracing::debug!(result = %result.path.display(), kind = ?result.kind, "conversion route succeeded");
+                break result;
+            }
             Err((error, plugin)) => {
                 tracing::warn!("plugin {plugin} failed: {error}; trying another route");
                 banned.push(plugin);
+                tracing::trace!(?banned, "updated failed-plugin exclusion list");
             }
         }
     };
 
     if let Some(output) = &args.output_path {
+        tracing::debug!(output = %output.display(), "installing conversion result");
         if !should_overwrite(&args, output) {
             fail("output was not replaced");
         }
         if output.exists() {
             if output.is_dir() {
+                tracing::trace!(output = %output.display(), "removing existing output directory");
                 fs::remove_dir_all(output).unwrap_or_else(|error| fail(error));
             } else {
+                tracing::trace!(output = %output.display(), "removing existing output file");
                 fs::remove_file(output).unwrap_or_else(|error| fail(error));
             }
         }
         runner::install_result(&result, output).unwrap_or_else(|error| fail(error));
+        tracing::info!(output = %output.display(), "conversion result installed");
     } else if result.kind == ArtifactKind::Directory {
         fail("directory output requires an output path");
     } else {
+        tracing::trace!(path = %result.path.display(), "reading result for standard output");
         let bytes = fs::read(&result.path).unwrap_or_else(|error| fail(error));
+        tracing::trace!(
+            byte_count = bytes.len(),
+            stdout_terminal = io::stdout().is_terminal(),
+            "prepared result bytes for standard output"
+        );
         if io::stdout().is_terminal() && !args.write_to_console {
             tracing::warn!(
                 "writing conversion bytes to the terminal; use -c to suppress this warning"
@@ -244,5 +342,10 @@ fn main() {
         io::stdout()
             .write_all(&bytes)
             .unwrap_or_else(|error| fail(error));
+        tracing::trace!(
+            byte_count = bytes.len(),
+            "wrote result bytes to standard output"
+        );
     }
+    tracing::debug!("Convertis engine completed successfully");
 }

src/pathfinder.rs

@@ -22,7 +22,12 @@ pub struct RouteStep<'a> {
 }
 
 fn route_score(route: &[RouteStep<'_>], priority: &str) -> Vec<u32> {
-    priority
+    tracing::trace!(
+        step_count = route.len(),
+        priority,
+        "scoring conversion route"
+    );
+    let score: Vec<u32> = priority
         .chars()
         .map(|criterion| {
             route
@@ -35,7 +40,9 @@ fn route_score(route: &[RouteStep<'_>], priority: &str) -> Vec<u32> {
                 })
                 .sum()
         })
-        .collect()
+        .collect();
+    tracing::trace!(?score, "calculated conversion route score");
+    score
 }
 
 pub fn find_best_path<'a>(
@@ -45,13 +52,29 @@ pub fn find_best_path<'a>(
     priority: &str,
     banned: &[String],
 ) -> Option<Vec<RouteStep<'a>>> {
+    tracing::debug!(
+        plugin_count = plugins.len(),
+        from,
+        to,
+        priority,
+        ?banned,
+        "building conversion graph"
+    );
     let mut edges: HashMap<String, Vec<RouteStep<'a>>> = HashMap::new();
     for plugin in plugins {
         let metadata = plugin.metadata();
-        if banned.contains(&metadata.id) || plugin.availability().is_err() {
+        if banned.contains(&metadata.id) {
+            tracing::trace!(plugin = %metadata.id, "excluded banned plugin from conversion graph");
             continue;
         }
+        tracing::trace!(plugin = %metadata.id, "checking plugin availability for conversion graph");
+        if let Err(error) = plugin.availability() {
+            tracing::debug!(plugin = %metadata.id, %error, "excluded unavailable plugin from conversion graph");
+            continue;
+        }
+        tracing::trace!(plugin = %metadata.id, conversion_count = metadata.conversions.len(), "adding available plugin conversions to graph");
         for conversion in metadata.conversions {
+            tracing::trace!(plugin = %metadata.id, from = %conversion.from, to = %conversion.to, "adding conversion graph edge");
             edges
                 .entry(conversion.from.clone())
                 .or_default()
@@ -61,38 +84,86 @@ pub fn find_best_path<'a>(
                 });
         }
     }
+    let edge_count: usize = edges.values().map(Vec::len).sum();
+    tracing::debug!(
+        node_count = edges.len(),
+        edge_count,
+        "conversion graph built"
+    );
 
     let mut queue = VecDeque::from([(from.to_owned(), Vec::<RouteStep<'a>>::new())]);
     let mut depths = HashMap::from([(from.to_owned(), 0usize)]);
     let mut solutions = Vec::new();
     let mut minimum = None;
     while let Some((current, route)) = queue.pop_front() {
+        tracing::trace!(
+            current,
+            depth = route.len(),
+            queue_length = queue.len(),
+            known_minimum = ?minimum,
+            "visiting conversion graph state"
+        );
         if minimum.is_some_and(|depth| route.len() > depth) {
+            tracing::trace!(
+                current,
+                depth = route.len(),
+                "pruned state deeper than shortest solution"
+            );
             continue;
         }
         if current == to && !route.is_empty() {
             minimum = Some(route.len());
+            tracing::trace!(
+                depth = route.len(),
+                solution_count = solutions.len() + 1,
+                "found shortest conversion route candidate"
+            );
             solutions.push(route);
             continue;
         }
         if let Some(next_steps) = edges.get(&current) {
+            tracing::trace!(
+                current,
+                next_step_count = next_steps.len(),
+                "expanding conversion graph state"
+            );
             for step in next_steps {
                 let next_depth = route.len() + 1;
-                if next_depth
-                    <= depths
-                        .get(&step.conversion.to)
-                        .copied()
-                        .unwrap_or(usize::MAX)
-                {
+                let previous_depth = depths
+                    .get(&step.conversion.to)
+                    .copied()
+                    .unwrap_or(usize::MAX);
+                tracing::trace!(
+                    plugin = %step.plugin.metadata().id,
+                    from = %step.conversion.from,
+                    to = %step.conversion.to,
+                    next_depth,
+                    previous_depth,
+                    "considering conversion graph edge"
+                );
+                if next_depth <= previous_depth {
                     depths.insert(step.conversion.to.clone(), next_depth);
                     let mut next_route = route.clone();
                     next_route.push(step.clone());
                     queue.push_back((step.conversion.to.clone(), next_route));
+                    tracing::trace!(next = %step.conversion.to, queue_length = queue.len(), "queued conversion graph state");
+                } else {
+                    tracing::trace!(next = %step.conversion.to, "skipped conversion graph state with longer path");
                 }
             }
+        } else {
+            tracing::trace!(current, "conversion graph state has no outgoing edges");
         }
     }
-    solutions
+    tracing::debug!(solution_count = solutions.len(), shortest_depth = ?minimum, "conversion graph search completed");
+    let selected = solutions
         .into_iter()
-        .max_by_key(|route| route_score(route, priority))
+        .max_by_key(|route| route_score(route, priority));
+    if let Some(route) = &selected {
+        let plugins: Vec<_> = route.iter().map(|step| step.plugin.metadata().id).collect();
+        tracing::debug!(?plugins, score = ?route_score(route, priority), "selected highest-scoring shortest route");
+    } else {
+        tracing::debug!("no conversion route selected");
+    }
+    selected
 }

src/plugin.rs

@@ -3,24 +3,37 @@
 // This program is free software: you can redistribute it and/or modify
 // it under the terms of the GNU General Public License as published by
 // the Free Software Foundation, version 3 exclusively.
-//
-// This program is distributed in the hope that it will be useful,
-// but WITHOUT ANY WARRANTY; without even the implied warranty of
-// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
-// GNU General Public License for more details.
-//
-// You should have received a copy of the GNU General Public License
-// along with this program.  If not, see <https://www.gnu.org/licenses/>.
 
 use convertis_plugin_api::{
-    ENGINE_VERSION, FACTORY_SYMBOL, MANIFEST_SYMBOL, Plugin, PluginFactory, PluginManifest,
+    AVAILABILITY_SYMBOL_V2, CONVERT_SYMBOL_V2, ConversionRequest, FREE_SYMBOL_V2,
+    LEGACY_FACTORY_SYMBOL_V1, LEGACY_MANIFEST_SYMBOL_V1, MANIFEST_SYMBOL, METADATA_SYMBOL_V2,
+    Plugin, PluginConvertCall, PluginFactory, PluginJsonCall, PluginManifest, PluginMetadata,
+    PluginStringFree, WireResponse,
 };
 use libloading::Library;
-use serde::Deserialize;
-use std::{collections::HashSet, ffi::CStr, fs, path::PathBuf};
+use semver::{Version, VersionReq};
+use serde::{Deserialize, de::DeserializeOwned};
+use std::{
+    collections::HashSet,
+    ffi::{CStr, CString, c_char},
+    fs,
+    path::{Path, PathBuf},
+};
 
-#[derive(Deserialize)]
-struct AbiManifest {
+const SUPPORTED_PROTOCOLS: &[u32] = &[2];
+
+#[derive(Debug, Deserialize)]
+struct StableManifest {
+    manifest_version: u32,
+    protocol_versions: Vec<u32>,
+    engine_requirement: String,
+    plugin_id: String,
+    plugin_version: String,
+    target: String,
+}
+
+#[derive(Debug, Deserialize)]
+struct LegacyManifestV1 {
     api_version: u32,
     engine_version: String,
     plugin_id: String,
@@ -28,6 +41,67 @@ struct AbiManifest {
     target: String,
 }
 
+struct ProtocolV2Plugin {
+    metadata: PluginMetadata,
+    availability: PluginJsonCall,
+    convert: PluginConvertCall,
+    free: PluginStringFree,
+}
+
+impl ProtocolV2Plugin {
+    unsafe fn call<T: DeserializeOwned>(
+        &self,
+        operation: &str,
+        call: PluginJsonCall,
+    ) -> Result<T, String> {
+        tracing::trace!(plugin = %self.metadata.id, operation, "calling plugin protocol operation");
+        let pointer = unsafe { call() };
+        let result = unsafe { decode_response(pointer, self.free, operation) };
+        tracing::trace!(
+            plugin = %self.metadata.id,
+            operation,
+            success = result.is_ok(),
+            "plugin protocol operation completed"
+        );
+        result
+    }
+}
+
+impl Plugin for ProtocolV2Plugin {
+    fn metadata(&self) -> PluginMetadata {
+        tracing::trace!(plugin = %self.metadata.id, "returning cached plugin metadata");
+        self.metadata.clone()
+    }
+
+    fn availability(&self) -> Result<(), String> {
+        unsafe { self.call("availability", self.availability) }
+    }
+
+    fn convert(&self, request: &ConversionRequest) -> Result<(), String> {
+        tracing::trace!(
+            plugin = %self.metadata.id,
+            input = %request.input.display(),
+            output = %request.output.display(),
+            from = %request.from,
+            to = %request.to,
+            option_count = request.options.len(),
+            "serializing conversion request"
+        );
+        let json = serde_json::to_string(request)
+            .map_err(|error| format!("could not serialize conversion request: {error}"))?;
+        let json =
+            CString::new(json).map_err(|_| "conversion request contained a NUL byte".to_owned())?;
+        let pointer = unsafe { (self.convert)(json.as_ptr()) };
+        let result = unsafe { decode_response(pointer, self.free, "convert") };
+        tracing::trace!(
+            plugin = %self.metadata.id,
+            success = result.is_ok(),
+            "conversion protocol call completed"
+        );
+        result
+    }
+}
+
 pub struct PluginRegistry {
     // Plugins must be dropped before their backing libraries.
     pub plugins: Vec<Box<dyn Plugin>>,
@@ -37,19 +111,38 @@ pub struct PluginRegistry {
 
 impl PluginRegistry {
     pub fn load(extra_dirs: &[PathBuf], include_defaults: bool) -> Self {
+        tracing::debug!(
+            extra_directory_count = extra_dirs.len(),
+            include_defaults,
+            "starting plugin discovery"
+        );
         let mut directories = extra_dirs.to_vec();
+        for directory in extra_dirs {
+            tracing::trace!(directory = %directory.display(), source = "command-line", "queued plugin directory");
+        }
         if let Some(paths) = std::env::var_os("CONVERTIS_PLUGIN_PATH") {
-            directories.extend(std::env::split_paths(&paths));
+            for directory in std::env::split_paths(&paths) {
+                tracing::trace!(directory = %directory.display(), source = "environment", "queued plugin directory");
+                directories.push(directory);
+            }
+        } else {
+            tracing::trace!("CONVERTIS_PLUGIN_PATH is not set");
         }
         if include_defaults {
-            if let Ok(executable) = std::env::current_exe()
-                && let Some(parent) = executable.parent()
-            {
-                directories.push(parent.to_path_buf());
-                directories.push(parent.join("plugins"));
+            match std::env::current_exe() {
+                Ok(executable) => {
+                    tracing::trace!(executable = %executable.display(), "resolved current executable");
+                    if let Some(parent) = executable.parent() {
+                        directories.push(parent.to_path_buf());
+                        directories.push(parent.join("plugins"));
+                    }
+                }
+                Err(error) => tracing::debug!(%error, "could not resolve current executable"),
             }
             if let Some(home) = std::env::var_os("HOME") {
                 directories.push(PathBuf::from(home).join(".local/lib/convertis/plugins"));
+            } else {
+                tracing::trace!("HOME is not set; skipping per-user plugin directory");
             }
             directories.push(PathBuf::from("/usr/lib/convertis/plugins"));
         }
@@ -63,94 +156,307 @@ impl PluginRegistry {
         let mut seen_ids = HashSet::new();
 
         for directory in directories {
-            let Ok(directory) = directory.canonicalize() else {
-                continue;
+            tracing::trace!(directory = %directory.display(), "examining plugin directory");
+            let directory = match directory.canonicalize() {
+                Ok(directory) => directory,
+                Err(error) => {
+                    tracing::trace!(directory = %directory.display(), %error, "plugin directory is unavailable");
+                    continue;
+                }
             };
             if !seen_paths.insert(directory.clone()) {
+                tracing::trace!(directory = %directory.display(), "skipping duplicate plugin directory");
                 continue;
             }
-            let Ok(entries) = fs::read_dir(&directory) else {
-                continue;
+            let entries = match fs::read_dir(&directory) {
+                Ok(entries) => entries,
+                Err(error) => {
+                    tracing::debug!(directory = %directory.display(), %error, "could not read plugin directory");
+                    continue;
+                }
             };
-            let mut paths: Vec<_> = entries.flatten().map(|entry| entry.path()).collect();
+            let mut paths: Vec<_> = entries
+                .filter_map(|entry| match entry {
+                    Ok(entry) => Some(entry.path()),
+                    Err(error) => {
+                        tracing::trace!(directory = %directory.display(), %error, "could not read directory entry");
+                        None
+                    }
+                })
+                .collect();
             paths.sort();
+            tracing::trace!(directory = %directory.display(), entry_count = paths.len(), "sorted plugin directory entries");
             for path in paths {
                 let is_plugin = path.extension().and_then(|value| value.to_str()) == Some("so")
                     && path
                         .file_name()
                         .and_then(|value| value.to_str())
                         .is_some_and(|name| name.starts_with("libconvertis_"));
+                tracing::trace!(path = %path.display(), is_plugin, "classified plugin candidate");
                 if !is_plugin {
                     continue;
                 }
+                tracing::debug!(path = %path.display(), "loading plugin candidate");
                 match unsafe { Self::load_one(&path) } {
-                    Ok((library, plugin, id)) => {
+                    Ok((library, plugin, id, protocol)) => {
                         if seen_ids.insert(id.clone()) {
+                            tracing::info!(plugin = %id, protocol, path = %path.display(), "loaded plugin");
                             registry.plugins.push(plugin);
                             registry.libraries.push(library);
                         } else {
+                            tracing::debug!(plugin = %id, path = %path.display(), "ignored duplicate plugin");
                             registry.diagnostics.push(format!(
                                 "ignored duplicate plugin '{id}' from {}",
                                 path.display()
                             ));
                         }
                     }
-                    Err(error) => registry
-                        .diagnostics
-                        .push(format!("could not load {}: {error}", path.display())),
+                    Err(error) => {
+                        tracing::debug!(path = %path.display(), %error, "plugin candidate was rejected");
+                        registry
+                            .diagnostics
+                            .push(format!("could not load {}: {error}", path.display()));
+                    }
                 }
             }
         }
+        tracing::debug!(
+            plugin_count = registry.plugins.len(),
+            diagnostic_count = registry.diagnostics.len(),
+            "plugin discovery completed"
+        );
         registry
     }
 
-    unsafe fn load_one(
-        path: &std::path::Path,
-    ) -> Result<(Library, Box<dyn Plugin>, String), String> {
+    unsafe fn load_one(path: &Path) -> Result<(Library, Box<dyn Plugin>, String, u32), String> {
+        tracing::trace!(path = %path.display(), "opening dynamic library");
         let library = unsafe { Library::new(path) }.map_err(|error| error.to_string())?;
-        let manifest_fn = unsafe { library.get::<PluginManifest>(MANIFEST_SYMBOL) }
-            .map_err(|error| format!("missing ABI manifest: {error}"))?;
-        let pointer = unsafe { manifest_fn() };
-        if pointer.is_null() {
-            return Err("ABI manifest was null".to_owned());
+        tracing::trace!(path = %path.display(), "dynamic library opened");
+
+        if let Ok(manifest_fn) = unsafe { library.get::<PluginManifest>(MANIFEST_SYMBOL) } {
+            tracing::trace!(path = %path.display(), "found stable plugin manifest entry point");
+            let manifest: StableManifest = unsafe { read_manifest(*manifest_fn) }?;
+            let protocol = validate_stable_manifest(&manifest, env!("CARGO_PKG_VERSION"))?;
+            tracing::debug!(
+                plugin = %manifest.plugin_id,
+                plugin_version = %manifest.plugin_version,
+                protocol,
+                engine_requirement = %manifest.engine_requirement,
+                "negotiated plugin protocol"
+            );
+            let metadata_call = *unsafe { library.get::<PluginJsonCall>(METADATA_SYMBOL_V2) }
+                .map_err(|error| format!("protocol v2 metadata entry point is missing: {error}"))?;
+            let availability = *unsafe { library.get::<PluginJsonCall>(AVAILABILITY_SYMBOL_V2) }
+                .map_err(|error| {
+                    format!("protocol v2 availability entry point is missing: {error}")
+                })?;
+            let convert = *unsafe { library.get::<PluginConvertCall>(CONVERT_SYMBOL_V2) }.map_err(
+                |error| format!("protocol v2 conversion entry point is missing: {error}"),
+            )?;
+            let free =
+                *unsafe { library.get::<PluginStringFree>(FREE_SYMBOL_V2) }.map_err(|error| {
+                    format!("protocol v2 string-free entry point is missing: {error}")
+                })?;
+            tracing::trace!(plugin = %manifest.plugin_id, "resolved all protocol v2 entry points");
+            let metadata: PluginMetadata = unsafe {
+                let pointer = metadata_call();
+                decode_response(pointer, free, "metadata")
+            }?;
+            if metadata.id != manifest.plugin_id {
+                return Err("manifest and plugin metadata IDs differ".to_owned());
+            }
+            let id = manifest.plugin_id;
+            let plugin = ProtocolV2Plugin {
+                metadata,
+                availability,
+                convert,
+                free,
+            };
+            return Ok((library, Box::new(plugin), id, protocol));
         }
-        let json = unsafe { CStr::from_ptr(pointer) }
-            .to_str()
-            .map_err(|error| format!("invalid ABI manifest string: {error}"))?;
-        let manifest: AbiManifest =
-            serde_json::from_str(json).map_err(|error| format!("invalid ABI manifest: {error}"))?;
-        if manifest.api_version != convertis_plugin_api::API_VERSION {
-            return Err(format!(
-                "plugin API {} is not supported",
-                manifest.api_version
-            ));
-        }
-        if manifest.engine_version != ENGINE_VERSION {
-            return Err(format!(
-                "plugin targets engine {}, but this engine is {}",
-                manifest.engine_version, ENGINE_VERSION
-            ));
-        }
-        if manifest.rustc_version != env!("CONVERTIS_RUSTC_VERSION") {
-            return Err(format!(
-                "plugin was built with {}, but the engine uses {}",
-                manifest.rustc_version,
-                env!("CONVERTIS_RUSTC_VERSION")
-            ));
-        }
-        if manifest.target != env!("CONVERTIS_TARGET") {
-            return Err(format!(
-                "plugin targets {}, but the engine targets {}",
-                manifest.target,
-                env!("CONVERTIS_TARGET")
-            ));
-        }
-        let factory = unsafe { library.get::<PluginFactory>(FACTORY_SYMBOL) }
-            .map_err(|error| format!("missing Rust plugin factory: {error}"))?;
+
+        tracing::trace!(path = %path.display(), "stable manifest absent; trying legacy protocol v1 adapter");
+        let manifest_fn = unsafe { library.get::<PluginManifest>(LEGACY_MANIFEST_SYMBOL_V1) }
+            .map_err(|error| format!("missing stable or legacy ABI manifest: {error}"))?;
+        let manifest: LegacyManifestV1 = unsafe { read_manifest(*manifest_fn) }?;
+        validate_legacy_manifest(&manifest)?;
+        let factory = unsafe { library.get::<PluginFactory>(LEGACY_FACTORY_SYMBOL_V1) }
+            .map_err(|error| format!("missing legacy Rust plugin factory: {error}"))?;
         let plugin = unsafe { factory() };
         if plugin.metadata().id != manifest.plugin_id {
-            return Err("manifest and plugin IDs differ".to_owned());
+            return Err("legacy manifest and plugin IDs differ".to_owned());
         }
-        Ok((library, plugin, manifest.plugin_id))
+        tracing::debug!(
+            plugin = %manifest.plugin_id,
+            built_for_engine = %manifest.engine_version,
+            "loaded plugin through legacy protocol v1 adapter"
+        );
+        Ok((library, plugin, manifest.plugin_id, 1))
+    }
+}
+
+fn validate_stable_manifest(
+    manifest: &StableManifest,
+    engine_version: &str,
+) -> Result<u32, String> {
+    tracing::trace!(
+        ?manifest,
+        engine_version,
+        "validating stable plugin manifest"
+    );
+    if manifest.manifest_version != 1 {
+        return Err(format!(
+            "manifest format {} is not supported",
+            manifest.manifest_version
+        ));
+    }
+    let engine = Version::parse(engine_version)
+        .map_err(|error| format!("engine has an invalid version: {error}"))?;
+    let requirement = VersionReq::parse(&manifest.engine_requirement)
+        .map_err(|error| format!("plugin has an invalid engine requirement: {error}"))?;
+    if !requirement.matches(&engine) {
+        return Err(format!(
+            "plugin requires engine {}, but this engine is {}",
+            manifest.engine_requirement, engine_version
+        ));
+    }
+    if manifest.target != env!("CONVERTIS_TARGET") {
+        return Err(format!(
+            "plugin targets {}, but the engine targets {}",
+            manifest.target,
+            env!("CONVERTIS_TARGET")
+        ));
+    }
+    SUPPORTED_PROTOCOLS
+        .iter()
+        .rev()
+        .find(|version| manifest.protocol_versions.contains(version))
+        .copied()
+        .ok_or_else(|| {
+            format!(
+                "plugin protocols {:?} are not supported; engine supports {:?}",
+                manifest.protocol_versions, SUPPORTED_PROTOCOLS
+            )
+        })
+}
+
+fn validate_legacy_manifest(manifest: &LegacyManifestV1) -> Result<(), String> {
+    tracing::trace!(?manifest, "validating legacy plugin manifest");
+    if manifest.api_version != 1 {
+        return Err(format!(
+            "legacy plugin API {} is not supported",
+            manifest.api_version
+        ));
+    }
+    if manifest.engine_version != convertis_plugin_api::ENGINE_VERSION {
+        tracing::debug!(
+            plugin = %manifest.plugin_id,
+            built_for_engine = %manifest.engine_version,
+            current_engine = convertis_plugin_api::ENGINE_VERSION,
+            "legacy engine release differs; continuing because protocol v1 is retained"
+        );
+    }
+    if manifest.rustc_version != env!("CONVERTIS_RUSTC_VERSION") {
+        return Err(format!(
+            "legacy plugin was built with {}, but the engine uses {}; protocol v1 uses the unstable Rust ABI",
+            manifest.rustc_version,
+            env!("CONVERTIS_RUSTC_VERSION")
+        ));
+    }
+    if manifest.target != env!("CONVERTIS_TARGET") {
+        return Err(format!(
+            "legacy plugin targets {}, but the engine targets {}",
+            manifest.target,
+            env!("CONVERTIS_TARGET")
+        ));
+    }
+    Ok(())
+}
+
+unsafe fn read_manifest<T: DeserializeOwned>(manifest: PluginManifest) -> Result<T, String> {
+    tracing::trace!("calling plugin manifest entry point");
+    let pointer = unsafe { manifest() };
+    if pointer.is_null() {
+        return Err("ABI manifest was null".to_owned());
+    }
+    let json = unsafe { CStr::from_ptr(pointer) }
+        .to_str()
+        .map_err(|error| format!("invalid ABI manifest string: {error}"))?;
+    tracing::trace!(
+        manifest_bytes = json.len(),
+        manifest = json,
+        "received plugin manifest"
+    );
+    serde_json::from_str(json).map_err(|error| format!("invalid ABI manifest: {error}"))
+}
+
+unsafe fn decode_response<T: DeserializeOwned>(
+    pointer: *mut c_char,
+    free: PluginStringFree,
+    operation: &str,
+) -> Result<T, String> {
+    if pointer.is_null() {
+        return Err(format!("plugin returned null from {operation}"));
+    }
+    let json_result = unsafe { CStr::from_ptr(pointer) }
+        .to_str()
+        .map(str::to_owned)
+        .map_err(|error| format!("plugin returned invalid UTF-8 from {operation}: {error}"));
+    unsafe { free(pointer) };
+    let json = json_result?;
+    tracing::trace!(
+        operation,
+        response_bytes = json.len(),
+        "received plugin protocol response"
+    );
+    let response: WireResponse<T> = serde_json::from_str(&json)
+        .map_err(|error| format!("plugin returned invalid JSON from {operation}: {error}"))?;
+    match (response.ok, response.result, response.error) {
+        (true, Some(result), None) => Ok(result),
+        (true, None, None) => serde_json::from_value(serde_json::Value::Null).map_err(|error| {
+            format!("plugin returned no result value from successful {operation}: {error}")
+        }),
+        (false, _, Some(error)) => Err(error),
+        (true, _, Some(error)) => Err(format!(
+            "plugin returned both success and an error from {operation}: {error}"
+        )),
+        (false, _, None) => Err(format!(
+            "plugin returned failure without an error from {operation}"
+        )),
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    fn manifest(requirement: &str, protocols: &[u32]) -> StableManifest {
+        StableManifest {
+            manifest_version: 1,
+            protocol_versions: protocols.to_vec(),
+            engine_requirement: requirement.into(),
+            plugin_id: "example".into(),
+            plugin_version: "0.3.0".into(),
+            target: env!("CONVERTIS_TARGET").into(),
+        }
+    }
+
+    #[test]
+    fn current_plugin_requirement_accepts_future_engines() {
+        let manifest = manifest(">=0.3.0", &[2]);
+        assert_eq!(validate_stable_manifest(&manifest, "0.3.0"), Ok(2));
+        assert_eq!(validate_stable_manifest(&manifest, "99.0.0"), Ok(2));
+    }
+
+    #[test]
+    fn protocol_is_negotiated_independently_of_release_version() {
+        let manifest = manifest(">=0.1.0", &[1, 2, 3]);
+        assert_eq!(validate_stable_manifest(&manifest, "1.0.0"), Ok(2));
+    }
+
+    #[test]
+    fn unsupported_protocol_is_rejected() {
+        let error = validate_stable_manifest(&manifest(">=0.3.0", &[7]), "0.3.0").unwrap_err();
+        assert!(error.contains("not supported"));
     }
 }

src/runner.rs

@@ -32,35 +32,61 @@ pub fn run_conversion(
     temp_root: &Path,
     options: &BTreeMap<String, String>,
 ) -> Result<ConversionResult, (String, String)> {
+    tracing::debug!(
+        route_steps = route.len(),
+        input = %input.display(),
+        temp_root = %temp_root.display(),
+        option_count = options.len(),
+        "preparing conversion workspace"
+    );
+    tracing::trace!(directory = %temp_root.display(), "ensuring temporary root exists");
     fs::create_dir_all(temp_root).map_err(|error| (error.to_string(), "engine".to_owned()))?;
     let workspace = tempfile::Builder::new()
         .prefix("convertis-")
         .tempdir_in(temp_root)
         .map_err(|error| (error.to_string(), "engine".to_owned()))?;
+    tracing::debug!(workspace = %workspace.path().display(), "created conversion workspace");
     let mut current = input.to_path_buf();
     let mut kind = if input.is_dir() {
         ArtifactKind::Directory
     } else {
         ArtifactKind::File
     };
+    tracing::trace!(current = %current.display(), ?kind, "initialized current artifact");
 
     for (index, step) in route.iter().enumerate() {
         let metadata = step.plugin.metadata();
+        tracing::debug!(
+            step = index + 1,
+            total_steps = route.len(),
+            plugin = %metadata.id,
+            from = %step.conversion.from,
+            to = %step.conversion.to,
+            input_kind = ?step.conversion.input_kind,
+            output_kind = ?step.conversion.output_kind,
+            "preparing conversion step"
+        );
         let mut plugin_options = BTreeMap::new();
         for option in &metadata.options {
             if let Some(default) = &option.default {
+                tracing::trace!(plugin = %metadata.id, option = %option.name, value_length = default.len(), "applying default plugin option");
                 plugin_options.insert(option.name.clone(), default.clone());
             }
         }
         for (key, value) in options {
             if let Some((plugin_id, option)) = key.split_once('.') {
                 if plugin_id == metadata.id {
+                    tracing::trace!(plugin = %metadata.id, key, option, value_length = value.len(), "applying qualified plugin option");
                     plugin_options.insert(option.to_owned(), value.clone());
+                } else {
+                    tracing::trace!(plugin = %metadata.id, key, "qualified option belongs to another route step");
                 }
             } else if metadata.options.iter().any(|option| option.name == *key) {
+                tracing::trace!(plugin = %metadata.id, key, value_length = value.len(), "applying unqualified plugin option");
                 plugin_options.insert(key.clone(), value.clone());
             }
         }
+        tracing::trace!(plugin = %metadata.id, options = ?plugin_options.keys().collect::<Vec<_>>(), "resolved conversion-step options");
         let output = match step.conversion.output_kind {
             ArtifactKind::File => workspace.path().join(format!(
                 "step-{index}.{}",
@@ -68,7 +94,9 @@ pub fn run_conversion(
             )),
             ArtifactKind::Directory => workspace.path().join(format!("step-{index}")),
         };
+        tracing::trace!(plugin = %metadata.id, output = %output.display(), "allocated conversion-step output path");
         if step.conversion.output_kind == ArtifactKind::Directory {
+            tracing::trace!(output = %output.display(), "creating directory artifact output");
             fs::create_dir_all(&output)
                 .map_err(|error| (error.to_string(), "engine".to_owned()))?;
         }
@@ -79,12 +107,22 @@ pub fn run_conversion(
             to: step.conversion.to.clone(),
             options: plugin_options,
         };
-        step.plugin
-            .convert(&request)
-            .map_err(|error| (error, step.plugin.metadata().id))?;
+        tracing::trace!(
+            plugin = %metadata.id,
+            input = %request.input.display(),
+            output = %request.output.display(),
+            "dispatching conversion request to plugin"
+        );
+        step.plugin.convert(&request).map_err(|error| {
+            tracing::debug!(plugin = %metadata.id, %error, "conversion step failed");
+            (error, metadata.id.clone())
+        })?;
+        tracing::trace!(plugin = %metadata.id, output_exists = output.exists(), "plugin returned conversion success");
         current = output;
         kind = step.conversion.output_kind;
+        tracing::debug!(step = index + 1, plugin = %metadata.id, artifact = %current.display(), ?kind, "conversion step completed");
     }
+    tracing::debug!(result = %current.display(), ?kind, "all conversion steps completed");
     Ok(ConversionResult {
         path: current,
         kind,
@@ -93,45 +131,59 @@ pub fn run_conversion(
 }
 
 fn file_extension(format: &str) -> &str {
-    match format {
+    let extension = match format {
         "animated-gif" => "gif",
         "animated-webp" => "webp",
         "text" => "txt",
         other => other,
-    }
+    };
+    tracing::trace!(format, extension, "mapped format to workspace extension");
+    extension
 }
 
 pub fn install_result(result: &ConversionResult, destination: &Path) -> io::Result<()> {
     let parent = destination.parent().unwrap_or_else(|| Path::new("."));
+    tracing::debug!(source = %result.path.display(), destination = %destination.display(), ?result.kind, "installing result atomically");
+    tracing::trace!(parent = %parent.display(), "ensuring destination parent exists");
     fs::create_dir_all(parent)?;
     match result.kind {
         ArtifactKind::File => {
+            tracing::trace!(parent = %parent.display(), "creating file staging area");
             let staging = tempfile::NamedTempFile::new_in(parent)?;
+            tracing::trace!(staging = %staging.path().display(), "copying file result into staging area");
             fs::copy(&result.path, staging.path())?;
+            tracing::trace!(destination = %destination.display(), "persisting staged file result");
             staging.persist(destination).map_err(|error| error.error)?;
         }
         ArtifactKind::Directory => {
+            tracing::trace!(parent = %parent.display(), "creating directory staging area");
             let staging = tempfile::Builder::new()
                 .prefix(".convertis-output-")
                 .tempdir_in(parent)?;
             let payload = staging.path().join("payload");
             copy_directory(&result.path, &payload)?;
+            tracing::trace!(payload = %payload.display(), destination = %destination.display(), "renaming staged directory result");
             fs::rename(payload, destination)?;
         }
     }
+    tracing::debug!(destination = %destination.display(), "result installation completed");
     Ok(())
 }
 
 fn copy_directory(source: &Path, destination: &Path) -> io::Result<()> {
+    tracing::trace!(source = %source.display(), destination = %destination.display(), "copying directory");
     fs::create_dir_all(destination)?;
     for entry in fs::read_dir(source)? {
         let entry = entry?;
         let target = destination.join(entry.file_name());
-        if entry.file_type()?.is_dir() {
+        let file_type = entry.file_type()?;
+        tracing::trace!(source = %entry.path().display(), target = %target.display(), is_directory = file_type.is_dir(), "copying directory entry");
+        if file_type.is_dir() {
             copy_directory(&entry.path(), &target)?;
         } else {
             fs::copy(entry.path(), target)?;
         }
     }
+    tracing::trace!(source = %source.display(), destination = %destination.display(), "directory copy completed");
     Ok(())
 }