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]| {