From c6e83fc034b0d52f892069d2afc15c0cd500d4ab Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Sun, 4 Oct 2026 19:47:35 +1100 Subject: [PATCH] feat(run): CK_LOG=debug prints one stderr line per call A fresh hit and a stored miss printed nothing, so a caller could not tell whether ck served stored output or ran the command. With CK_LOG=debug, every ck run call that reaches an outcome prints one `ck: debug:` line naming it, with the backend, the program name, an entry id, the stored output's age, the exit code and the elapsed time. An env var rather than a flag: ck runs inside $(...) in startup files and scripts, and one export reaches every call site, nested calls included. Not RUST_LOG, which the wrapped command also sees, and not CACHEKIT_*, which is stripped from it. Any other value warns once and is ignored, so a typo never stops the command. The line never carries the command's arguments, its output or either key. The entry id is the first 12 hex characters of the keyed hash that names the entry's lock file, so it cannot be checked against a guessed command without the master key. No new dependency. --- README.md | 33 ++++++++++ src/cli.rs | 4 +- src/lib.rs | 22 +++++++ src/run.rs | 110 ++++++++++++++++++++++++-------- tests/common/mod.rs | 7 +- tests/readme.rs | 1 + tests/run.rs | 151 ++++++++++++++++++++++++++++++++++++++++++++ tests/saas.rs | 105 ++++++++++++++++++++++++++++++ 8 files changed, 403 insertions(+), 30 deletions(-) diff --git a/README.md b/README.md index 964c138..0ad384e 100644 --- a/README.md +++ b/README.md @@ -272,6 +272,39 @@ other failure. A signal ck inherits as ignored, as under `nohup`, stays ignored: ck neither forwards it nor stops for it, and the command inherits it ignored too. +### Seeing what ck did + +A hit and a stored miss print nothing, so you cannot tell from the output +whether ck served the stored output or ran the command. Set `CK_LOG=debug` and +every `ck run` call prints one more line on stderr saying what it did. Export +it once, and the calls in your shell startup files and scripts report too: + +```console +$ CK_LOG=debug ck run --ttl 12h -- op item get api --fields token --reveal +ck: debug: served fresh: backend=file program="op" entry=ab6888403fb1 age=2873104ms exit=0 elapsed=1ms +``` + +The line starts with what happened: `served fresh`, `served stale`, +`ran and stored`, `ran, not stored` (the command failed, or its output was too +large or could not be written), `refreshed and stored` or `refreshed, not stored` +(`--refresh`), `suppressed` (backing off after a failure), `ran uncached` (the +cache was unavailable), or `could not start the command`. Then come the backend, +the program name, the entry id, the stored output's age when ck read one, ck's +exit code and how long the call took. Any warning ck prints for the call comes +first and is unchanged. An interrupted call may print no debug line. + +The line names only the program, never its arguments: they can hold a secret, +as can the output, which is never logged either, and neither key is. The entry +id is the first 12 characters of the entry's lock file name in +`~/.cache/ck/locks/`. It comes from the keyed hash, so it cannot be matched +against a guessed command without the master key. + +`CK_LOG` takes only `debug`. Any other non-empty value prints one warning and +is otherwise ignored, so a typo never stops the command. ck reads `CK_LOG` +rather than `RUST_LOG` because the wrapped command sees every variable ck does +except `CACHEKIT_*`, so `RUST_LOG` would switch on a Rust program's own logs +too. To keep the lines, redirect stderr: `2>>ck.log`. + ### Platforms Linux and macOS. The cache directory must be on a local filesystem: on NFS or diff --git a/src/cli.rs b/src/cli.rs index 30c6425..8ee8a57 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -24,7 +24,9 @@ stdin, never ck's: pass input in arguments, files or --scope. --scope S an extra string folded into the cache key --refresh run the command now, ignoring any stored output -D is a whole number followed by s, m, h or d, such as 90s, 15m, 12h or 7d."; +D is a whole number followed by s, m, h or d, such as 90s, 15m, 12h or 7d. + +Set CK_LOG=debug to print one line per call on stderr saying what ck did."; #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub enum BackendKind { diff --git a/src/lib.rs b/src/lib.rs index b5c7dad..68ec6a1 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -60,6 +60,28 @@ pub(crate) fn warn(message: &str) { let _ = writeln!(std::io::stderr(), "ck: {message}"); } +/// Whether `CK_LOG=debug` asks for one `ck: debug:` line per call. An env var +/// rather than a flag, so one export reaches every call site, nested ones +/// included. Not `RUST_LOG`, which the wrapped command also reads, and not +/// `CACHEKIT_*`, which is stripped from it. Any other non-empty value warns and +/// is otherwise ignored: a typo exported from a shell startup file must not +/// break every cached command. +pub(crate) fn debug_enabled() -> bool { + match std::env::var_os("CK_LOG") { + Some(v) if v == "debug" => true, + Some(v) if !v.is_empty() => { + warn("ignoring CK_LOG: the only accepted value is debug"); + false + } + _ => false, + } +} + +/// One debug line on stderr, dropped on a failed write as [`warn`] is. +pub(crate) fn debug(message: &str) { + let _ = writeln!(std::io::stderr(), "ck: debug: {message}"); +} + /// Write to stdout, and say whether it worked. A reader that has gone away /// (EPIPE) is normal in a pipeline and stays silent; any other failure is /// reported. diff --git a/src/run.rs b/src/run.rs index a5e5713..cd371f5 100644 --- a/src/run.rs +++ b/src/run.rs @@ -9,7 +9,7 @@ use std::ops::ControlFlow; use std::os::fd::OwnedFd; use std::os::unix::fs::DirBuilderExt; use std::path::{Path, PathBuf}; -use std::time::Duration; +use std::time::{Duration, Instant}; use rustix::fs::{FlockOperation, Mode, OFlags}; @@ -19,9 +19,11 @@ use crate::entry::{human, now_ms, Envelope, Freshness, Marker}; use crate::keys::{self, KeyHasher}; use crate::saas::{self, Connect}; use crate::store::{ReadError, Store}; -use crate::{emit, warn, Fatal}; +use crate::{debug, emit, warn, Fatal}; pub fn run(args: &RunArgs, connect: &Connect) -> Result { + let started = Instant::now(); + let debug = crate::debug_enabled(); // A saas call without its credentials exits 125 before anything runs. let credentials = match args.backend { BackendKind::File => None, @@ -55,6 +57,8 @@ pub fn run(args: &RunArgs, connect: &Connect) -> Result { lock_path: cache_dir.join("locks").join(keys::key_hash(&key)), key, store, + debug, + started, }; if args.refresh { return call.refresh(); @@ -68,6 +72,9 @@ struct Call<'a> { key: String, marker_key: String, lock_path: PathBuf, + /// `CK_LOG=debug`: each outcome reports itself through [`Call::done`]. + debug: bool, + started: Instant, } /// A stored run that may be replayed because the command failed. @@ -83,9 +90,9 @@ impl Call<'_> { Err(e) => return self.read_failed(e, &Supervisor::install()?), }; let stale = match self.fresh_or_stale(value) { - ControlFlow::Break(fresh) => { + ControlFlow::Break((fresh, age_ms)) => { emit(&fresh); - return Ok(0); + return Ok(self.done("served fresh", Some(age_ms), 0)); } ControlFlow::Continue(stale) => stale, }; @@ -120,7 +127,7 @@ impl Call<'_> { "cannot take the fill lock {}: {e}; running uncached", self.lock_path.display() )); - return Ok(run_uncached(&supervisor, &self.args.command)); + return Ok(self.run_uncached(&supervisor)); } }; @@ -132,12 +139,12 @@ impl Call<'_> { Err(e) => return self.read_failed(e, &supervisor), }; let stale = match self.fresh_or_stale(value) { - ControlFlow::Break(fresh) => { + ControlFlow::Break((fresh, age_ms)) => { if let Some(code) = supervisor.interrupted() { return Ok(code); } emit(&fresh); - return Ok(0); + return Ok(self.done("served fresh", Some(age_ms), 0)); } ControlFlow::Continue(stale) => stale, }; @@ -158,7 +165,7 @@ impl Call<'_> { m.exit, human(m.retry_at_ms - now) )); - return Ok(m.exit); + return Ok(self.done("suppressed", None, m.exit)); } let code = self.record(&supervisor, stale, marker); @@ -180,6 +187,13 @@ impl Call<'_> { /// Run the command and record the outcome: the value on success, the /// bumped marker on failure. `marker` is the current one, if any. fn record(&self, supervisor: &Supervisor, stale: Option, marker: Option) -> i32 { + let age_ms = stale.as_ref().map(|s| s.age_ms); + let ran = if self.args.refresh { + "refreshed" + } else { + "ran" + }; + let not_stored = format!("{ran}, not stored"); let (code, stdout) = match supervisor.run(&self.args.command, Some(self.store.max_output())) { Ran::SpawnFailed { code } => { @@ -188,7 +202,7 @@ impl Call<'_> { // turned a received signal into `Interrupted`. return match stale { Some(stale) => self.serve_stale(&stale, None, None, None), - None => code, + None => self.done(NOT_STARTED, None, code), }; } Ran::Interrupted { signal } => return 128 + signal, @@ -199,7 +213,7 @@ impl Call<'_> { } (_, stdout) => { stdout.emit_captured(); - 126 + self.done(¬_stored, age_ms, 126) } }; } @@ -223,6 +237,10 @@ impl Call<'_> { envelope.as_deref().map(|e| (e, ttl)), &self.marker_key, ); + let outcome = match (&envelope, &stored) { + (Some(_), Ok(())) => format!("{ran} and stored"), + _ => not_stored, + }; // One warning: a failed write and a failed clear usually share a cause. match (stored, cleared) { (Err(e), Err(_)) => warn(&format!( @@ -235,13 +253,13 @@ impl Call<'_> { (Ok(()), Err(e)) => warn(&format!("cannot clear the recorded failure: {e}")), (Ok(()), Ok(())) => {} } - return 0; + return self.done(&outcome, age_ms, 0); } if matches!(stdout, Stdout::OutputLost) { // ck's stdout failed mid-stream and the command most likely died // of SIGPIPE: no evidence about the origin, so no marker. - return code; + return self.done(¬_stored, age_ms, code); } let next = Marker::bumped(marker.as_ref(), code, now); if let Err(e) = self @@ -256,19 +274,26 @@ impl Call<'_> { } (stdout, _) => { stdout.emit_captured(); - code + self.done(¬_stored, age_ms, code) } } } - /// Break with a fresh value to print, or continue with the stale run (if - /// `--stale` still allows one) for the caller to fall back on. - fn fresh_or_stale(&self, value: Option) -> ControlFlow, Option> { + /// Break with a fresh value to print and its age, or continue with the + /// stale run (if `--stale` still allows one) for the caller to fall back on. + fn fresh_or_stale( + &self, + value: Option, + ) -> ControlFlow<(Vec, u64), Option> { let Some(envelope) = value else { return ControlFlow::Continue(None); }; - match envelope.freshness(now_ms(), self.args.ttl_secs, self.args.stale_secs) { - Freshness::Fresh => ControlFlow::Break(envelope.stdout), + let now = now_ms(); + match envelope.freshness(now, self.args.ttl_secs, self.args.stale_secs) { + Freshness::Fresh => { + let age_ms = now.saturating_sub(envelope.stored_at_ms); + ControlFlow::Break((envelope.stdout, age_ms)) + } Freshness::Stale { age_ms } => ControlFlow::Continue(Some(Stale { envelope, age_ms })), Freshness::Expired => ControlFlow::Continue(None), } @@ -302,7 +327,7 @@ impl Call<'_> { } warn(&line); emit(&stale.envelope.stdout); - 0 + self.done("served stale", Some(stale.age_ms), 0) } /// Any backend error before the run disables caching for this call, never @@ -312,20 +337,53 @@ impl Call<'_> { ReadError::Local(fatal) => Err(fatal), ReadError::Backend(e) => { warn(&format!("the cache is unavailable ({e}); running uncached")); - Ok(run_uncached(supervisor, &self.args.command)) + Ok(self.run_uncached(supervisor)) } } } -} -fn run_uncached(supervisor: &Supervisor, argv: &[std::ffi::OsString]) -> i32 { - match supervisor.run(argv, None) { - Ran::SpawnFailed { code } | Ran::Exited { code, .. } => code, - Ran::StatusUnknown { .. } => 126, - Ran::Interrupted { signal } => 128 + signal, + fn run_uncached(&self, supervisor: &Supervisor) -> i32 { + match supervisor.run(&self.args.command, None) { + Ran::SpawnFailed { code } => self.done(NOT_STARTED, None, code), + Ran::Exited { code, .. } => self.done("ran uncached", None, code), + Ran::StatusUnknown { .. } => self.done("ran uncached", None, 126), + Ran::Interrupted { signal } => 128 + signal, + } + } + + /// Return `code`, first saying on stderr what the call did when + /// `CK_LOG=debug`. Every outcome passes through here exactly once; an + /// interrupted run or a ck error does not. + /// + /// The line names only the program: its arguments, its output and both + /// keys can carry secrets. The entry id is the start of the keyed hash + /// that names the fill lock, so a guessed command line cannot be checked + /// against it without the master key. + fn done(&self, outcome: &str, age_ms: Option, code: i32) -> i32 { + if !self.debug { + return code; + } + let backend = match self.args.backend { + BackendKind::File => "file", + BackendKind::Saas => "saas", + }; + // Debug-quoted, so control characters cannot drive the terminal. + let program = self.args.command[0].to_string_lossy(); + let entry = &keys::key_hash(&self.key)[..ENTRY_ID_LEN]; + let age = age_ms.map_or(String::new(), |ms| format!(" age={ms}ms")); + debug(&format!( + "{outcome}: backend={backend} program={program:?} entry={entry}{age} exit={code} elapsed={}ms", + self.started.elapsed().as_millis() + )); + code } } +/// Hex characters of the key hash that identify an entry in a debug line. +const ENTRY_ID_LEN: usize = 12; + +const NOT_STARTED: &str = "could not start the command"; + /// Take the fill lock, an exclusive `flock` on the key's lockfile. When it is /// contended, wait for it only if `wait`; otherwise return `None`. flock is /// released when its holder exits or dies, so no lock goes stale. diff --git a/tests/common/mod.rs b/tests/common/mod.rs index cf96361..099f561 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -81,8 +81,8 @@ impl Sandbox { } /// `ck ` in this sandbox, in its own process group, with stdin on - /// /dev/null and no CacheKit variables inherited from the machine running - /// the tests. + /// /dev/null and no CacheKit variables or `CK_LOG` inherited from the + /// machine running the tests. pub fn ck(&self, args: &[&str]) -> Command { self.command(Path::new(BIN), args) } @@ -103,7 +103,8 @@ impl Sandbox { let path = std::env::var_os("PATH").unwrap_or_default(); let mut paths = vec![self.bin()]; paths.extend(std::env::split_paths(&path)); - cmd.env("HOME", self.home()) + cmd.env_remove("CK_LOG") + .env("HOME", self.home()) .env("PATH", std::env::join_paths(paths).unwrap()) .stdin(Stdio::null()) .stdout(Stdio::piped()) diff --git a/tests/readme.rs b/tests/readme.rs index 06866e3..e43fae3 100644 --- a/tests/readme.rs +++ b/tests/readme.rs @@ -43,6 +43,7 @@ fn readme_examples_run() { let out = Command::new("sh") .args(["-euc", &example]) .env("HOME", s.home()) + .env_remove("CK_LOG") .env("PATH", path) // A pipe, as in CI, not /dev/null: the examples carry no redirect. .stdin(Stdio::piped()) diff --git a/tests/run.rs b/tests/run.rs index 8bf3f1f..a485d02 100644 --- a/tests/run.rs +++ b/tests/run.rs @@ -1094,3 +1094,154 @@ fn a_signal_while_serving_stale_output_stops_ck() { let _ = filler.kill(); let _ = filler.wait(); } + +// ── CK_LOG ─────────────────────────────────────────────────────────────────── + +/// `ck run -- ` with `CK_LOG=debug`. +fn logged(s: &Sandbox, flags: &[&str], command: &[&str]) -> std::process::Output { + let mut args = vec!["run"]; + args.extend_from_slice(flags); + args.push("--"); + args.extend_from_slice(command); + s.ck(&args).env("CK_LOG", "debug").output().unwrap() +} + +/// The call's one debug line, checked to name `outcome`. +fn debug_line(out: &std::process::Output, outcome: &str) -> String { + let err = stderr(out); + let lines: Vec<&str> = err + .lines() + .filter(|l| l.starts_with("ck: debug: ")) + .collect(); + assert_eq!(lines.len(), 1, "{err}"); + let prefix = format!("ck: debug: {outcome}: "); + assert!(lines[0].starts_with(&prefix), "want {outcome:?}: {err}"); + lines[0].to_owned() +} + +/// The value of `name=` in a debug line. +fn field<'a>(line: &'a str, name: &str) -> Option<&'a str> { + line.split(' ') + .find_map(|f| f.strip_prefix(name)?.strip_prefix('=')) +} + +#[test] +fn ck_log_debug_reports_each_outcome() { + let s = Sandbox::new(); + let flags = ["--ttl", "1s", "--stale", "1h"]; + let line = debug_line(&logged(&s, &flags, &["origin"]), "ran and stored"); + assert_eq!(field(&line, "age"), None, "{line}"); + assert_eq!(field(&line, "exit"), Some("0"), "{line}"); + let out = logged(&s, &flags, &["origin"]); + assert_eq!(stderr(&out).lines().count(), 1, "{}", stderr(&out)); + debug_line(&out, "served fresh"); + + sleep(PAST_TTL); + s.set("exit", "1"); + let out = logged(&s, &flags, &["origin"]); + assert_eq!((code(&out), stdout(&out)), (0, "hello\n".into())); + // The existing warning, then the debug line. + let err = stderr(&out); + assert!( + err.starts_with("ck: the command exited 1; serving"), + "{err}" + ); + assert_eq!(err.lines().count(), 2, "{err}"); + let line = debug_line(&out, "served stale"); + assert!(field(&line, "age").is_some(), "{line}"); + + // Another entry, with nothing stored to fall back on. + let other = ["--scope", "other"]; + let line = debug_line(&logged(&s, &other, &["origin"]), "ran, not stored"); + assert_eq!(field(&line, "exit"), Some("1"), "{line}"); + let line = debug_line(&logged(&s, &other, &["origin"]), "suppressed"); + assert_eq!(field(&line, "exit"), Some("1"), "{line}"); + s.set("exit", "0"); + let refresh = ["--scope", "other", "--refresh"]; + debug_line(&logged(&s, &refresh, &["origin"]), "refreshed and stored"); + s.set("exit", "2"); + debug_line(&logged(&s, &refresh, &["origin"]), "refreshed, not stored"); + + let out = logged(&s, &[], &["ck-test-not-installed"]); + assert_eq!(code(&out), 127); + let line = debug_line(&out, "could not start the command"); + assert_eq!(field(&line, "exit"), Some("127"), "{line}"); +} + +#[test] +fn a_ck_log_line_names_the_entry_by_its_lock_file() { + let s = Sandbox::new(); + logged(&s, &["--ttl", "1h"], &["origin", "--flag", "value"]); + let line = debug_line( + &logged(&s, &["--ttl", "1h"], &["origin", "--flag", "value"]), + "served fresh", + ); + assert_eq!(field(&line, "backend"), Some("file"), "{line}"); + assert_eq!(field(&line, "program"), Some("\"origin\""), "{line}"); + assert!( + !line.contains("--flag") && !line.contains("value"), + "{line}" + ); + let age: u64 = field(&line, "age") + .unwrap() + .strip_suffix("ms") + .unwrap() + .parse() + .unwrap(); + assert!(age < 60_000, "{line}"); + let elapsed = field(&line, "elapsed").unwrap(); + assert!( + elapsed.strip_suffix("ms").unwrap().parse::().is_ok(), + "{line}" + ); + + let entry = field(&line, "entry").unwrap(); + assert_eq!(entry.len(), 12, "{line}"); + assert!(entry.bytes().all(|b| b.is_ascii_hexdigit()), "{line}"); + let locks = entries(&s.home().join(".cache/ck/locks")); + assert_eq!(locks.len(), 1, "{locks:?}"); + assert!(locks[0].starts_with(entry), "{entry} is not {locks:?}"); +} + +#[test] +fn ck_log_leaves_a_hits_stdout_alone() { + let s = Sandbox::new(); + s.set("out", "a\tb\n\nno trailing newline"); + assert_eq!(code(&s.run(&["--ttl", "1h"])), 0); + let plain = s.run(&["--ttl", "1h"]); + let logged = logged(&s, &["--ttl", "1h"], &["origin"]); + assert_eq!(plain.stdout, logged.stdout); + assert_eq!((code(&plain), code(&logged)), (0, 0)); + assert_eq!(s.runs(), 1); +} + +#[test] +fn a_bad_ck_log_warns_and_runs_the_command() { + for value in ["DEBUG", "1", "trace", "debug ", "verbose"] { + let s = Sandbox::new(); + s.set("exit", "3"); + let out = s + .ck(&["run", "--", "origin"]) + .env("CK_LOG", value) + .output() + .unwrap(); + assert_eq!((code(&out), stdout(&out)), (3, "hello\n".into()), "{value}"); + assert_eq!( + stderr(&out), + "ck: ignoring CK_LOG: the only accepted value is debug\n", + "{value}" + ); + assert_eq!(s.runs(), 1); + } + + let s = Sandbox::new(); + let out = s + .ck(&["run", "--", "origin"]) + .env("CK_LOG", "") + .output() + .unwrap(); + assert_eq!( + (code(&out), stdout(&out), stderr(&out)), + (0, "hello\n".into(), String::new()) + ); +} diff --git a/tests/saas.rs b/tests/saas.rs index b15799d..eda0576 100644 --- a/tests/saas.rs +++ b/tests/saas.rs @@ -85,6 +85,11 @@ const CASES: &[(&str, fn())] = &[ an_api_key_alone_never_selects_saas, ), ("readme_saas_examples_run", readme_saas_examples_run), + ( + "ck_log_reports_a_fault_and_the_size_cap", + ck_log_reports_a_fault_and_the_size_cap, + ), + ("ck_log_prints_no_secret", ck_log_prints_no_secret), ( "the_harness_reads_libtest_options", the_harness_reads_libtest_options, @@ -783,6 +788,106 @@ fn a_contended_lock_serves_stale_in_one_line() { assert_eq!(stdout(&filler.wait_with_output().unwrap()), "new\n"); } +/// The call's one `ck: debug:` line, checked to name `outcome` on saas. +fn debug_line(out: &Output, outcome: &str) -> String { + let debug: Vec = lines(out) + .into_iter() + .filter(|l| l.starts_with("ck: debug: ")) + .collect(); + assert_eq!(debug.len(), 1, "{}", stderr(out)); + let prefix = format!("ck: debug: {outcome}: backend=saas "); + assert!(debug[0].starts_with(&prefix), "want {outcome:?}: {debug:?}"); + debug[0].clone() +} + +fn ck_log_reports_a_fault_and_the_size_cap() { + use std::os::unix::fs::PermissionsExt; + + let service = Service::new(); + let host = Sandbox::new(); + let out = service + .ck(&host, &[]) + .env("CK_LOG", "debug") + .env(FAULT, "get=503") + .output() + .unwrap(); + assert_eq!(code(&out), 0); + assert!(stderr(&out).starts_with("ck: the cache is unavailable")); + debug_line(&out, "ran uncached"); + + let origin = host.bin().join("origin"); + fs::write( + &origin, + "#!/bin/sh\nhead -c 1052672 /dev/zero | tr '\\0' x\n", + ) + .unwrap(); + fs::set_permissions(&origin, fs::Permissions::from_mode(0o755)).unwrap(); + let out = service + .ck(&host, &[]) + .env("CK_LOG", "debug") + .output() + .unwrap(); + assert_eq!((code(&out), out.stdout.len()), (0, 1_052_672)); + assert!(stderr(&out).contains("passed 1 MiB"), "{}", stderr(&out)); + debug_line(&out, "ran, not stored"); +} + +/// No path's debug line carries the command's arguments, its output, or +/// either key. Each sentinel would show up on stderr if one did. +fn ck_log_prints_no_secret() { + const ARG: &str = "sentinel-argument-4f1c"; + const OUT: &str = "sentinel-output-4f1c"; + const API_KEY: &str = "ck_sdk_sentinel-api-key-4f1c"; + let master_key = "4f1c".repeat(16); + + let service = Service::new(); + let host = Sandbox::new(); + host.set("out", &format!("{OUT}\n")); + let call = |fault: Option<&str>| { + let args = [ + "run", + "--backend", + "saas", + "--ttl", + "1s", + "--stale", + "1h", + "--", + "origin", + "--token", + ARG, + ]; + let mut cmd = service.bare(&host, &args); + cmd.env("CACHEKIT_API_KEY", API_KEY) + .env("CACHEKIT_MASTER_KEY", &master_key) + .env("CK_LOG", "debug"); + if let Some(fault) = fault { + cmd.env(FAULT, fault); + } + cmd.output().unwrap() + }; + let check = |out: &Output, outcome: &str| { + assert_eq!(stdout(out), format!("{OUT}\n")); + for secret in [ARG, OUT, API_KEY, master_key.as_str()] { + assert!( + !stderr(out).contains(secret), + "{secret:?} on stderr: {}", + stderr(out) + ); + } + let line = debug_line(out, outcome); + assert!(line.contains("program=\"origin\""), "{line}"); + }; + + check(&call(None), "ran and stored"); + check(&call(None), "served fresh"); + std::thread::sleep(Duration::from_millis(1_100)); + host.set("exit", "1"); + check(&call(None), "served stale"); + host.set("exit", "0"); + check(&call(Some("get=401")), "ran uncached"); +} + fn the_harness_reads_libtest_options() { let all: Vec<&str> = CASES.iter().map(|(name, _)| *name).collect(); let selected = |args: &[&str]| {