diff --git a/Cargo.lock b/Cargo.lock index 45f00211..144046af 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4374,6 +4374,7 @@ dependencies = [ "clap", "clap_complete", "clap_mangen", + "log", "same-file", "serde", "serde_json", diff --git a/apps/soundcraft-cli/Cargo.toml b/apps/soundcraft-cli/Cargo.toml index 9316b5b8..37ba7649 100644 --- a/apps/soundcraft-cli/Cargo.toml +++ b/apps/soundcraft-cli/Cargo.toml @@ -25,6 +25,7 @@ soundcraft-dsp.workspace = true serde.workspace = true serde_json.workspace = true thiserror.workspace = true +log.workspace = true clap.workspace = true same-file.workspace = true diff --git a/apps/soundcraft-cli/src/lib.rs b/apps/soundcraft-cli/src/lib.rs index fe351e2e..f72c42a8 100644 --- a/apps/soundcraft-cli/src/lib.rs +++ b/apps/soundcraft-cli/src/lib.rs @@ -11,6 +11,7 @@ mod catalog; mod convert; mod error; mod info; +pub mod logger; mod mcp; mod session; diff --git a/apps/soundcraft-cli/src/logger.rs b/apps/soundcraft-cli/src/logger.rs new file mode 100644 index 00000000..317b44a0 --- /dev/null +++ b/apps/soundcraft-cli/src/logger.rs @@ -0,0 +1,49 @@ +//! The command line's logger. Without one, every `log::warn!` and `log::error!` in the workspace +//! was dropped: a plugin that failed to load just vanished from `engine.clap_plugins`, and nothing +//! said why. Warnings and errors now go to standard error as `warning: ` and +//! `error: `, like the CLI's own errors; standard output keeps only the results. +//! `RUST_LOG` stays a desktop app variable (docs/cli.md), so the level is fixed. + +use std::io::Write; + +struct StderrLogger; + +impl log::Log for StderrLogger { + fn enabled(&self, metadata: &log::Metadata<'_>) -> bool { + metadata.level() <= log::Level::Warn + } + + fn log(&self, record: &log::Record<'_>) { + if self.enabled(record.metadata()) { + // A closed standard error is not worth failing a command over. + let _ = std::io::stderr().write_all(line(record.level(), &record.args().to_string()).as_bytes()); + } + } + + fn flush(&self) {} +} + +/// One record as the CLI prints it. +fn line(level: log::Level, message: &str) -> String { + let label = if level == log::Level::Error { "error" } else { "warning" }; + format!("{label}: {}\n", message.strip_suffix('\n').unwrap_or(message)) +} + +/// Installs the logger. Once per process: `main` calls it, not `run`, which tests call many times. +pub fn install() { + static LOGGER: StderrLogger = StderrLogger; + if log::set_logger(&LOGGER).is_ok() { + log::set_max_level(log::LevelFilter::Warn); + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn records_print_like_the_cli_errors() { + assert_eq!(line(log::Level::Warn, "cannot load CLAP plugin x.clap: bad file\n"), "warning: cannot load CLAP plugin x.clap: bad file\n"); + assert_eq!(line(log::Level::Error, "panic: boom"), "error: panic: boom\n"); + } +} diff --git a/apps/soundcraft-cli/src/main.rs b/apps/soundcraft-cli/src/main.rs index 7d381be7..e29c38f4 100644 --- a/apps/soundcraft-cli/src/main.rs +++ b/apps/soundcraft-cli/src/main.rs @@ -3,6 +3,7 @@ #![deny(clippy::unwrap_used, clippy::expect_used, clippy::panic, clippy::unimplemented, clippy::todo, clippy::unreachable)] fn main() { + soundcraft_cli::logger::install(); // `args_os`, not `args`: a non-Unicode argument must reach clap, not panic before anything is printed. let code = soundcraft_cli::run(std::env::args_os().skip(1), &mut std::io::stdout(), &mut std::io::stderr()); // The subcommand's engine and its plugin instances are gone by now. This is process teardown, diff --git a/apps/soundcraft-cli/tests/it/behaviour.rs b/apps/soundcraft-cli/tests/it/behaviour.rs index 69bdffa9..52c5eaeb 100644 --- a/apps/soundcraft-cli/tests/it/behaviour.rs +++ b/apps/soundcraft-cli/tests/it/behaviour.rs @@ -88,6 +88,25 @@ fn assert_refused(got: &Invoke, port: u16) { assert!(got.stderr.starts_with(&prefix) && got.stderr.contains(" (os error ") && got.stderr.ends_with(")\n"), "{}", got.stderr); } +// ---- logging ---- + +/// Warnings SoundCraft logs (a plugin that fails to load, a backup it can't write) go to standard +/// error. Without a logger they were dropped. +#[test] +fn logged_warnings_reach_standard_error() { + let dir = sandbox("log"); + let first = invoke(&dir, &["run", "--save", "s.scraft"]); + assert_eq!(first.code, 0, "{}", first.stderr); + // A file where the backups folder should go: the next save that changes the session can't + // back the old one up. + std::fs::write(dir.join("Backups"), b"not a folder").unwrap(); + let again = invoke(&dir, &["run", "--in", "s.scraft", "--cmd", r#"track.new={"count":1}"#, "--save", "s.scraft", "--in-place"]); + assert_eq!(again.code, 0, "{}", again.stderr); + assert!(again.stderr.contains("warning: no backup of"), "{}", again.stderr); + assert!(!again.stdout.contains("no backup"), "results only on standard output: {}", again.stdout); + let _ = std::fs::remove_dir_all(&dir); +} + // ---- unknown flags ---- #[test] diff --git a/docs/cli.md b/docs/cli.md index eb94ab74..28d36fcd 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -38,7 +38,7 @@ Results go to standard output, as JSON where a program is meant to read them. `i file), `describe`, `app` and the `--inspect` output of `run` and `script` pretty-print it; `--compact` prints the same JSON on one line. The result lines of `run` and `script` (`ID: JSON`) and the `--bounce` and `--save` results are always one line each. `commands`, `plugins`, `parity` and the -`.scraft` summary of `info` are text. Errors go to standard error as `error: `. `mcp` writes only the protocol +`.scraft` summary of `info` are text. Errors go to standard error as `error: `, and so do the warnings and errors SoundCraft and the plugin hosts log (`warning: `, `error: `), such as a plugin that fails to load. `mcp` writes only the protocol to standard output. | Exit code | Meaning |