mcp_execution_cli/runner.rs
1//! Command execution and runtime logic.
2//!
3//! Contains the main command execution loop and logging initialization.
4
5use std::io::{self, Write};
6
7use anyhow::Result;
8use mcp_execution_core::Error as CoreError;
9use mcp_execution_core::cli::{ExitCode, LOG_FORMAT_ENV_VAR, LogFormat, OutputFormat};
10use mcp_execution_files::FilesError;
11use tracing_subscriber::{EnvFilter, Layer as _, layer::SubscriberExt, util::SubscriberInitExt};
12
13use crate::cli::Commands;
14use crate::commands;
15use crate::commands::common::ServerSource;
16use crate::formatters::escape_error_text;
17
18/// [`Write`] wrapper that redacts embedded secrets out of each buffer before forwarding it to the
19/// inner sink.
20///
21/// Exists because `rmcp`'s own `tracing` targets (e.g. `rmcp::transport::worker`'s `ERROR` line on
22/// a connection failure) format a `reqwest::Error` whose `Display` embeds the full request URL,
23/// query string included, and log it directly — bypassing every redacting `Debug` impl this
24/// project applies to its own types, since this project never constructs that line's text.
25/// `tracing-subscriber`'s fmt layer formats each event into a buffer and issues exactly one
26/// [`write_all`](Write::write_all) call per event (verified against `tracing-subscriber` 0.3.23's
27/// `fmt_layer` internals), so `write` here always receives one whole formatted event line, which
28/// [`mcp_execution_core::redact_urls_in_text`] can scan and redact as a unit.
29///
30/// Generic over the inner writer so tests can redirect to an in-memory buffer instead of the real
31/// `stderr` [`init_logging`] wraps it around.
32struct RedactingWriter<W>(W);
33
34impl<W: Write> Write for RedactingWriter<W> {
35 fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
36 let text = String::from_utf8_lossy(buf);
37 self.0
38 .write_all(mcp_execution_core::redact_urls_in_text(&text).as_bytes())?;
39 // The whole input was consumed and forwarded (redaction only ever
40 // changes the byte count written *downstream*, not how much of
41 // `buf` this call accounts for), so report all of it as written.
42 Ok(buf.len())
43 }
44
45 fn flush(&mut self) -> io::Result<()> {
46 self.0.flush()
47 }
48}
49
50/// Resolves the effective log format from `log_format` (the `--log-format` flag value) and the
51/// `MCP_EXECUTION_LOG_FORMAT` environment variable, mirroring `mcp-execution-server`'s
52/// `resolve_log_format`. Kept as its own function (rather than inlined in [`init_logging`]) so a
53/// test can assert the environment variable is actually consulted -- see
54/// `resolve_log_format_reads_env_var_when_flag_unset` -- rather than only exercising the pure
55/// `LogFormat::resolve` this delegates to.
56fn resolve_log_format(log_format: Option<LogFormat>) -> LogFormat {
57 let env_value = std::env::var(LOG_FORMAT_ENV_VAR).ok();
58 LogFormat::resolve(log_format, env_value.as_deref())
59}
60
61/// Whether [`init_logging`] should warn about a rejected `MCP_EXECUTION_LOG_FORMAT` value: the
62/// flag was not passed (matching `LogFormat::resolve`'s own precedence -- a bad env value is not
63/// even inspected once the flag has decided, so it must not warn either) and the environment
64/// variable is set to a non-empty value [`LogFormat::is_invalid_env_value`] rejects. Kept
65/// separate from [`resolve_log_format`] (rather than a second return value there) since
66/// production code needs only a yes/no answer, not the rejected value itself -- see
67/// [`LogFormat::resolve`]'s own doc comment on why that value isn't threaded through.
68fn log_format_env_is_invalid(log_format: Option<LogFormat>) -> bool {
69 log_format.is_none()
70 && std::env::var(LOG_FORMAT_ENV_VAR)
71 .ok()
72 .is_some_and(|raw| LogFormat::is_invalid_env_value(&raw))
73}
74
75/// Caps `rmcp`'s own `tracing` targets at `info`, on top of whatever base filter is already in
76/// effect.
77///
78/// `rmcp` 3.1.2's transport layer logs raw, unsanitized peer input at `debug` level. This crate is
79/// a *client* of third-party MCP servers (see `mcp_execution_introspector::Introspector`), so
80/// without this cap, `--verbose` alone -- with no `RUST_LOG` involved -- streams an untrusted
81/// server's raw stdout lines into stderr; [`RedactingWriter`] only rewrites embedded URLs, it does
82/// not neutralize this (issue #421). This closes the *debug-level, raw-line* logging specifically
83/// -- `rmcp` also logs a `Debug`-formatted peer notification at `info`, which this cap does not
84/// and cannot suppress (`rmcp=info` still allows `info`); that site is mitigated by
85/// `Debug`-escaping control characters, not eliminated.
86///
87/// Applied via [`EnvFilter::add_directive`] to the filter already selected by [`init_logging`]'s
88/// verbose/non-verbose branches, not folded into only one of them: a directive added solely to
89/// the non-verbose fallback string would never apply to `--verbose`'s `EnvFilter::new("debug")`,
90/// which does not consult `RUST_LOG` at all.
91///
92/// Directive sets order by target specificity, so this `rmcp=info` directive (more specific than
93/// a bare global `debug`) wins over it. An operator who explicitly sets a *more specific*
94/// directive, e.g. `RUST_LOG=rmcp::transport=debug`, still wins over this one -- that is
95/// intentional: this cap closes the accidental broad-`debug` case, not an operator's deliberate
96/// request for `rmcp` transport debug logs -- **this is the escape hatch**: a target under
97/// `rmcp::` (not the bare `rmcp` target this cap sets) survives the cap and can be raised back to
98/// `debug` explicitly. Note this is target *specificity*, not level: an equally-specific
99/// `RUST_LOG=rmcp=debug` (same target as this cap, different level) is *replaced* by this cap's
100/// `rmcp=info`, not merged with it -- `tracing_subscriber`'s `Directive` ordering does not compare
101/// level, so a same-target `add_directive` call overwrites the existing entry. Both behaviors are
102/// pinned by tests below rather than assumed.
103fn cap_rmcp_log_level(filter: EnvFilter) -> EnvFilter {
104 filter.add_directive(
105 "rmcp=info"
106 .parse()
107 .expect("static \"rmcp=info\" directive string is always valid"),
108 )
109}
110
111/// Initializes logging infrastructure.
112///
113/// Sets up tracing with appropriate log levels based on verbosity flag.
114/// Writes log messages to stderr, with any embedded URL's credentials/query string redacted (via
115/// a wrapping [`Write`] adapter around the fmt layer's writer) — this covers `rmcp` and any other
116/// dependency's log lines, not just this
117/// project's own, since a dependency's `tracing` output cannot go through this crate's
118/// `Debug`/[`escape_error_text`] redaction paths.
119///
120/// `log_format` selects text or JSON output. When `None` (the flag was not passed),
121/// [`LogFormat::resolve`] consults the `MCP_EXECUTION_LOG_FORMAT` environment variable; an unset
122/// or invalid environment value falls back to text with a `WARN`-level log line (never echoing
123/// the rejected raw value — see the project's log-injection hardening for this switch).
124///
125/// Both branches are passed through `cap_rmcp_log_level`, which caps `rmcp`'s own `tracing`
126/// targets at `info` regardless of the base filter -- see that function's doc comment for why.
127///
128/// # Arguments
129///
130/// * `verbose` - If true, sets log level to DEBUG; otherwise uses INFO or
131/// environment variable override via `RUST_LOG`
132/// * `log_format` - `--log-format` flag value, or `None` to consult
133/// `MCP_EXECUTION_LOG_FORMAT`
134///
135/// # Errors
136///
137/// This function cannot fail—it always returns `Ok(())`. Multiple calls
138/// in the same process will panic rather than returning an error, but this
139/// is not a recoverable condition and indicates a programming error.
140///
141/// # Examples
142///
143/// ```no_run
144/// use mcp_execution_cli::runner;
145///
146/// // `no_run`: this installs a process-global tracing subscriber, which
147/// // panics if called more than once in the same process.
148/// runner::init_logging(false, None)?;
149/// # Ok::<(), anyhow::Error>(())
150/// ```
151pub fn init_logging(verbose: bool, log_format: Option<LogFormat>) -> Result<()> {
152 let filter = cap_rmcp_log_level(if verbose {
153 EnvFilter::new("debug")
154 } else {
155 EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))
156 });
157
158 let format = resolve_log_format(log_format);
159
160 let fmt_layer = tracing_subscriber::fmt::layer().with_writer(|| RedactingWriter(io::stderr()));
161 let layer = match format {
162 LogFormat::Json => fmt_layer.json().boxed(),
163 LogFormat::Text => fmt_layer.boxed(),
164 };
165
166 tracing_subscriber::registry()
167 .with(filter)
168 .with(layer)
169 .init();
170
171 // No raw value interpolation: the rejected value already comes from an external environment
172 // variable, and echoing it into a log line — even truncated — would open a log-injection
173 // vector for whoever controls the process environment.
174 if log_format_env_is_invalid(log_format) {
175 tracing::warn!(
176 "invalid value for {LOG_FORMAT_ENV_VAR} (expected 'text' or 'json'), falling back to text"
177 );
178 }
179
180 Ok(())
181}
182
183/// Executes the specified CLI command.
184///
185/// Routes commands to their respective handlers. On success, returns the exit
186/// code reported by the handler. If the handler fails, the error is printed
187/// to stderr and classified into a semantic [`ExitCode`] via
188/// `classify_exit_code` rather than propagated — this lets `main` always
189/// turn the result into a process exit code without falling back to anyhow's
190/// default behavior of collapsing every `Err` to exit code 1.
191///
192/// # Arguments
193///
194/// * `command` - The parsed CLI command to execute
195/// * `output_format` - Output format preference (JSON, text, or pretty)
196///
197/// # Errors
198///
199/// This function does not propagate command execution failures as `Err` —
200/// see above. It is fallible in signature to match this crate's convention
201/// of using `Result` consistently across command handlers.
202///
203/// # Examples
204///
205/// ```no_run
206/// use mcp_execution_cli::cli::Commands;
207/// use mcp_execution_cli::runner;
208/// use mcp_execution_core::cli::OutputFormat;
209///
210/// # async fn example() -> anyhow::Result<()> {
211/// let exit_code = runner::execute_command(
212/// Commands::Setup,
213/// OutputFormat::Pretty,
214/// ).await?;
215/// # Ok(())
216/// # }
217/// ```
218pub async fn execute_command(command: Commands, output_format: OutputFormat) -> Result<ExitCode> {
219 Ok(match dispatch(command, output_format).await {
220 Ok(code) => code,
221 Err(err) => report_and_classify(&err),
222 })
223}
224
225/// Routes `command` to its handler and returns the handler's result unclassified.
226///
227/// # Errors
228///
229/// Returns whatever error the dispatched command handler produces.
230async fn dispatch(command: Commands, output_format: OutputFormat) -> Result<ExitCode> {
231 match command {
232 Commands::Introspect { flags, detailed } => {
233 let source = ServerSource::try_from(flags)?;
234 commands::introspect::run(source, detailed, output_format).await
235 }
236 Commands::Skill {
237 server,
238 servers_dir,
239 output,
240 skill_name,
241 hints,
242 overwrite,
243 } => {
244 commands::skill::run(
245 server,
246 servers_dir,
247 output,
248 skill_name,
249 hints,
250 overwrite,
251 output_format,
252 )
253 .await
254 }
255 Commands::Generate {
256 flags,
257 name,
258 progressive_output,
259 dry_run,
260 } => {
261 let source = ServerSource::try_from(flags)?;
262 commands::generate::run(source, name, progressive_output, dry_run, output_format).await
263 }
264 Commands::Server { action } => commands::server::run(action, output_format).await,
265 Commands::Setup => commands::setup::run(output_format).await,
266 Commands::Completions { shell } => run_completions(shell).await,
267 }
268}
269
270/// Runs the `completions` subcommand: builds the clap command tree and generates the shell
271/// completion script for it.
272async fn run_completions(shell: clap_complete::Shell) -> Result<ExitCode> {
273 use crate::cli::Cli;
274 use clap::CommandFactory;
275 let mut cmd = Cli::command();
276 commands::completions::run(shell, &mut cmd).await
277}
278
279/// Prints `err` to stderr, then classifies it into a semantic [`ExitCode`].
280///
281/// Structurally matches anyhow's default `main`-error format (a summary line, then a numbered
282/// "Caused by:" section for any further causes), but with each cause's own text — not anyhow's
283/// surrounding structure — passed through [`escape_error_text`] before printing. Classification is
284/// via `classify_exit_code`.
285///
286/// Shared by [`execute_command`] (command-handler failures) and `main`
287/// (pre-dispatch failures, e.g. an invalid `--format` value), so every
288/// failure this CLI can produce is reported and exits the same way. An
289/// error's cause chain can embed content from an untrusted MCP server (e.g.
290/// a JSON-RPC error `message`), and both `anyhow::Error`'s `Debug` rendering
291/// and the `thiserror`-derived `Display` impls it walks interpolate that
292/// content verbatim — so `err`'s formatted report is sanitized via
293/// `sanitized_error_report` before printing.
294///
295/// # Examples
296///
297/// ```
298/// use mcp_execution_cli::runner;
299/// use mcp_execution_core::Error as CoreError;
300/// use mcp_execution_core::cli::ExitCode;
301///
302/// let err = anyhow::Error::from(CoreError::InvalidArgument(
303/// "invalid output format: 'xml' (expected: json, text, or pretty)".to_string(),
304/// ));
305/// assert_eq!(runner::report_and_classify(&err), ExitCode::INVALID_INPUT);
306/// ```
307#[must_use]
308pub fn report_and_classify(err: &anyhow::Error) -> ExitCode {
309 eprintln!("Error: {}", sanitized_error_report(err));
310 classify_exit_code(err)
311}
312
313/// Renders `err`'s cause chain — and, if captured, its backtrace — exactly as
314/// [`report_and_classify`] prints them: a summary line, then (if there are further causes) a
315/// "Caused by:" section listing each one, numbered from 0, then (if `RUST_BACKTRACE`/
316/// `RUST_LIB_BACKTRACE` caused one to be captured) a "Stack backtrace:" section. Each cause's own
317/// rendered text is sanitized individually via [`escape_error_text`] (capped to 4000 chars each);
318/// the backtrace is not, and is not length-capped either.
319///
320/// An earlier version of this function sanitized anyhow's fully-rendered `{err:?}` report as one
321/// blob. That could not tell anyhow's own trusted structural newlines/indentation (between `Caused
322/// by:` frames, and throughout a backtrace) apart from a `\n` embedded in one cause's own
323/// untrusted `Display` text (e.g. a hostile MCP server's JSON-RPC error `message`, which
324/// `anyhow`/`thiserror` interpolate verbatim) — so it neutralized both alike, collapsing a
325/// legitimate multi-cause chain, and any backtrace, onto one line and truncating the result well
326/// short of a typical backtrace's length, for no security benefit. Building the report from
327/// [`anyhow::Error::chain`] instead sanitizes only each cause's own text and rejoins with
328/// `\n\nCaused by:\n{n:>5}: ` separators this function itself writes, so a hostile cause cannot
329/// forge those separators (any `\n` in *its* text is still neutralized) while a chain with only
330/// trusted causes keeps its real multi-line structure. [`anyhow::Error::backtrace`] is not part of
331/// `chain()` — it is captured once from the local call stack at the point `err` was constructed —
332/// so it carries nothing an external MCP server could have influenced, and is appended verbatim.
333///
334/// Deliberately does not reproduce one thing anyhow's own `{err:?}` output has: it always numbers
335/// every cause, where anyhow omits the number when there is exactly one. That's structural/local
336/// formatting with nothing untrusted in it, so it isn't a correctness concern for this function's
337/// purpose — a simplification to avoid depending on anyhow's private formatting internals, not the
338/// reason this exists. The backtrace section's own layout mirrors anyhow's
339/// (`anyhow-1.0.104/src/fmt.rs`'s `ErrorImpl::debug`) via the same public
340/// [`anyhow::Error::backtrace`] accessor it uses internally.
341///
342/// Factored out of [`report_and_classify`] (rather than inlined) so tests can assert on precisely
343/// the string that reaches stderr by calling this directly, instead of recomputing the same
344/// pipeline independently and asserting against that — which would silently drift from the real
345/// code path if either implementation changed without the other.
346fn sanitized_error_report(err: &anyhow::Error) -> String {
347 use std::backtrace::BacktraceStatus;
348 use std::fmt::Write as _;
349
350 let mut links = err.chain();
351
352 let mut report = links
353 .next()
354 .map_or_else(String::new, |top| escape_error_text(&top.to_string()));
355
356 let causes: Vec<_> = links.collect();
357 if !causes.is_empty() {
358 report.push_str("\n\nCaused by:");
359 for (n, cause) in causes.into_iter().enumerate() {
360 // `write!` into a `String` is infallible.
361 let _ = write!(
362 report,
363 "\n{n:>5}: {}",
364 escape_error_text(&cause.to_string())
365 );
366 }
367 }
368
369 let backtrace = err.backtrace();
370 if backtrace.status() == BacktraceStatus::Captured {
371 // Trusted, locally-generated content (source file paths, function names from this
372 // binary's own stack) — deliberately not sanitized or length-capped, unlike the chain
373 // links above. Mirrors anyhow's own `ErrorImpl::debug` header handling: some Rust/backtrace
374 // versions' `Backtrace::to_string()` already starts with a lowercase "stack backtrace:"
375 // header, others don't.
376 let mut backtrace_text = backtrace.to_string();
377 report.push_str("\n\n");
378 if backtrace_text.starts_with("stack backtrace:") {
379 backtrace_text.replace_range(0..1, "S");
380 } else {
381 report.push_str("Stack backtrace:\n");
382 }
383 backtrace_text.truncate(backtrace_text.trim_end().len());
384 report.push_str(&backtrace_text);
385 }
386
387 report
388}
389
390/// Classifies an [`anyhow::Error`] returned by a command handler into a
391/// semantic [`ExitCode`].
392///
393/// Walks the error's cause chain looking for a [`CoreError`] — the concrete
394/// type every command handler ultimately produces via `?` — and delegates to
395/// [`classify_core_error`] for the variant-to-exit-code mapping. Falls back to checking for a
396/// [`FilesError`] (the `generate` command's `export_to_filesystem` errors are wrapped via
397/// `anyhow::Context` rather than converted to `CoreError`, so they would otherwise never match
398/// the first check and always fall through to the generic [`ExitCode::ERROR`] — issue #198 M6).
399/// Errors that match neither (e.g. CLI argument parsing, serialization) fall back to
400/// [`ExitCode::ERROR`].
401fn classify_exit_code(error: &anyhow::Error) -> ExitCode {
402 if let Some(core_error) = error
403 .chain()
404 .find_map(|cause| cause.downcast_ref::<CoreError>())
405 {
406 return classify_core_error(core_error);
407 }
408
409 if let Some(files_error) = error
410 .chain()
411 .find_map(|cause| cause.downcast_ref::<FilesError>())
412 {
413 return match files_error {
414 // Same "the server is at fault" classification as `CoreError::ResourceLimitExceeded`
415 // above — the export this bounds is sized by what the (possibly hostile or
416 // misbehaving) introspected server returned, not by CLI-caller-supplied input.
417 FilesError::ResourceLimitExceeded { .. } => ExitCode::SERVER_ERROR,
418 FilesError::FileNotFound { .. }
419 | FilesError::NotADirectory { .. }
420 | FilesError::InvalidPath { .. }
421 | FilesError::PathNotAbsolute { .. }
422 | FilesError::InvalidPathComponent { .. }
423 | FilesError::PathEscapesBase { .. }
424 | FilesError::IoError { .. } => ExitCode::ERROR,
425 };
426 }
427
428 ExitCode::ERROR
429}
430
431/// Classifies a single [`CoreError`] variant.
432///
433/// [`CoreError::ScriptGenerationError`] wraps an arbitrary underlying failure (schema
434/// extraction, template rendering, output tracking) behind one variant so a codegen error can
435/// always be attributed to the tool that caused it; that wrapping must not also collapse the
436/// wrapped cause's own exit-code classification (e.g. a wrapped
437/// [`CoreError::ResourceLimitExceeded`] should still report [`ExitCode::SERVER_ERROR`], not the
438/// generic code every other `ScriptGenerationError` gets). Recursing into `source` when it
439/// downcasts to another `CoreError` preserves that.
440fn classify_core_error(core_error: &CoreError) -> ExitCode {
441 match core_error {
442 CoreError::Timeout { .. } => ExitCode::TIMEOUT,
443 // A resource limit is exceeded by data the remote MCP server returned (tool
444 // count, schema size, etc.), not by the CLI caller's own arguments — same
445 // "the server is at fault" classification as `ConnectionFailed`.
446 CoreError::ConnectionFailed { .. } | CoreError::ResourceLimitExceeded { .. } => {
447 ExitCode::SERVER_ERROR
448 }
449 CoreError::ValidationError { .. }
450 | CoreError::SecurityViolation { .. }
451 | CoreError::InvalidArgument(_) => ExitCode::INVALID_INPUT,
452 // A duplicate generated-file path indicates a codegen invariant was violated (e.g. a
453 // reserved output filename not seeded into name-collision resolution), not something
454 // caused by the remote server's data or the CLI caller's own arguments.
455 CoreError::SerializationError { .. } | CoreError::DuplicateGeneratedFilePath { .. } => {
456 ExitCode::ERROR
457 }
458 CoreError::ScriptGenerationError { source, .. } => source
459 .as_deref()
460 .and_then(|source| source.downcast_ref::<CoreError>())
461 .map_or(ExitCode::ERROR, classify_core_error),
462 }
463}
464
465#[cfg(test)]
466mod tests {
467 use super::*;
468 use mcp_execution_core::ResourceKind;
469 use mcp_execution_core::ServerId;
470 use mcp_execution_files::FilesResourceKind;
471
472 fn wrap(core_error: CoreError) -> anyhow::Error {
473 anyhow::Error::new(core_error)
474 }
475
476 #[test]
477 fn test_classify_exit_code_timeout() {
478 let err = wrap(CoreError::Timeout {
479 operation: "discover".to_string(),
480 duration_secs: 30,
481 });
482 assert_eq!(classify_exit_code(&err), ExitCode::TIMEOUT);
483 }
484
485 #[test]
486 fn test_classify_exit_code_connection_failed() {
487 let err = wrap(CoreError::ConnectionFailed {
488 server: "test".to_string(),
489 source: "refused".into(),
490 });
491 assert_eq!(classify_exit_code(&err), ExitCode::SERVER_ERROR);
492 }
493
494 #[test]
495 fn test_classify_exit_code_resource_limit_exceeded() {
496 let err = wrap(CoreError::ResourceLimitExceeded {
497 resource: ResourceKind::ToolCount {
498 server_id: ServerId::new("github").unwrap(),
499 },
500 actual: 1500,
501 limit: 1000,
502 });
503 assert_eq!(classify_exit_code(&err), ExitCode::SERVER_ERROR);
504 }
505
506 /// #198 M6 — `FilesError` (e.g. from `generate`'s `export_to_filesystem`, wrapped via
507 /// `anyhow::Context` rather than converted to `CoreError`) must be classified too, not
508 /// fall through to the generic `ExitCode::ERROR` unconditionally.
509 #[test]
510 fn test_classify_exit_code_files_error_resource_limit_exceeded() {
511 let files_error = FilesError::ResourceLimitExceeded {
512 resource: FilesResourceKind::ExportFileCount,
513 actual: 3000,
514 limit: 2000,
515 };
516 // Mirrors how `commands::generate::run` actually wraps this error.
517 let err: anyhow::Error =
518 anyhow::Error::new(files_error).context("failed to export files to filesystem");
519
520 assert_eq!(classify_exit_code(&err), ExitCode::SERVER_ERROR);
521 }
522
523 #[test]
524 fn test_classify_exit_code_files_error_other_variant_falls_back_to_error() {
525 let err = anyhow::Error::new(FilesError::FileNotFound {
526 path: "/missing".to_string(),
527 });
528 assert_eq!(classify_exit_code(&err), ExitCode::ERROR);
529 }
530
531 #[test]
532 fn test_classify_exit_code_validation_error() {
533 let err = wrap(CoreError::ValidationError {
534 field: "connect_timeout".to_string(),
535 reason: "must be greater than zero".to_string(),
536 });
537 assert_eq!(classify_exit_code(&err), ExitCode::INVALID_INPUT);
538 }
539
540 #[test]
541 fn test_classify_exit_code_security_violation() {
542 let err = wrap(CoreError::SecurityViolation {
543 reason: "forbidden env var".to_string(),
544 });
545 assert_eq!(classify_exit_code(&err), ExitCode::INVALID_INPUT);
546 }
547
548 #[test]
549 fn test_classify_exit_code_invalid_argument() {
550 let err = wrap(CoreError::InvalidArgument("bad flag".to_string()));
551 assert_eq!(classify_exit_code(&err), ExitCode::INVALID_INPUT);
552 }
553
554 #[test]
555 fn test_classify_exit_code_other_core_errors_fall_back_to_error() {
556 let err = wrap(CoreError::SerializationError {
557 message: "bad json".to_string(),
558 source: None,
559 });
560 assert_eq!(classify_exit_code(&err), ExitCode::ERROR);
561
562 let err = wrap(CoreError::ScriptGenerationError {
563 tool: "example_tool".to_string(),
564 message: "template rendering failed".to_string(),
565 source: None,
566 });
567 assert_eq!(classify_exit_code(&err), ExitCode::ERROR);
568 }
569
570 /// `ScriptGenerationError` wraps its cause via `source` (see
571 /// `ProgressiveGenerator::wrap_tool_generation_error`) precisely so this recursion can
572 /// still find the original classification instead of collapsing every wrapped cause to the
573 /// generic exit code.
574 #[test]
575 fn test_classify_exit_code_script_generation_error_recurses_into_wrapped_source() {
576 let err = wrap(CoreError::ScriptGenerationError {
577 tool: "example_tool".to_string(),
578 message: "failed to track generated tool file".to_string(),
579 source: Some(Box::new(CoreError::ResourceLimitExceeded {
580 resource: ResourceKind::GeneratedOutputSize,
581 actual: 10,
582 limit: 5,
583 })),
584 });
585 assert_eq!(classify_exit_code(&err), ExitCode::SERVER_ERROR);
586 }
587
588 #[test]
589 fn test_classify_exit_code_non_core_error_falls_back_to_error() {
590 let err = anyhow::anyhow!("plain CLI-layer failure");
591 assert_eq!(classify_exit_code(&err), ExitCode::ERROR);
592 }
593
594 #[test]
595 fn test_classify_exit_code_finds_core_error_through_context_chain() {
596 // The command handlers wrap `mcp_execution_core::Error` with
597 // `.with_context(...)` before it reaches `execute_command` — the
598 // classifier must find it through that wrapping, not just at the top.
599 let err = wrap(CoreError::Timeout {
600 operation: "connect".to_string(),
601 duration_secs: 5,
602 })
603 .context("failed to connect to server 'test' - ensure the server is installed");
604 assert_eq!(classify_exit_code(&err), ExitCode::TIMEOUT);
605 }
606
607 #[tokio::test]
608 async fn test_execute_command_converts_failure_into_classified_exit_code_not_err() {
609 // Regression test for #195: a failing command must surface as
610 // `Ok(non_success_exit_code)`, never as `Err`, so `main` can always
611 // reach `std::process::exit` with the classified code instead of
612 // falling back to anyhow's default exit-code-1 handling. Asserting
613 // the exact `SERVER_ERROR` value (not just `!is_success()`) so a
614 // regression to the generic `ExitCode::ERROR` fallback is caught.
615 //
616 // Built via real clap parsing (rather than a `Commands::Introspect`
617 // literal): `ServerFlags`'s fields are private outside `cli.rs` by
618 // design, so this is the only way an external module can produce one.
619 use clap::Parser as _;
620 let cli = crate::cli::Cli::parse_from([
621 "mcp-execution-cli",
622 "introspect",
623 "nonexistent-server-for-exit-code-test",
624 ]);
625 let result = execute_command(cli.command, OutputFormat::Json).await;
626
627 let exit_code = result.expect("execute_command must not propagate Err");
628 assert_eq!(exit_code, ExitCode::SERVER_ERROR);
629 }
630
631 #[test]
632 fn test_report_and_classify_prints_and_classifies() {
633 // Regression test for #195/S2: `main` routes pre-dispatch failures
634 // (e.g. an invalid `--format` value) through this same function, not
635 // just command-handler failures via `execute_command`.
636 let err = anyhow::Error::from(CoreError::InvalidArgument(
637 "invalid output format: 'xml' (expected: json, text, or pretty)".to_string(),
638 ));
639 assert_eq!(report_and_classify(&err), ExitCode::INVALID_INPUT);
640 }
641
642 #[test]
643 fn test_report_and_classify_escapes_control_chars_in_error_chain() {
644 // Regression test for #308: a malicious/compromised MCP server can embed raw ANSI/control
645 // escape sequences in a JSON-RPC error message, which end up in the `Display` string of a
646 // `CoreError::ConnectionFailed`'s wrapped `source` — a distinct link in `err.chain()`,
647 // since `ConnectionFailed`'s own `#[error(...)]` message never interpolates `{source}` —
648 // and, by extension, in the "Caused by:" section of `sanitized_error_report`'s output.
649 // `report_and_classify` must neutralize those bytes before printing to stderr rather than
650 // passing them through verbatim. Calls `sanitized_error_report` directly — the exact
651 // helper `report_and_classify` prints — rather than recomputing the same pipeline inline,
652 // so this can't silently drift from the real code path.
653 let source: Box<dyn std::error::Error + Send + Sync> =
654 "boom\u{1b}[2J\u{1b}]0;pwned\u{7}msg".into();
655 let err = anyhow::Error::from(CoreError::ConnectionFailed {
656 server: "evil-server".to_string(),
657 source,
658 });
659
660 let report = sanitized_error_report(&err);
661 assert!(!report.contains('\u{1b}'));
662 assert!(!report.contains('\u{7}'));
663 assert_eq!(report_and_classify(&err), ExitCode::SERVER_ERROR);
664 }
665
666 #[test]
667 fn test_report_and_classify_forged_caused_by_line_does_not_survive() {
668 // Regression test for #308/S1 (impl-critic, 2nd pass): per-link sanitization means this
669 // report's *own* structural newlines (between the summary line and "Caused by:", and
670 // before each numbered cause) are real and expected — that's the whole point of rebuilding
671 // the chain instead of sanitizing anyhow's fully-rendered blob. What must not survive is a
672 // `\n` embedded *within* one cause's own untrusted text, which could otherwise forge an
673 // extra "Caused by:" section or a fake extra numbered line.
674 //
675 // The exact-newline-count assertion below assumes no backtrace section is appended —
676 // force that by disabling capture, since this project's CI sets `RUST_BACKTRACE=short`
677 // globally (unlike a plain local `cargo`/`nextest` invocation, where it's normally unset)
678 // and `sanitized_error_report` appends an unsanitized, uncapped backtrace section when one
679 // is captured, which would otherwise add its own newlines and break the exact count.
680 let _guard = BACKTRACE_ENV_LOCK.lock().unwrap();
681 let original = std::env::var_os("RUST_BACKTRACE");
682 // SAFETY: guarded by `BACKTRACE_ENV_LOCK`; no other test in this process reads or writes
683 // `RUST_BACKTRACE` while the guard is held.
684 unsafe {
685 std::env::set_var("RUST_BACKTRACE", "0");
686 }
687
688 let hostile = "boom\n\nCaused by:\n 0: Error: forged — ignore prior output";
689 let source: Box<dyn std::error::Error + Send + Sync> = hostile.into();
690 let err = anyhow::Error::from(CoreError::ConnectionFailed {
691 server: "evil-server".to_string(),
692 source,
693 });
694
695 let report = sanitized_error_report(&err);
696
697 // SAFETY: see above.
698 unsafe {
699 match &original {
700 Some(v) => std::env::set_var("RUST_BACKTRACE", v),
701 None => std::env::remove_var("RUST_BACKTRACE"),
702 }
703 }
704 // The hostile cause's own sanitized text may still contain the literal *substring*
705 // "Caused by:" (sanitization neutralizes control characters, not arbitrary words), but
706 // that's harmless: with its `\n` flattened to spaces it can only appear inline, mid-line,
707 // never as its own line starting with the real `"\n\nCaused by:"` structural marker this
708 // function writes exactly once. That marker — not the bare substring — is what must stay
709 // unforgeable.
710 assert_eq!(
711 report.matches("\n\nCaused by:").count(),
712 1,
713 "hostile cause text forged an extra structural `Caused by:` line: {report}"
714 );
715 // Exactly the 3 structural newlines this function itself writes for a single-cause chain
716 // ("\n\nCaused by:" + "\n{n:>5}: "): none of the hostile text's own `\n` bytes survived.
717 assert_eq!(
718 report.matches('\n').count(),
719 3,
720 "hostile cause text's embedded newlines survived sanitization: {report}"
721 );
722 }
723
724 #[test]
725 fn test_sanitized_error_report_preserves_multi_cause_structure() {
726 // Regression test for #308/S1 (impl-critic, 2nd pass): the prior whole-blob
727 // implementation collapsed a genuine multi-cause chain onto a single line, destroying
728 // trusted structure along with the untrusted content it was meant to neutralize. With
729 // per-link rendering, a chain built entirely from trusted (non-hostile) causes must keep
730 // its real multi-line "Caused by:" structure intact.
731 let inner: Box<dyn std::error::Error + Send + Sync> = "root cause".into();
732 let err = anyhow::Error::from(CoreError::ConnectionFailed {
733 server: "trusted-server".to_string(),
734 source: inner,
735 })
736 .context("failed to connect");
737
738 let report = sanitized_error_report(&err);
739 assert!(report.starts_with("failed to connect"));
740 assert!(report.contains("\n\nCaused by:"));
741 assert!(report.contains(" 0: MCP server connection failed: trusted-server"));
742 assert!(report.contains(" 1: root cause"));
743 }
744
745 /// Serializes tests in this module that mutate `RUST_BACKTRACE`, mirroring the
746 /// `HOME_ENV_LOCK` pattern `commands::common`/`commands::server`'s tests already use for
747 /// env-var mutation: a safety net for plain `cargo test` (which shares one process across a
748 /// crate's tests), not required by the mandated `cargo nextest run` (which isolates every
749 /// test in its own process).
750 static BACKTRACE_ENV_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(());
751
752 #[test]
753 fn test_sanitized_error_report_preserves_backtrace_when_captured() {
754 // Regression test for #308/S1 (impl-critic, 3rd pass): a backtrace anyhow captures under
755 // `RUST_BACKTRACE=1` is fully local, trusted content (source paths, function names from
756 // this binary's own stack) with nothing an external MCP server could have influenced, so
757 // it must survive `sanitized_error_report` untouched rather than being dropped or
758 // sanitized/truncated like a chain link. `RUST_BACKTRACE` must be set *before* the error
759 // is constructed — anyhow captures the backtrace (if any) at that point, not lazily at
760 // format time.
761 let _guard = BACKTRACE_ENV_LOCK.lock().unwrap();
762 let original = std::env::var_os("RUST_BACKTRACE");
763 // SAFETY: guarded by `BACKTRACE_ENV_LOCK`; no other test in this process reads or writes
764 // `RUST_BACKTRACE` while the guard is held.
765 unsafe {
766 std::env::set_var("RUST_BACKTRACE", "1");
767 }
768
769 let err = anyhow::Error::msg("boom");
770 let captured = err.backtrace().status() == std::backtrace::BacktraceStatus::Captured;
771
772 // SAFETY: see above.
773 unsafe {
774 match &original {
775 Some(v) => std::env::set_var("RUST_BACKTRACE", v),
776 None => std::env::remove_var("RUST_BACKTRACE"),
777 }
778 }
779
780 // Best-effort: some environments (e.g. certain sandboxes, targets without frame-pointer
781 // unwind info) leave backtrace capture `Disabled`/`Unsupported` even with the env var set
782 // — nothing this function controls, so only assert the positive case when it applies.
783 if captured {
784 let report = sanitized_error_report(&err);
785 assert!(
786 report.contains("tack backtrace:"),
787 "captured backtrace did not survive: {report}"
788 );
789 }
790 }
791
792 /// Leak B regression: `CoreError::ConnectionFailed`'s boxed `source` is an opaque
793 /// `Box<dyn Error + Send + Sync>` that, for an http/sse transport, is really `rmcp`'s wrapped
794 /// `reqwest::Error` — whose `Display` embeds the full request URL, query string included. This
795 /// simulates that exact shape (the security audit's captured `rmcp` output) without a live
796 /// network connection, and asserts the secret never reaches the printed report.
797 #[test]
798 fn test_sanitized_error_report_redacts_connection_failed_source_url_secret() {
799 let source: Box<dyn std::error::Error + Send + Sync> = concat!(
800 "Client error: error sending request for url ",
801 "(http://127.0.0.1:1/mcp?token=REFUSEDSECRET), when send initialize request"
802 )
803 .into();
804 let err = wrap(CoreError::ConnectionFailed {
805 server: "test".to_string(),
806 source,
807 });
808
809 let report = sanitized_error_report(&err);
810 assert!(!report.contains("REFUSEDSECRET"), "secret leaked: {report}");
811 assert!(report.contains("http://127.0.0.1:1/mcp?<redacted>"));
812 assert!(report.contains("MCP server connection failed: test"));
813 }
814
815 /// C2 regression at this leak's real entry point: an IPv6-literal authority must not defeat
816 /// redaction here either. Mirrors the critic's live repro
817 /// (`introspect --http "http://[::1]:1/mcp?token=..."`), which printed the secret in this
818 /// exact report on the unfixed version.
819 #[test]
820 fn test_sanitized_error_report_redacts_connection_failed_source_ipv6_url_secret() {
821 let source: Box<dyn std::error::Error + Send + Sync> = concat!(
822 "Client error: error sending request for url ",
823 "(http://[::1]:1/mcp?token=IPV6LEAKTEST), when send initialize request"
824 )
825 .into();
826 let err = wrap(CoreError::ConnectionFailed {
827 server: "test".to_string(),
828 source,
829 });
830
831 let report = sanitized_error_report(&err);
832 assert!(!report.contains("IPV6LEAKTEST"), "secret leaked: {report}");
833 assert!(report.contains("http://[::1]:1/mcp?<redacted>"));
834 }
835
836 #[test]
837 fn test_redacting_writer_redacts_url_secret_before_forwarding() {
838 let mut sink = Vec::new();
839 {
840 let mut writer = RedactingWriter(&mut sink);
841 let line = "ERROR rmcp::transport::worker: worker quit with fatal: Client error: error sending request for url (https://api.example.invalid/mcp?token=hunter2secret), when send initialize request\n";
842 let n = writer.write(line.as_bytes()).unwrap();
843 assert_eq!(n, line.len());
844 }
845 let written = String::from_utf8(sink).unwrap();
846 assert!(!written.contains("hunter2secret"));
847 assert!(written.contains("https://api.example.invalid/mcp?<redacted>"));
848 assert!(written.contains("worker quit with fatal"));
849 }
850
851 #[test]
852 fn test_redacting_writer_passes_through_text_without_urls() {
853 let mut sink = Vec::new();
854 RedactingWriter(&mut sink)
855 .write_all(b"INFO some ordinary log line\n")
856 .unwrap();
857 assert_eq!(sink, b"INFO some ordinary log line\n");
858 }
859
860 /// Pins the assumption `RedactingWriter`'s doc comment relies on but the two tests above
861 /// don't exercise: that `tracing-subscriber`'s fmt layer issues exactly one `write_all` per
862 /// event, so `RedactingWriter::write` always sees a whole formatted line. Wires the real
863 /// `fmt::layer()` (not a direct `RedactingWriter::write` call) through a scoped subscriber
864 /// into a shared buffer, so a future `tracing-subscriber` upgrade that splits an event across
865 /// multiple writes -- which would let a URL straddling the split leak unredacted -- fails this
866 /// test instead of failing silently in production.
867 #[test]
868 fn test_redacting_writer_wired_into_real_fmt_layer_redacts_full_event() {
869 use std::sync::{Arc, Mutex};
870
871 #[derive(Clone)]
872 struct SharedBuf(Arc<Mutex<Vec<u8>>>);
873
874 impl Write for SharedBuf {
875 fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
876 self.0.lock().unwrap().write(buf)
877 }
878
879 fn flush(&mut self) -> io::Result<()> {
880 self.0.lock().unwrap().flush()
881 }
882 }
883
884 let buf = Arc::new(Mutex::new(Vec::new()));
885 let make_writer = {
886 let buf = buf.clone();
887 move || RedactingWriter(SharedBuf(buf.clone()))
888 };
889
890 let subscriber = tracing_subscriber::registry().with(
891 tracing_subscriber::fmt::layer()
892 .with_writer(make_writer)
893 .with_ansi(false),
894 );
895
896 tracing::subscriber::with_default(subscriber, || {
897 tracing::error!(
898 "error sending request for url (https://api.example.invalid/mcp?token=hunter2secret), when send initialize request"
899 );
900 });
901
902 let written = String::from_utf8(buf.lock().unwrap().clone()).unwrap();
903 assert!(
904 !written.contains("hunter2secret"),
905 "secret leaked: {written}"
906 );
907 assert!(written.contains("https://api.example.invalid/mcp?<redacted>"));
908 assert!(written.contains("when send initialize request"));
909 }
910
911 /// JSON-mode counterpart to `test_redacting_writer_wired_into_real_fmt_layer_redacts_full_event`:
912 /// wires `RedactingWriter` through a real `fmt::layer().json()` (the `.boxed()` branch
913 /// `init_logging` takes for `LogFormat::Json`) and asserts (a) the secret never reaches the
914 /// sink, (b) the redaction marker is present, and (c) every emitted line parses as JSON via
915 /// `serde_json` -- the assertion that would have caught the C1 regression (an unescaped `"`
916 /// left behind when a redacted URL sits inside a JSON-escaped string).
917 #[test]
918 fn test_redacting_writer_wired_into_real_json_layer_emits_valid_json() {
919 use std::sync::{Arc, Mutex};
920
921 #[derive(Clone)]
922 struct SharedBuf(Arc<Mutex<Vec<u8>>>);
923
924 impl Write for SharedBuf {
925 fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
926 self.0.lock().unwrap().write(buf)
927 }
928
929 fn flush(&mut self) -> io::Result<()> {
930 self.0.lock().unwrap().flush()
931 }
932 }
933
934 let buf = Arc::new(Mutex::new(Vec::new()));
935 let make_writer = {
936 let buf = buf.clone();
937 move || RedactingWriter(SharedBuf(buf.clone()))
938 };
939
940 let subscriber = tracing_subscriber::registry().with(
941 tracing_subscriber::fmt::layer()
942 .json()
943 .with_writer(make_writer)
944 .with_ansi(false),
945 );
946
947 tracing::subscriber::with_default(subscriber, || {
948 tracing::error!(
949 "failed to connect to \"https://api.example.invalid/mcp?token=hunter2secret\" after 3 tries"
950 );
951 });
952
953 let written = String::from_utf8(buf.lock().unwrap().clone()).unwrap();
954 assert!(
955 !written.contains("hunter2secret"),
956 "secret leaked: {written}"
957 );
958 assert!(written.contains("<redacted>"));
959
960 for line in written.lines().filter(|line| !line.is_empty()) {
961 serde_json::from_str::<serde_json::Value>(line)
962 .unwrap_or_else(|e| panic!("invalid JSON line: {e}\n{line}"));
963 }
964 }
965
966 /// Shared harness for the `cap_rmcp_log_level` regression tests below: builds
967 /// `cap_rmcp_log_level(EnvFilter::new(base_filter))`, wires it into a real `fmt::layer()`
968 /// over a scoped subscriber (mirroring
969 /// `test_redacting_writer_wired_into_real_fmt_layer_redacts_full_event` above), emits one
970 /// `rmcp::transport::async_rw`-targeted `debug!` (standing in for `rmcp`'s own raw-peer-line
971 /// logging) and one `mcp_execution_cli`-targeted `debug!` (standing in for this crate's own
972 /// diagnostics), and returns `(rmcp_line_visible, own_line_visible)`. Does not mutate
973 /// `RUST_LOG` (parallel test threads share one process) -- `base_filter` plays the same role
974 /// a real `RUST_LOG` value would, but only ever reaches `EnvFilter::new` directly.
975 fn rmcp_capped_filter_captures(base_filter: &str) -> (bool, bool) {
976 use std::sync::{Arc, Mutex};
977
978 #[derive(Clone)]
979 struct SharedBuf(Arc<Mutex<Vec<u8>>>);
980
981 impl Write for SharedBuf {
982 fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
983 self.0.lock().unwrap().write(buf)
984 }
985
986 fn flush(&mut self) -> io::Result<()> {
987 self.0.lock().unwrap().flush()
988 }
989 }
990
991 let buf = Arc::new(Mutex::new(Vec::new()));
992 let make_writer = {
993 let buf = buf.clone();
994 move || SharedBuf(buf.clone())
995 };
996
997 let filter = cap_rmcp_log_level(EnvFilter::new(base_filter));
998 let subscriber = tracing_subscriber::registry().with(filter).with(
999 tracing_subscriber::fmt::layer()
1000 .with_writer(make_writer)
1001 .with_ansi(false),
1002 );
1003
1004 tracing::subscriber::with_default(subscriber, || {
1005 tracing::debug!(
1006 target: "rmcp::transport::async_rw",
1007 "raw untrusted peer line"
1008 );
1009 tracing::debug!(target: "mcp_execution_cli", "own debug event");
1010 });
1011
1012 let written = String::from_utf8(buf.lock().unwrap().clone()).unwrap();
1013 (
1014 written.contains("raw untrusted peer line"),
1015 written.contains("own debug event"),
1016 )
1017 }
1018
1019 /// Regression coverage for issue #421: `--verbose`'s `EnvFilter::new("debug")` branch (no
1020 /// `RUST_LOG` involved) must not let `rmcp`'s own `tracing` targets -- which log raw,
1021 /// unsanitized peer input at `debug` -- through, while this crate's own `debug` events must
1022 /// still pass.
1023 #[test]
1024 fn cap_rmcp_log_level_suppresses_rmcp_debug_but_keeps_own_debug() {
1025 let (rmcp_visible, own_visible) = rmcp_capped_filter_captures("debug");
1026 assert!(
1027 !rmcp_visible,
1028 "rmcp debug line was not suppressed under a global `debug` base"
1029 );
1030 assert!(
1031 own_visible,
1032 "own debug event was unexpectedly suppressed under a global `debug` base"
1033 );
1034 }
1035
1036 /// Regression coverage for critic finding S1: `tracing_subscriber`'s `Directive` ordering
1037 /// does not compare level, so `EnvFilter::add_directive` *replaces* a same-target directive
1038 /// rather than merging it. An operator's explicit `RUST_LOG=rmcp=debug` is therefore silently
1039 /// downgraded to this cap's own `rmcp=info`, not left to coexist at `debug` -- this was named
1040 /// by the original security audit as the ambiguous case to verify with a test rather than
1041 /// assume. The escape hatch for an operator who needs this is a *more specific* target (see
1042 /// the test below) -- documented in `cap_rmcp_log_level`'s doc comment and the CHANGELOG.
1043 #[test]
1044 fn cap_rmcp_log_level_replaces_a_same_target_rmcp_debug_directive() {
1045 let (rmcp_visible, _) = rmcp_capped_filter_captures("rmcp=debug");
1046 assert!(
1047 !rmcp_visible,
1048 "RUST_LOG=rmcp=debug was expected to be replaced by this cap's rmcp=info, not merged \
1049 with it -- if this now fails, `tracing_subscriber`'s directive-merge behavior \
1050 changed and `cap_rmcp_log_level`'s doc comment needs updating"
1051 );
1052 }
1053
1054 /// Counterpart to the test above: a target *more specific* than `rmcp` (e.g.
1055 /// `RUST_LOG=rmcp::transport=debug`) is not overwritten by this cap's `rmcp=info` --
1056 /// `tracing_subscriber` orders directives by target specificity, and a longer target wins.
1057 /// This is the documented escape hatch for an operator who deliberately wants rmcp transport
1058 /// debug output.
1059 #[test]
1060 fn cap_rmcp_log_level_does_not_override_a_more_specific_rmcp_target() {
1061 let (rmcp_visible, _) = rmcp_capped_filter_captures("rmcp::transport=debug");
1062 assert!(
1063 rmcp_visible,
1064 "RUST_LOG=rmcp::transport=debug should still surface rmcp debug output -- a more \
1065 specific target must win over this cap's rmcp=info"
1066 );
1067 }
1068
1069 /// Serializes tests in this module that mutate `MCP_EXECUTION_LOG_FORMAT`, mirroring
1070 /// `BACKTRACE_ENV_LOCK` above and `mcp-execution-server`'s own `LOG_FORMAT_ENV_LOCK`: a
1071 /// safety net for plain `cargo test` (which shares one process across a crate's tests), not
1072 /// required by the mandated `cargo nextest run` (which isolates every test in its own
1073 /// process).
1074 static LOG_FORMAT_ENV_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(());
1075
1076 /// Proves `resolve_log_format` -- the function `init_logging` actually calls -- reads the
1077 /// real `MCP_EXECUTION_LOG_FORMAT` environment variable itself, not just that the pure
1078 /// `LogFormat::resolve` it delegates to works given a hand-built `Option<&str>`. A version of
1079 /// `resolve_log_format` that dropped the `std::env::var` call entirely would still pass every
1080 /// other test in this module.
1081 #[test]
1082 fn resolve_log_format_reads_env_var_when_flag_unset() {
1083 let _guard = LOG_FORMAT_ENV_LOCK.lock().unwrap();
1084 let original = std::env::var_os(LOG_FORMAT_ENV_VAR);
1085 // SAFETY: guarded by `LOG_FORMAT_ENV_LOCK`; no other test in this process reads or
1086 // writes `MCP_EXECUTION_LOG_FORMAT` while the guard is held.
1087 unsafe {
1088 std::env::set_var(LOG_FORMAT_ENV_VAR, "json");
1089 }
1090
1091 let format = resolve_log_format(None);
1092
1093 // SAFETY: see above.
1094 unsafe {
1095 match &original {
1096 Some(v) => std::env::set_var(LOG_FORMAT_ENV_VAR, v),
1097 None => std::env::remove_var(LOG_FORMAT_ENV_VAR),
1098 }
1099 }
1100
1101 assert_eq!(format, LogFormat::Json);
1102 }
1103
1104 #[test]
1105 fn resolve_log_format_flag_wins_over_bad_env() {
1106 let _guard = LOG_FORMAT_ENV_LOCK.lock().unwrap();
1107 let original = std::env::var_os(LOG_FORMAT_ENV_VAR);
1108 // SAFETY: guarded by `LOG_FORMAT_ENV_LOCK`; no other test in this process reads or
1109 // writes `MCP_EXECUTION_LOG_FORMAT` while the guard is held.
1110 unsafe {
1111 std::env::set_var(LOG_FORMAT_ENV_VAR, "xml");
1112 }
1113
1114 let format = resolve_log_format(Some(LogFormat::Json));
1115 let is_invalid = log_format_env_is_invalid(Some(LogFormat::Json));
1116
1117 // SAFETY: see above.
1118 unsafe {
1119 match &original {
1120 Some(v) => std::env::set_var(LOG_FORMAT_ENV_VAR, v),
1121 None => std::env::remove_var(LOG_FORMAT_ENV_VAR),
1122 }
1123 }
1124
1125 assert_eq!(format, LogFormat::Json);
1126 assert!(
1127 !is_invalid,
1128 "a bad env value must not be reported once the flag has already decided"
1129 );
1130 }
1131
1132 #[test]
1133 fn resolve_log_format_bad_env_value_falls_back_to_text() {
1134 let _guard = LOG_FORMAT_ENV_LOCK.lock().unwrap();
1135 let original = std::env::var_os(LOG_FORMAT_ENV_VAR);
1136 // SAFETY: guarded by `LOG_FORMAT_ENV_LOCK`; no other test in this process reads or
1137 // writes `MCP_EXECUTION_LOG_FORMAT` while the guard is held.
1138 unsafe {
1139 std::env::set_var(LOG_FORMAT_ENV_VAR, "xml");
1140 }
1141
1142 let format = resolve_log_format(None);
1143
1144 // SAFETY: see above.
1145 unsafe {
1146 match &original {
1147 Some(v) => std::env::set_var(LOG_FORMAT_ENV_VAR, v),
1148 None => std::env::remove_var(LOG_FORMAT_ENV_VAR),
1149 }
1150 }
1151
1152 assert_eq!(format, LogFormat::Text);
1153 }
1154
1155 /// Proves `log_format_env_is_invalid` -- the function that actually gates `init_logging`'s
1156 /// warning -- reads the real environment variable itself, not just that
1157 /// `LogFormat::is_invalid_env_value` works given a hand-built `&str`.
1158 #[test]
1159 fn log_format_env_is_invalid_true_for_bad_value_when_flag_unset() {
1160 let _guard = LOG_FORMAT_ENV_LOCK.lock().unwrap();
1161 let original = std::env::var_os(LOG_FORMAT_ENV_VAR);
1162 // SAFETY: guarded by `LOG_FORMAT_ENV_LOCK`; no other test in this process reads or
1163 // writes `MCP_EXECUTION_LOG_FORMAT` while the guard is held.
1164 unsafe {
1165 std::env::set_var(LOG_FORMAT_ENV_VAR, "xml");
1166 }
1167
1168 let is_invalid = log_format_env_is_invalid(None);
1169
1170 // SAFETY: see above.
1171 unsafe {
1172 match &original {
1173 Some(v) => std::env::set_var(LOG_FORMAT_ENV_VAR, v),
1174 None => std::env::remove_var(LOG_FORMAT_ENV_VAR),
1175 }
1176 }
1177
1178 assert!(is_invalid);
1179 }
1180
1181 #[test]
1182 fn log_format_env_is_invalid_false_for_valid_value() {
1183 let _guard = LOG_FORMAT_ENV_LOCK.lock().unwrap();
1184 let original = std::env::var_os(LOG_FORMAT_ENV_VAR);
1185 // SAFETY: guarded by `LOG_FORMAT_ENV_LOCK`; no other test in this process reads or
1186 // writes `MCP_EXECUTION_LOG_FORMAT` while the guard is held.
1187 unsafe {
1188 std::env::set_var(LOG_FORMAT_ENV_VAR, "json");
1189 }
1190
1191 let is_invalid = log_format_env_is_invalid(None);
1192
1193 // SAFETY: see above.
1194 unsafe {
1195 match &original {
1196 Some(v) => std::env::set_var(LOG_FORMAT_ENV_VAR, v),
1197 None => std::env::remove_var(LOG_FORMAT_ENV_VAR),
1198 }
1199 }
1200
1201 assert!(!is_invalid);
1202 }
1203
1204 #[test]
1205 fn log_format_env_is_invalid_false_when_unset() {
1206 let _guard = LOG_FORMAT_ENV_LOCK.lock().unwrap();
1207 let original = std::env::var_os(LOG_FORMAT_ENV_VAR);
1208 // SAFETY: guarded by `LOG_FORMAT_ENV_LOCK`; no other test in this process reads or
1209 // writes `MCP_EXECUTION_LOG_FORMAT` while the guard is held.
1210 unsafe {
1211 std::env::remove_var(LOG_FORMAT_ENV_VAR);
1212 }
1213
1214 let is_invalid = log_format_env_is_invalid(None);
1215
1216 // SAFETY: see above.
1217 unsafe {
1218 if let Some(v) = &original {
1219 std::env::set_var(LOG_FORMAT_ENV_VAR, v);
1220 }
1221 }
1222
1223 assert!(!is_invalid);
1224 }
1225}