CyberCoveLLC/Triple-C
1
0
Fork 0
Code Issues 1 Pull Requests Actions Packages Projects Releases 35 Wiki Activity

Make the scrub work off /usr/bin, and stop a log level deciding whether it runs

Browse Source 
H3 — the pre-commit scrub was a silent no-op on any base image whose coreutils
are not under /usr/bin. Hardening against a PATH-planted `stat` shim by naming
every tool absolutely bought nothing the `PATH` reset on the first line had not
already bought — the shim lives in the persisted home volume, and uid 1000
cannot write /usr/bin or /bin — and it cost the whole feature on Alpine, which
Settings -> Docker -> Custom accepts. Measured on one seeded tree in a real
container: the absolute-path script printed `###TRIPLE-C-SCRUBBED 0` and left
every planted file in place; the PATH-resolved one reclaims 77824 bytes. The
default image is unchanged at 521038.

It was silent three times over, and all three are fixed:

* The script now probes for all six things it needs (`command -v` for the five
  tools, plus the root device id reading back as a number) and, if any is
  missing, prints `###TRIPLE-C-SCRUB-UNAVAILABLE <what>` and no total at all.
* `scrub_writable_layer` reads that marker first and returns a new
  `ScrubOutcome::Unavailable`, warning with what the image is missing; a
  genuine `Reclaimed(0)` now leaves a debug line rather than nothing.
* `commit_log_suffix` renders `Reclaimed(0)` as "ran and found nothing to drop"
  rather than "0.00 MB dropped", which is what a scrub that could not run used
  to look like.

Verified in real containers: the mount-at-the-match defence still holds with a
home-volume `stat` shim first on PATH (the volume survives; deleting the PATH
reset from the same script empties it, so the harness can tell the difference).

H2 — the pre-migration scrub had been folded into `log::info!`'s argument list
to satisfy `#[must_use]`. `log::info!` expands to `if Info <= max_level() { … }`,
so the awaited scrub lived inside the level check, and `logging::init`
tolerates `dispatch.apply()` failing — which returns before `set_max_level` and
leaves the process at `Off`. In that state the scrub never ran and the layer
was committed into the longest-lived snapshot the app takes. The outcome is
bound first now, `logging::init` restores the level on failure and says so on
stderr, and a test scans all four files for an `.await` inside any `log::*!`
argument list.

Also:

* `reconcile_migration` deferred a held project instead of dropping it. Its
  only caller fires once per "Docker became available", so a project held at
  that instant was never revisited for the session — phase un-normalised, no
  resume or rollback offered, pin left `Claimed`. It now waits for the holder
  to let go (20s x 90, one waiter per project) and reconciles then.
* The scrub's byte total counts what a partly failed `rm` removed, by
  re-measuring rather than dropping the whole subtree on a non-zero exit —
  which was exactly the `--one-file-system` case.
* The scrub exec blanks `LD_PRELOAD`, `LD_AUDIT` and `LD_LIBRARY_PATH`.
  `LD_PRELOAD` is in none of the reserved env families, so a project's custom
  env var reached a root exec and injected code into every tool the scrub runs,
  `PATH` reset or not. Verified against Engine 29.7 that `docker exec -e` wins.
* The device test is described honestly: it is a mount test under `overlay2`
  and not under `vfs`, where checks 1 and 2 are what still hold.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GBq2rGum6GX7xXgsas1fDc
This commit is contained in:
shadow-test
2026-08-23 15:47:36 -07:00
co-authored by Claude Opus 5
parent ed91423666
commit 00128f9b1a
3 changed files with 895 additions and 97 deletions
Download Patch File Download Diff File Expand all files Collapse all files
app/src-tauri/src/commands/migration_commands.rs
+280 -8
View File
@@ -472,13 +472,23 @@ async fn fresh_migration(
// The outcome is logged rather than discarded: this is the one scrub whose
// silence would be expensive, because the layer it declined to clean is
// about to be committed into a snapshot that outlives the migration.
log::info!(
"Pre-migration scrub of {}{}",
container_id,
docker::scrub_writable_layer(&container_id)
.await
.commit_log_suffix()
);
//
// H2: **bind it first.** `ScrubOutcome` is `#[must_use]`, and the way that
// was satisfied here was by folding the awaited call into `log::info!`'s
// argument list. `log::info!` expands to
// `if Info <= max_level() { … }` — so the arguments, this data-integrity
// step among them, live inside the level check and do not run at all when
// the global filter is `Off`. That is reachable: `logging::init` tolerates
// `dispatch.apply()` failing, and fern returns *before* `set_max_level` on
// error, so a process that failed to install a logger sits at `Off` with
// every `log::` argument list silently dead. The scrub would then never
// run, and the unscrubbed layer would be committed into the longest-lived
// snapshot the app takes. `commit_container_snapshot` gets this right for
// the same reason; nothing may put an effect inside a log macro's
// arguments. (`logging::init` now also restores the level on failure, but
// the call site is not allowed to depend on that.)
let scrub = docker::scrub_writable_layer(&container_id).await;
log::info!("Pre-migration scrub of {}{}", container_id, scrub.commit_log_suffix());
emit_progress(&app_handle, &project_id, "Stopping the container...");
let _ = state
@@ -1016,15 +1026,142 @@ pub async fn reconcile_migration(project: &Project, app_handle: &tauri::AppHandl
// whatever was running. `reconcile_project_statuses` is a command, not just
// a startup step, so "nothing else can be running yet" is not available as
// an argument.
//
// Yielding is right; yielding *forever* was not. The only caller fires once
// per "Docker became available", so a project that happened to be held at
// that instant was never looked at again for the rest of the session: its
// phase stayed un-normalised, no resume or rollback was ever offered, and
// its `:pre-migration-*` pin stayed `Claimed`. So the visit is deferred
// rather than dropped — see [`defer_migration_reconcile`].
if let Some(holder) = crate::project_lock::held(&project.id) {
log::debug!(
"Skipping migration reconcile for '{}' ({}): {}",
"Deferring migration reconcile for '{}' ({}): {}",
project.name,
project.id,
holder.describe()
);
defer_migration_reconcile(project, app_handle);
return;
}
reconcile_migration_now(project, app_handle).await;
}
/// How long [`defer_migration_reconcile`] waits between looks, and how many
/// times it looks.
///
/// The operations it is waiting behind are minutes long — a Reset recreates a
/// container from a base image, a compaction rebuilds a multi-gigabyte
/// snapshot — so the interval is coarse on purpose: this is a `held()` read
/// against an in-process map, but every wakeup is a task and the point is to
/// catch the release, not to catch it promptly. Twenty seconds × ninety is
/// thirty minutes, comfortably past the longest measured compaction, after
/// which the project is left for the next `reconcile_project_statuses`.
const RECONCILE_RETRY_INTERVAL: std::time::Duration = std::time::Duration::from_secs(20);
const RECONCILE_RETRY_ATTEMPTS: usize = 90;
/// Project ids with a deferred reconcile already waiting.
///
/// `reconcile_project_statuses` is a command the frontend can call more than
/// once — every "Docker became available" — and each call walks every project.
/// Without this, a project held for a few minutes would accumulate one waiting
/// task per call, all of which would then reconcile the same record in a row.
fn reconcile_retries() -> &'static std::sync::Mutex<std::collections::HashSet<String>> {
static RETRIES: std::sync::OnceLock<std::sync::Mutex<std::collections::HashSet<String>>> =
std::sync::OnceLock::new();
RETRIES.get_or_init(|| std::sync::Mutex::new(std::collections::HashSet::new()))
}
/// Claim the right to be the one deferred reconcile for `project_id`.
/// `false` means somebody else already is.
fn claim_reconcile_retry(project_id: &str) -> bool {
reconcile_retries()
.lock()
.unwrap_or_else(|e| e.into_inner())
.insert(project_id.to_string())
}
/// Give the claim back, so a later `reconcile_project_statuses` can defer again.
fn release_reconcile_retry(project_id: &str) {
reconcile_retries()
.lock()
.unwrap_or_else(|e| e.into_inner())
.remove(project_id);
}
/// Come back to a project that was held when [`reconcile_migration`] reached it.
///
/// Only for projects that have a record on disk: [`migration_store::has_record`]
/// is filesystem presence, so it costs nothing and is deliberately the *cheap*
/// question — every project is walked on every reconcile and almost none of
/// them have a migration in flight. A record that exists but cannot be parsed
/// answers `true` here and is handled, conservatively, by `load` when the
/// retry lands.
///
/// The wait is a poll rather than a notification because `project_lock` has no
/// release hook and giving it one would mean a guard's `Drop` waking tasks
/// while it still holds the map's mutex. A read of an in-process `HashMap`
/// every twenty seconds, for as long as one operation is running on one
/// project, is not worth a condvar.
fn defer_migration_reconcile(project: &Project, app_handle: &tauri::AppHandle) {
// No record means nothing to come back for. An unreadable migrations
// directory answers "maybe", and maybe is worth a look.
if !migration_store::has_record(&project.id).unwrap_or(true) {
return;
}
if !claim_reconcile_retry(&project.id) {
return;
}
let project = project.clone();
let app_handle = app_handle.clone();
tauri::async_runtime::spawn(async move {
let released =
await_release(&project.id, RECONCILE_RETRY_INTERVAL, RECONCILE_RETRY_ATTEMPTS).await;
if released {
// Whatever was holding it may have finished the migration itself or
// cleared the record — `reconcile_migration_now` loads the record
// first and returns on `None`, so that is a no-op rather than a
// special case here.
reconcile_migration_now(&project, &app_handle).await;
} else {
log::warn!(
"Gave up waiting to reconcile the migration record for '{}' ({}): it has been \
held for {} minutes. Its phase is unchanged and its rollback pin is still \
claimed; the next reconcile pass will try again.",
project.name,
project.id,
RECONCILE_RETRY_INTERVAL.as_secs() as usize * RECONCILE_RETRY_ATTEMPTS / 60
);
}
release_reconcile_retry(&project.id);
});
}
/// Wait for `project_id` to stop being held, up to `attempts` looks
/// `interval` apart. `true` means it was released, `false` that the budget ran
/// out with it still held.
///
/// Split out of [`defer_migration_reconcile`] so the waiting can be tested
/// against a real [`crate::project_lock`] guard on a paused clock — the part
/// that is easy to get wrong is "gives up while still holding the claim" and
/// "never looks again", neither of which is visible from the constants.
async fn await_release(
project_id: &str,
interval: std::time::Duration,
attempts: usize,
) -> bool {
for _ in 0..attempts {
tokio::time::sleep(interval).await;
if crate::project_lock::held(project_id).is_none() {
return true;
}
}
false
}
/// [`reconcile_migration`] with the "is anything holding this project" question
/// already answered.
async fn reconcile_migration_now(project: &Project, app_handle: &tauri::AppHandle) {
let state = match migration_store::load(&project.id) {
Ok(Some(s)) => s,
Ok(None) => return,
@@ -1962,4 +2099,139 @@ mod tests {
assert!(!r.rollback_available);
assert!(r.packages_requested.is_empty());
}
/// No `await` may sit inside a `log::*!` argument list — H2, generalised.
///
/// `log::info!(a, b)` expands to `if Info <= max_level() { … a … b … }`, so
/// an argument is only evaluated while the level admits the record. Folding
/// `scrub_writable_layer(&id).await.commit_log_suffix()` into the arguments
/// here — done to satisfy `#[must_use]` on `ScrubOutcome` — therefore made
/// the pre-migration scrub conditional on the log level, and
/// `logging::init` deliberately tolerates failing to install a logger,
/// which leaves `max_level()` at `Off`. A scrub that never runs before the
/// largest snapshot the app takes is not something a log level may decide.
///
/// Scanned over the source rather than asserted at one call site: the bug
/// is a shape, and it is reintroduced by whoever next has a `#[must_use]`
/// value they only want to log.
#[test]
fn nothing_awaits_inside_a_log_macros_arguments() {
let sources: &[(&str, &str)] = &[
("commands/migration_commands.rs", include_str!("migration_commands.rs")),
("docker/container.rs", include_str!("../docker/container.rs")),
("docker/migration.rs", include_str!("../docker/migration.rs")),
("logging.rs", include_str!("../logging.rs")),
];
let macros = ["log::error!(", "log::warn!(", "log::info!(", "log::debug!(", "log::trace!("];
let mut scanned = 0usize;
for (name, src) in sources {
for mac in macros {
let mut from = 0usize;
while let Some(at) = src[from..].find(mac) {
let start = from + at + mac.len();
// Balance the macro's own parentheses. String literals in
// these call sites never contain an unbalanced one, and a
// `(` inside a format string would only ever widen the
// slice, i.e. fail safe.
let mut depth = 1usize;
let mut end = start;
for (i, c) in src[start..].char_indices() {
match c {
'(' => depth += 1,
')' => {
depth -= 1;
if depth == 0 {
end = start + i;
break;
}
}
_ => {}
}
}
let args = &src[start..end];
// This test's own name mentions the thing it forbids.
assert!(
!args.contains(".await"),
"{}: an `.await` inside a `{}` argument list stops happening whenever the \
log level does not admit the record:\n{}",
name,
mac.trim_end_matches('('),
args
);
scanned += 1;
from = end.max(start);
}
}
}
// A scanner that matched nothing would pass silently forever.
assert!(scanned > 80, "only {} log call sites were scanned", scanned);
}
/// MEDIUM: a project held when the reconcile pass reached it must be
/// revisited, not dropped for the session.
///
/// `reconcile_project_statuses` fires once per "Docker became available",
/// so the old `return` meant a project that happened to be mid-Reset at
/// that instant never had its migration phase normalised, was never offered
/// resume or rollback, and kept its `:pre-migration-*` pin `Claimed` — for
/// the rest of the session. On a paused clock, so the thirty-minute budget
/// costs nothing.
#[tokio::test(start_paused = true)]
async fn a_held_project_is_revisited_once_the_holder_lets_go() {
let id = format!("await-release-{}", uuid::Uuid::new_v4().simple());
let guard = crate::project_lock::try_acquire(&id, crate::project_lock::ProjectOp::Reset)
.expect("a fresh project id is not held");
let waiting = {
let id = id.clone();
tokio::spawn(async move {
await_release(&id, RECONCILE_RETRY_INTERVAL, RECONCILE_RETRY_ATTEMPTS).await
})
};
// Long enough that several looks have already happened and found it
// held, so this cannot pass by the waiter never having polled.
tokio::time::sleep(RECONCILE_RETRY_INTERVAL * 3).await;
assert!(!waiting.is_finished(), "the waiter returned while the project was held");
drop(guard);
assert!(
waiting.await.expect("the waiter task"),
"the holder let go and the reconcile never came back"
);
}
/// And the budget is finite: a project held indefinitely does not leave a
/// task waiting on it forever, and the claim is handed back either way.
#[tokio::test(start_paused = true)]
async fn waiting_for_a_holder_gives_up_eventually() {
let id = format!("await-release-{}", uuid::Uuid::new_v4().simple());
let _guard =
crate::project_lock::try_acquire(&id, crate::project_lock::ProjectOp::Migration)
.expect("a fresh project id is not held");
assert!(!await_release(&id, RECONCILE_RETRY_INTERVAL, RECONCILE_RETRY_ATTEMPTS).await);
// Thirty minutes: past the longest measured compaction, and the thing
// being waited on is always a bounded, user-initiated operation.
assert!(RECONCILE_RETRY_ATTEMPTS > 0, "deferring would be a no-op");
let budget = RECONCILE_RETRY_INTERVAL * RECONCILE_RETRY_ATTEMPTS as u32;
assert!(budget >= std::time::Duration::from_secs(15 * 60), "{:?}", budget);
}
#[test]
fn only_one_deferred_reconcile_waits_per_project() {
// Every "Docker became available" walks every project, so without the
// claim a project held for a few minutes accumulates one waiting task
// per call — all of which then reconcile the same record in a row.
let id = format!("retry-claim-{}", uuid::Uuid::new_v4().simple());
let other = format!("retry-claim-{}", uuid::Uuid::new_v4().simple());
assert!(claim_reconcile_retry(&id));
assert!(!claim_reconcile_retry(&id), "a second waiter was allowed in");
assert!(claim_reconcile_retry(&other), "the claim is not per-project");
release_reconcile_retry(&id);
assert!(claim_reconcile_retry(&id), "the claim was never handed back");
release_reconcile_retry(&id);
release_reconcile_retry(&other);
// Releasing something that was never claimed is not an error.
release_reconcile_retry(&id);
}
}
app/src-tauri/src/docker/container.rs
+550 -87
View File
@@ -2149,6 +2149,42 @@ const SCRUB_CONTAINMENT_PREFIXES: &[&str] = &["/tmp", "/var/log", "/var/lib/apt"
/// exec's interleaved stdout/stderr.
const SCRUB_MARKER: &str = "###TRIPLE-C-SCRUBBED ";
/// Marker the scrub script prints **instead of** [`SCRUB_MARKER`] when it
/// cannot run at all, followed by what was missing.
///
/// H3: the script needs six external tools and the root filesystem's device id,
/// and on a base image that has none of them where it looked it used to run its
/// seven patterns, delete nothing, and print `###TRIPLE-C-SCRUBBED 0` — a
/// number indistinguishable from an honest "there was nothing to take". A scrub
/// that could not run must never read as one that ran, so it says so in a line
/// the caller can tell apart, and prints no total at all.
///
/// Deliberately **not** a prefix of [`SCRUB_MARKER`] and not prefixed by it, so
/// `parse_scrub_total` can never mistake one for the other.
const SCRUB_UNAVAILABLE_MARKER: &str = "###TRIPLE-C-SCRUB-UNAVAILABLE ";
/// Environment the scrub exec sets explicitly, rather than inheriting.
///
/// The exec inherits the container's configured env, and a project's *custom*
/// env vars are part of that: `is_reserved_env_key` reserves the `ANTHROPIC_`,
/// `AWS_`, `GIT_`, `HOST_` and `TRIPLE_C_` families and a handful of exact
/// names, none of which is `LD_PRELOAD`. So a custom env var naming a shared
/// object inside the container's *persisted home volume* injects code into
/// every tool the scrub runs — as **root**, since that is the user the exec is
/// created as — and decides the answer to checks 3 and 4 without ever touching
/// `PATH`. `docker commit` bakes env into the snapshot, so it rides along too.
///
/// Blanking them in the exec closes that without breaking anything: nothing
/// legitimate preloads into `/bin/sh`, `stat`, `du`, `cut`, `find` or `rm`, and
/// this env applies to the scrub exec **only** — a terminal session, which is a
/// different exec, is untouched. Verified against Engine 29.7 that a
/// `docker exec -e LD_PRELOAD=` overrides a container-level `LD_PRELOAD`.
///
/// `LD_LIBRARY_PATH` is here for the same reason as `LD_PRELOAD`: it is
/// searched ahead of the cache for every `DT_NEEDED` library, so a planted
/// `libselinux.so.1` is as good as a preload.
const SCRUB_EXEC_ENV: &[&str] = &["LD_PRELOAD=", "LD_AUDIT=", "LD_LIBRARY_PATH="];
/// Split a [`SNAPSHOT_SCRUB_PATHS`] entry into the literal directory it is
/// anchored to and the glob to expand inside it.
///
@@ -2204,19 +2240,32 @@ pub(crate) fn snapshot_scrub_script() -> String {
/// symlink is not the only way to name the wrong directory; this refuses to
/// operate outside the trees the scrub owns whatever the path list says.
/// 3. It must be on the same filesystem as the root. Check 1 does not see a
/// *bind mount*, which is not a symlink — but a bind mount and a named
/// volume each have a different `st_dev` from the overlay, and neither is
/// part of the writable layer the commit is about to capture. So anything on
/// another device is both dangerous to delete and pointless to.
/// *bind mount*, which is not a symlink — but under `overlay2` a bind mount
/// and a named volume each have a different `st_dev` from the overlay, and
/// neither is part of the writable layer the commit is about to capture. So
/// anything on another device is both dangerous to delete and pointless to.
///
/// The fifth is about each *match*, and it is the one the parent checks cannot
/// stand in for:
///
/// 4. Every expansion of the glob must itself be on the root's filesystem, or
/// it is skipped. Since the parent has already been proved to be, this is
/// exactly a "the match is not a mount point" test — the device of a
/// directory differs from its parent's precisely when something is mounted
/// on it.
/// it is skipped. Since the parent has already been proved to be, that is a
/// "the match is not a mount point" test — the device of a directory differs
/// from its parent's precisely when something is mounted on it.
///
/// **On `overlay2`, which is what these were measured against.** The overlay
/// synthesises its own `st_dev`, so *every* mount into the container differs
/// from it and checks 3 and 4 catch all of them. Under the `vfs` graph
/// driver there is no overlay: the container root is a plain directory tree
/// on the host filesystem, so a bind mount of a host directory that happens
/// to live on that same filesystem reports the *same* `st_dev` and these two
/// checks see nothing. Checks 1 and 2 — resolved path, and containment in
/// [`SCRUB_CONTAINMENT_PREFIXES`] — are what still hold there, and they are
/// why a `vfs` host is a narrower gap rather than an open one: the mount has
/// to be planted inside `/tmp`, `/var/log`, `/var/lib/apt` or
/// `/var/cache/apt` and match one of the seven globs to be reached at all.
/// Do not describe the device test as a mount test without that
/// qualification.
///
/// Checks 0–3 validate the *parent*, and `rm --one-file-system` compares
/// against the device of **its own command-line argument** — so when the
@@ -2240,23 +2289,58 @@ pub(crate) fn snapshot_scrub_script() -> String {
/// busybox's `rm` would reject it) refuses to recurse across a mount planted
/// *below* a match — which is the only mount position it does cover.
///
/// ## Why the tools are named absolutely
/// ## How the byte total is counted
///
/// Every external tool is called by absolute path, and `PATH` is reset before
/// anything runs. The image's `PATH` starts
/// `du` before the `rm`, `du` again after it if anything is still there, and
/// the difference is what was reclaimed. The obvious form —
/// `rm … && acc=$((acc + sz))` — was wrong in exactly the case
/// `--one-file-system` exists for: `rm` walking into a match that has a mount
/// planted *below* it removes everything else and still exits non-zero, so the
/// whole subtree's size was dropped from the total rather than the part that
/// survived. Under-reporting a scrub is the same class of quiet as reporting
/// zero for one that never ran. The second `du` only runs when the path is
/// still present, i.e. on the failure path, so the ordinary case pays nothing;
/// the figure is clamped at the pre-`rm` size so a directory something else is
/// concurrently growing cannot make it negative.
///
/// ## Why `PATH` is reset, and why the tools are *not* named absolutely (H3)
///
/// The first statement in the script sets `PATH={root}/usr/bin:{root}/bin` and
/// exports it, before any external tool runs. That is the whole shim defence.
/// The image's `PATH` starts
/// `/home/claude/.claude/bin:/home/claude/.local/bin:/home/claude/.cargo/bin`,
/// all of which live in the container's *persisted home volume* and are
/// writable by the agent — so a three-line `stat` on the front of it decides
/// the answer to checks 3 and 4. That was reproduced: with such a shim planted,
/// a volume mounted at `/var/log/apt` — refused by an unshimmed scrub — had its
/// entire contents deleted. A *missing* `stat` does fail closed (an empty
/// device string matches nothing), but a shimmed one answers, so failing closed
/// was never the property that mattered here. `auth_bridge` calls
/// `/usr/bin/cat` for the same reason.
/// entire contents deleted. The shim lives in the home volume; it cannot live
/// in `/usr/bin` or `/bin`, which uid 1000 cannot write. Resetting `PATH` to
/// exactly those two directories therefore defeats it just as completely as
/// spelling `/usr/bin/stat` out does.
///
/// This does not defend against something that can write `/usr/bin` itself,
/// which the agent's passwordless sudo can. It closes the part of the gap that
/// survives a container restart and needs no privileges at all.
/// Spelling them out as well was strictly *worse*, and it is what H3 was.
/// `/usr/bin/stat` is not where coreutils live on every base image — Settings →
/// Docker → **Custom** accepts any image, and on Alpine `stat` and `rm` are in
/// `/bin`. There, `/usr/bin/stat` is simply absent, `rootdev` comes back empty,
/// and `[ -n "$rootdev" ] || exit 0` fires for all seven patterns. Measured on
/// one seeded tree: the absolute-path script reported
/// `###TRIPLE-C-SCRUBBED 0` and left every planted file in place, where the
/// `PATH`-based one reclaimed 73738 bytes. Failing closed is correct; failing
/// closed while printing a number that reads as success is not, which is why
/// the tool probe and [`SCRUB_UNAVAILABLE_MARKER`] exist below.
///
/// So: the six tools are named bare and resolved through a `PATH` the script
/// controls, and the script refuses to delete anything at all unless
/// `command -v` finds every one of them and the root device id reads back as a
/// number. `find` is required along with the rest even though its absence would
/// only disable the age gate, because "ran with one hand tied" is exactly the
/// half-working state this whole section exists to stop being silent.
///
/// This does not defend against something that can write `/usr/bin` or `/bin`
/// itself, which the agent's passwordless sudo can. It closes the part of the
/// gap that survives a container restart and needs no privileges at all — and
/// see [`SCRUB_EXEC_ENV`] for the `LD_PRELOAD` half of the same question, which
/// `PATH` does nothing about.
///
/// ## Why every line ends in `;`, and why there are no `#` comments
///
@@ -2309,9 +2393,13 @@ fn snapshot_scrub_script_under(root: &str) -> String {
format!(
r#"PATH={root}/usr/bin:{root}/bin; export PATH;
total=0;
rootdev=$({root}/usr/bin/stat -c %d '{root}/' 2>/dev/null);
missing=;
for t in stat rm du cut find; do command -v "$t" >/dev/null 2>&1 || missing="$missing $t"; done;
rootdev=$(stat -c %d '{root}/' 2>/dev/null);
case "$rootdev" in ''|*[!0-9]*) rootdev=; missing="$missing root-device-id" ;; esac;
[ -z "$missing" ] || {{ echo "{unavailable}$missing"; exit 0; }};
rmopt=;
{root}/usr/bin/rm --one-file-system --help >/dev/null 2>&1 && rmopt=--one-file-system;
rm --one-file-system --help >/dev/null 2>&1 && rmopt=--one-file-system;
scrub_in() {{
n=$(
d=${{1%/*}}; [ -n "$d" ] || d=/;
@@ -2320,16 +2408,21 @@ cd -P "$d" 2>/dev/null || exit 0;
[ "$(pwd -P)" = "$d" ] || exit 0;
case "$d" in {allowed}) ;; *) exit 0 ;; esac;
[ -n "$rootdev" ] || exit 0;
[ "$({root}/usr/bin/stat -c %d . 2>/dev/null)" = "$rootdev" ] || exit 0;
[ "$(stat -c %d . 2>/dev/null)" = "$rootdev" ] || exit 0;
acc=0;
for p in $g; do
case "$p" in */*|.|..) continue ;; esac;
{{ [ -e "$p" ] || [ -L "$p" ]; }} || continue;
[ "$({root}/usr/bin/stat -c %d -- "$p" 2>/dev/null)" = "$rootdev" ] || continue;
[ "$2" = "-" ] || [ -n "$({root}/usr/bin/find "./$p" -maxdepth 0 -mtime +"$2" -print 2>/dev/null)" ] || continue;
sz=$({root}/usr/bin/du -sb -- "$p" 2>/dev/null | {root}/usr/bin/cut -f1);
[ "$(stat -c %d -- "$p" 2>/dev/null)" = "$rootdev" ] || continue;
[ "$2" = "-" ] || [ -n "$(find "./$p" -maxdepth 0 -mtime +"$2" -print 2>/dev/null)" ] || continue;
sz=$(du -sb -- "$p" 2>/dev/null | cut -f1);
case "$sz" in ''|*[!0-9]*) sz=0 ;; esac;
{root}/usr/bin/rm -rf $rmopt -- "$p" 2>/dev/null && acc=$((acc + sz));
rm -rf $rmopt -- "$p" 2>/dev/null;
rest=0;
{{ [ -e "$p" ] || [ -L "$p" ]; }} && rest=$(du -sb -- "$p" 2>/dev/null | cut -f1);
case "$rest" in ''|*[!0-9]*) rest=0 ;; esac;
[ "$rest" -le "$sz" ] || rest=$sz;
acc=$((acc + sz - rest));
done;
echo "$acc";
);
@@ -2343,12 +2436,18 @@ exit 0
allowed = allowed,
calls = calls,
marker = SCRUB_MARKER,
unavailable = SCRUB_UNAVAILABLE_MARKER,
)
}
/// Parse the byte total the scrub script reports. Returns `None` when the
/// marker is absent, which is how a container that never ran the script (or a
/// `sh` that died early) is told apart from one that reclaimed nothing.
///
/// A script that decided it could not run prints [`SCRUB_UNAVAILABLE_MARKER`]
/// and no total at all, so this returns `None` for that too — but callers must
/// ask [`parse_scrub_unavailable`] **first**, because "could not run" and
/// "printed nothing recognisable" deserve different words in the log.
fn parse_scrub_total(output: &str) -> Option<u64> {
output
.lines()
@@ -2356,6 +2455,27 @@ fn parse_scrub_total(output: &str) -> Option<u64> {
.find_map(|line| line.trim().strip_prefix(SCRUB_MARKER)?.trim().parse().ok())
}
/// What the scrub script said was missing, if it declined to run at all.
///
/// H3: the failure this exists for is silent by construction — a scrub with no
/// usable `stat` deletes nothing and, before this, printed the same
/// `###TRIPLE-C-SCRUBBED 0` a healthy container with nothing to clean prints.
/// The script now says which tools it could not find; this reads that back so
/// [`ScrubOutcome::Unavailable`] can carry it into the log.
fn parse_scrub_unavailable(output: &str) -> Option<String> {
output.lines().rev().find_map(|line| {
let missing = line.trim().strip_prefix(SCRUB_UNAVAILABLE_MARKER)?.trim();
Some(if missing.is_empty() {
"the image is missing the tools the scrub needs".to_string()
} else {
format!(
"the image has no usable {} on /usr/bin or /bin",
missing.split_whitespace().collect::<Vec<_>>().join(", ")
)
})
})
}
/// How long [`scrub_writable_layer`] waits for its exec before the commit goes
/// ahead without it.
///
@@ -2389,20 +2509,39 @@ pub enum ScrubOutcome {
TimedOut,
/// The container was running and the scrub genuinely failed.
Failed,
/// The exec ran, but the container's image does not have the tools the
/// scrub needs where it can reach them, so it deleted nothing.
///
/// Separate from [`ScrubOutcome::Failed`] because the exec itself worked
/// and the script ran to its own conclusion — and separate from
/// `Reclaimed(0)`, which is the whole of H3: a custom base image without
/// usr-merged coreutils reclaimed nothing and reported it as a completed
/// scrub of zero bytes.
Unavailable,
}
impl ScrubOutcome {
/// What the commit's log line should say about the scrub — **empty when
/// there is nothing to say**.
///
/// Every migration used to log "0.00 MB dropped by the pre-commit scrub",
/// because the migration path scrubs the container itself while it is
/// still running and stops it before committing, so the call here finds
/// nothing to exec into. A figure of zero reads as a scrub that ran and
/// found nothing, which is a different and more alarming thing than a
/// scrub that correctly had no work left.
/// Two different zeros used to render identically here. Every migration
/// logged "0.00 MB dropped by the pre-commit scrub", because the migration
/// path scrubs the container itself while it is still running and stops it
/// before committing, so the call here finds nothing to exec into. A figure
/// of zero reads as a scrub that ran and found nothing, which is a
/// different and more alarming thing than a scrub that correctly had no
/// work left.
///
/// The other zero was H3: a scrub that could not find its tools also
/// reclaimed nothing, and rendered as the same reassuring "0.00 MB
/// dropped". That one is [`ScrubOutcome::Unavailable`] now, and even a
/// genuine `Reclaimed(0)` says it *ran* rather than quoting a figure that
/// cannot be told apart from a broken scrub's.
pub(crate) fn commit_log_suffix(&self) -> String {
match self {
Self::Reclaimed(0) => {
" (the pre-commit scrub ran and found nothing to drop)".to_string()
}
Self::Reclaimed(bytes) => format!(
" ({:.2} MB dropped by the pre-commit scrub)",
*bytes as f64 / 1_048_576.0
@@ -2410,6 +2549,7 @@ impl ScrubOutcome {
Self::NotRunning => String::new(),
Self::TimedOut => " (the pre-commit scrub timed out, so the layer keeps whatever it had)".to_string(),
Self::Failed => " (the pre-commit scrub did not run, so the layer keeps whatever it had)".to_string(),
Self::Unavailable => " (the pre-commit scrub could not run in this image, so nothing was reclaimed and the layer keeps whatever it had)".to_string(),
}
}
}
@@ -2465,7 +2605,12 @@ pub async fn scrub_writable_layer(container_id: &str) -> ScrubOutcome {
let script = snapshot_scrub_script();
let cmd = vec!["/bin/sh".to_string(), "-c".to_string(), script];
let exec = crate::docker::exec::exec_oneshot_as(container_id, "root", cmd, Vec::new());
let exec = crate::docker::exec::exec_oneshot_as(
container_id,
"root",
cmd,
SCRUB_EXEC_ENV.iter().map(|e| (*e).to_string()).collect(),
);
// M12: nothing under `docker/` has a timeout, and this is the one call on
// the critical path of every recreate. Dropping the future stops us
@@ -2485,26 +2630,50 @@ pub async fn scrub_writable_layer(container_id: &str) -> ScrubOutcome {
};
match exec_result {
Ok((output, _exit_code)) => match parse_scrub_total(&output) {
Some(bytes) => {
if bytes > 0 {
Ok((output, _exit_code)) => {
// H3, first of the three silences: ask about "could not run"
// *before* reading a total, because the script prints no total in
// that case and a bare `None` would be reported as a generic
// failure without naming what the image is missing.
if let Some(reason) = parse_scrub_unavailable(&output) {
log::warn!(
"Pre-commit scrub of container {} could not run ({}); nothing was reclaimed and the commit will carry whatever the writable layer held",
container_id,
reason
);
return ScrubOutcome::Unavailable;
}
match parse_scrub_total(&output) {
// H3, second of the three: this used to log only when there
// was something to report, so a scrub that reclaimed nothing
// left no trace at all. A genuine zero is routine, so it is a
// debug line rather than a warning — the alarming zero is the
// `Unavailable` above, and that one is not quiet.
Some(0) => {
log::debug!(
"Pre-commit scrub of container {} ran and found nothing to reclaim",
container_id
);
ScrubOutcome::Reclaimed(0)
}
Some(bytes) => {
log::info!(
"Pre-commit scrub of container {} reclaimed {:.2} MB before it could be committed",
container_id,
bytes as f64 / 1_048_576.0
);
ScrubOutcome::Reclaimed(bytes)
}
None => {
log::warn!(
"Pre-commit scrub of container {} did not report a total; committing anyway. Output: {}",
container_id,
output.trim()
);
ScrubOutcome::Failed
}
ScrubOutcome::Reclaimed(bytes)
}
None => {
log::warn!(
"Pre-commit scrub of container {} did not report a total; committing anyway. Output: {}",
container_id,
output.trim()
);
ScrubOutcome::Failed
}
},
}
Err(e) => {
log::warn!(
"Pre-commit scrub of container {} could not run ({}); committing anyway",
@@ -4174,16 +4343,14 @@ mod tests {
// volume is not part of the writable layer and must never be
// touched.
assert!(script.contains(r#"[ -n "$rootdev" ] || exit 0;"#));
assert!(script
.contains(r#"[ "$(/usr/bin/stat -c %d . 2>/dev/null)" = "$rootdev" ] || exit 0;"#));
assert!(script.contains(r#"[ "$(stat -c %d . 2>/dev/null)" = "$rootdev" ] || exit 0;"#));
// 4. and *each match* on it too. Check 3 says nothing about a mount
// planted at the match itself, and `rm --one-file-system` compares
// against its own argument's device, so without this line a volume
// mounted at `/tmp/claude-x` has its contents deleted — reproduced
// against a live daemon before this existed.
assert!(script.contains(
r#"[ "$(/usr/bin/stat -c %d -- "$p" 2>/dev/null)" = "$rootdev" ] || continue;"#
));
assert!(script
.contains(r#"[ "$(stat -c %d -- "$p" 2>/dev/null)" = "$rootdev" ] || continue;"#));
// 5. an expansion carrying a separator means the list changed shape
assert!(script.contains(r#"case "$p" in */*|.|..) continue ;; esac;"#));
}
@@ -4195,32 +4362,81 @@ mod tests {
// persisted home volume. A three-line `stat` shim planted in the first
// of them made an unshimmed-refused mount at `/var/log/apt` delete its
// whole contents, so "no `stat` means no deletion" was never the
// property that mattered. Every tool is therefore named absolutely and
// `PATH` is reset before anything runs.
// property that mattered. The defence is the `PATH` reset, and it has
// to be the *first* statement in the script.
let script = snapshot_scrub_script();
assert!(
script.starts_with("PATH=/usr/bin:/bin; export PATH;\n"),
"the scrub inherits the container's PATH:\n{}",
script
);
// Nothing may run before the reset takes effect.
let reset_at = script.find("export PATH;").expect("the PATH reset");
assert!(
!script[..reset_at].contains('$'),
"something is expanded before PATH is reset:\n{}",
script
);
// H3: and the tools are *not* named absolutely on top of that.
// `/usr/bin/stat` is where coreutils live on Ubuntu and not where they
// live on Alpine, which Settings → Docker → Custom accepts — so an
// absolute path turned the whole scrub into a silent no-op there while
// buying nothing the reset above had not already bought.
assert!(
!script.contains("/usr/bin/stat"),
"the scrub hardcodes a coreutils location that is not universal:\n{}",
script
);
for tool in ["stat", "du", "find", "cut", "rm"] {
for (at, _) in script.match_indices(tool) {
// Skip the ones that are part of a longer word (`rmopt`,
// `--one-file-system`) rather than a command being run.
let before = &script[..at];
let after = &script[at + tool.len()..];
let is_word = !before.ends_with(|c: char| c.is_alphanumeric() || c == '-')
&& !after.starts_with(|c: char| c.is_alphanumeric() || c == '-');
if !is_word {
continue;
}
assert!(
before.ends_with("/usr/bin/"),
"`{}` is invoked without an absolute path, so the container decides which one runs:\n{}",
tool,
script
);
}
assert!(
!script.contains(&format!("/usr/bin/{}", tool)),
"`{}` is called by absolute path, which fails closed and silently on any image \
that does not put it there:\n{}",
tool,
script
);
}
}
#[test]
fn the_scrub_refuses_to_run_at_all_when_a_tool_is_missing() {
// H3, the structural half. Every one of the six things the script needs
// is probed up front, and a script that cannot find one prints a marker
// the caller can tell from a total instead of printing `0`.
let script = snapshot_scrub_script();
assert!(script.contains(
r#"for t in stat rm du cut find; do command -v "$t" >/dev/null 2>&1 || missing="$missing $t"; done;"#
));
assert!(script.contains(&format!(
r#"[ -z "$missing" ] || {{ echo "{}$missing"; exit 0; }};"#,
SCRUB_UNAVAILABLE_MARKER
)));
// The two markers must be un-confusable in both directions, since the
// caller reads whichever it finds out of one interleaved stream.
assert!(!SCRUB_UNAVAILABLE_MARKER.starts_with(SCRUB_MARKER));
assert!(!SCRUB_MARKER.starts_with(SCRUB_UNAVAILABLE_MARKER));
assert_eq!(parse_scrub_total("###TRIPLE-C-SCRUB-UNAVAILABLE stat"), None);
assert!(parse_scrub_unavailable("###TRIPLE-C-SCRUBBED 0").is_none());
}
#[test]
fn the_scrub_exec_blanks_the_dynamic_linker_hooks() {
// The exec inherits the container's env, and a project's custom env
// vars are part of it: `LD_PRELOAD` is in none of the reserved
// families, so it reaches a root exec unfiltered and injects code into
// every tool the scrub runs, `PATH` reset or not.
for key in ["LD_PRELOAD", "LD_AUDIT", "LD_LIBRARY_PATH"] {
assert!(
SCRUB_EXEC_ENV.contains(&format!("{}=", key).as_str()),
"{} reaches the scrub exec from the container's env",
key
);
// Blanked, never given a value — an empty `LD_PRELOAD` is what
// glibc reads as "no preload".
assert!(!is_reserved_env_key(key), "the reserved list has changed shape");
}
for entry in SCRUB_EXEC_ENV {
assert!(entry.ends_with('='), "{} carries a value into the scrub", entry);
}
}
@@ -4357,20 +4573,32 @@ mod tests {
);
}
/// Put the tools the re-anchored script calls where it will call them.
/// Put the tools the re-anchored script resolves through its own `PATH`
/// where it will look for them.
///
/// Symlinks to the real ones, so a test can replace exactly one — which is
/// how a mount point is simulated below without the privileges no test
/// process has.
#[cfg(target_os = "linux")]
fn plant_scrub_tools(root: &std::path::Path) {
std::fs::create_dir_all(root.join("usr/bin")).expect("mkdir usr/bin");
plant_scrub_tools_in(root, "usr/bin");
}
/// [`plant_scrub_tools`] into a chosen directory of the test root.
///
/// The script's `PATH` is `{root}/usr/bin:{root}/bin`, so `bin` is the
/// non-usr-merged layout — Alpine's — that H3 was a silent no-op on.
#[cfg(target_os = "linux")]
fn plant_scrub_tools_in(root: &std::path::Path, rel: &str) {
std::fs::create_dir_all(root.join(rel)).expect("mkdir the tool directory");
for tool in ["stat", "du", "find", "cut", "rm"] {
std::os::unix::fs::symlink(
std::path::Path::new("/usr/bin").join(tool),
root.join("usr/bin").join(tool),
)
.expect("link a tool into the test root");
let real = ["/usr/bin", "/bin"]
.iter()
.map(|d| std::path::Path::new(d).join(tool))
.find(|c| c.exists())
.unwrap_or_else(|| panic!("no {} on this host to link", tool));
std::os::unix::fs::symlink(real, root.join(rel).join(tool))
.expect("link a tool into the test root");
}
}
@@ -4445,7 +4673,14 @@ mod tests {
use std::os::unix::fs::PermissionsExt;
fs::set_permissions(hostile.join("stat"), fs::Permissions::from_mode(0o755)).unwrap();
}
let hostile_path = format!("{}:/usr/bin:/bin", hostile.display());
// The shim first, then the test root's own tool directory: without the
// reset the script finds the shim, with it the script finds neither
// this `PATH` nor the shim.
let hostile_path = format!(
"{}:{}/usr/bin:/usr/bin:/bin",
hostile.display(),
root_str
);
let real = snapshot_scrub_script_under(&root_str);
// Negative control 1: the same script with check 4 deleted.
@@ -4454,10 +4689,15 @@ mod tests {
.filter(|l| !l.contains(r#"-- "$p" 2>/dev/null)" = "$rootdev" ] || continue;"#))
.map(|l| format!("{}\n", l))
.collect();
// Negative control 2: the script as it was before the tools were named
// absolutely — bare names, resolved through whatever `PATH` says.
let with_bare_tools: String = real
.replace(&format!("{}/usr/bin/", root_str), "")
// Negative control 2: the same script with the `PATH` reset deleted,
// so its bare tool names resolve through whatever `PATH` says. This is
// what the scrub was before the reset existed, and the shim below owns
// it. (Naming the tools absolutely *also* defeated the shim — and was
// H3, because `/usr/bin/stat` is not where every image keeps `stat`.
// The reset defeats it without that failure mode: the shim lives in
// the home volume, which the reset drops off `PATH` entirely, and uid
// 1000 cannot write `/usr/bin` or `/bin`.)
let without_path_reset: String = real
.lines()
.filter(|l| !l.starts_with("PATH="))
.map(|l| format!("{}\n", l))
@@ -4482,7 +4722,7 @@ mod tests {
let no_check_kept = mounted_survived();
seed();
run(&with_bare_tools, &hostile_path);
run(&without_path_reset, &hostile_path);
let bare_kept = mounted_survived();
fs::remove_dir_all(&root).ok();
@@ -4514,6 +4754,211 @@ mod tests {
);
}
/// H3, the behavioural half: a base image whose coreutils are not under
/// `/usr/bin`.
///
/// Settings → Docker → **Custom** takes any image name, and on Alpine
/// `stat` and `rm` are in `/bin`. Measured in a real `alpine:latest`
/// container against the same seeded tree: the absolute-path script printed
/// `###TRIPLE-C-SCRUBBED 0` and left every planted file where it was, while
/// the `PATH`-resolved one reclaimed 73738 bytes. Both halves are asserted
/// here — the negative control is the script this replaced, rebuilt by
/// putting the `/usr/bin/` prefixes back — so a regression cannot pass by
/// the harness quietly losing the ability to tell them apart.
#[cfg(target_os = "linux")]
#[test]
fn the_scrub_finds_its_tools_when_coreutils_are_not_usr_merged() {
use std::fs;
use std::process::Command;
let base = fs::canonicalize(std::env::temp_dir()).expect("a real temp dir");
let root = base.join(format!("triple-c-scrub-{}", uuid::Uuid::new_v4().simple()));
let root_str = root.to_str().expect("a UTF-8 temp path").to_string();
// The whole point: `bin`, and deliberately no `usr/bin` at all.
plant_scrub_tools_in(&root, "bin");
assert!(!root.join("usr/bin").exists());
let seed = || {
fs::remove_dir_all(root.join("tmp")).ok();
fs::create_dir_all(root.join("tmp/claude-scratch")).expect("mkdir");
fs::write(root.join("tmp/claude-scratch/blob"), vec![0u8; 64 * 1024]).unwrap();
};
let script = snapshot_scrub_script_under(&root_str);
// The pre-fix shape, rebuilt: every tool named absolutely under a
// `/usr/bin` this root does not have.
let absolute: String = script
.replace(r#"$(stat "#, &format!("$({}/usr/bin/stat ", root_str))
.replace("\nrm --one-file-system", &format!("\n{}/usr/bin/rm --one-file-system", root_str))
.replace("\nrm -rf ", &format!("\n{}/usr/bin/rm -rf ", root_str))
.replace("$(du -sb", &format!("$({}/usr/bin/du -sb", root_str))
.replace("| cut -f1", &format!("| {}/usr/bin/cut -f1", root_str))
.replace("$(find ", &format!("$({}/usr/bin/find ", root_str))
.lines()
// The probe is what makes the pre-fix shape *loud*; the control has
// to be the quiet version it replaced, so drop it.
.filter(|l| !l.starts_with("for t in ") && !l.starts_with(r#"[ -z "$missing" ]"#))
.map(|l| format!("{}\n", l))
.collect();
let run = |sh: &str| {
Command::new("/bin/sh")
.arg("-c")
.arg(sh)
.output()
.expect("run the generated script")
};
seed();
let before = run(&absolute);
let before_out = String::from_utf8_lossy(&before.stdout).into_owned();
let before_kept = root.join("tmp/claude-scratch/blob").exists();
seed();
let after = run(&script);
let after_out = String::from_utf8_lossy(&after.stdout).into_owned();
let after_gone = !root.join("tmp/claude-scratch").exists();
fs::remove_dir_all(&root).ok();
assert!(
before_kept,
"the harness cannot tell the difference: the absolute-path script reclaimed on a \
root with no /usr/bin, so this proves nothing.\nstdout: {}",
before_out
);
assert_eq!(
parse_scrub_total(&before_out),
Some(0),
"the control is supposed to be the *silent* failure — a clean-looking zero"
);
assert!(
after_gone,
"the scrub is still a no-op where coreutils are in /bin.\nstdout: {}\nstderr: {}",
after_out,
String::from_utf8_lossy(&after.stderr)
);
assert!(
parse_scrub_total(&after_out).unwrap_or(0) >= 64 * 1024,
"reported total {:?} does not account for the planted debris",
parse_scrub_total(&after_out)
);
assert!(parse_scrub_unavailable(&after_out).is_none());
}
/// H3's third silence: a scrub that could not run must not read as one that
/// ran and found nothing.
#[cfg(target_os = "linux")]
#[test]
fn a_scrub_that_cannot_find_its_tools_says_so_instead_of_reporting_zero() {
use std::fs;
use std::process::Command;
let base = fs::canonicalize(std::env::temp_dir()).expect("a real temp dir");
let root = base.join(format!("triple-c-scrub-{}", uuid::Uuid::new_v4().simple()));
let root_str = root.to_str().expect("a UTF-8 temp path").to_string();
fs::create_dir_all(root.join("tmp/claude-scratch")).expect("mkdir");
fs::write(root.join("tmp/claude-scratch/blob"), vec![0u8; 64 * 1024]).unwrap();
// No tools planted anywhere: `PATH` names two directories that do not
// exist, which is what a base image the scrub cannot run in looks like.
let script = snapshot_scrub_script_under(&root_str);
let out = Command::new("/bin/sh")
.arg("-c")
.arg(&script)
.output()
.expect("run the generated script");
let stdout = String::from_utf8_lossy(&out.stdout).into_owned();
let debris_kept = root.join("tmp/claude-scratch/blob").exists();
fs::remove_dir_all(&root).ok();
assert!(debris_kept, "the scrub deleted with no tools to validate with");
assert_eq!(
parse_scrub_total(&stdout),
None,
"a scrub that could not run still printed a total: {}",
stdout
);
let reason = parse_scrub_unavailable(&stdout)
.unwrap_or_else(|| panic!("no unavailable marker in: {}", stdout));
assert!(reason.contains("stat"), "the reason does not name what is missing: {}", reason);
// And the outcome the caller derives from it is not a success.
assert_ne!(ScrubOutcome::Unavailable, ScrubOutcome::Reclaimed(0));
assert!(!ScrubOutcome::Unavailable.commit_log_suffix().contains("MB"));
}
/// The byte total counts what a partly failed `rm` actually removed.
///
/// `rm --one-file-system` walking into a match with a mount planted below
/// it removes everything else and exits non-zero. The old
/// `rm … && acc=$((acc + sz))` dropped the whole subtree from the figure,
/// so the one case the `--one-file-system` probe exists for was also the
/// one that under-reported. A mount cannot be created by a test process, so
/// the partial failure is produced the only other way it happens: an `rm`
/// that removes part of its argument and returns non-zero.
#[cfg(target_os = "linux")]
#[test]
fn the_byte_total_counts_what_a_partly_failed_rm_removed() {
use std::fs;
use std::os::unix::fs::PermissionsExt;
use std::process::Command;
let base = fs::canonicalize(std::env::temp_dir()).expect("a real temp dir");
let root = base.join(format!("triple-c-scrub-{}", uuid::Uuid::new_v4().simple()));
let root_str = root.to_str().expect("a UTF-8 temp path").to_string();
plant_scrub_tools(&root);
fs::create_dir_all(root.join("tmp/claude-partial")).expect("mkdir");
fs::write(root.join("tmp/claude-partial/gone"), vec![0u8; 64 * 1024]).unwrap();
fs::write(root.join("tmp/claude-partial/keep"), vec![0u8; 8 * 1024]).unwrap();
let real_rm = ["/usr/bin/rm", "/bin/rm"]
.iter()
.find(|c| std::path::Path::new(c).exists())
.expect("an rm on this host")
.to_string();
fs::remove_file(root.join("usr/bin/rm")).expect("drop the symlink to the real rm");
fs::write(
root.join("usr/bin/rm"),
format!(
"#!/bin/sh\nfor a in \"$@\"; do case \"$a\" in claude-partial) {rm} -rf -- \
./claude-partial/gone; exit 1 ;; esac; done\nexec {rm} \"$@\"\n",
rm = real_rm
),
)
.expect("plant a partly-failing rm");
fs::set_permissions(root.join("usr/bin/rm"), fs::Permissions::from_mode(0o755)).unwrap();
let script = snapshot_scrub_script_under(&root_str);
let out = Command::new("/bin/sh")
.arg("-c")
.arg(&script)
.output()
.expect("run the generated script");
let stdout = String::from_utf8_lossy(&out.stdout).into_owned();
let gone = !root.join("tmp/claude-partial/gone").exists();
let kept = root.join("tmp/claude-partial/keep").exists();
let total = parse_scrub_total(&stdout);
fs::remove_dir_all(&root).ok();
assert!(
gone && kept,
"the harness cannot tell the difference: the planted rm did not fail partly \
(gone={}, kept={})\nstdout: {}",
gone,
kept,
stdout
);
let total = total.expect("the marker line is missing");
assert!(
total >= 64 * 1024,
"a partly failed rm was counted as having reclaimed {} bytes",
total
);
// And what survived is not counted as reclaimed.
assert!(total < 72 * 1024, "the total {} counts bytes that are still there", total);
}
#[test]
fn the_scrub_total_is_read_back_from_the_marker_line() {
assert_eq!(
@@ -4526,6 +4971,17 @@ mod tests {
// from reclaiming nothing, and the caller logs it differently.
assert_eq!(parse_scrub_total("sh: du: not found"), None);
assert_eq!(parse_scrub_total(""), None);
// H3: and "could not run" is a third thing again, told apart by its
// own marker rather than by a total that looks healthy.
assert_eq!(
parse_scrub_total("###TRIPLE-C-SCRUB-UNAVAILABLE stat rm"),
None
);
let reason = parse_scrub_unavailable("noise\n###TRIPLE-C-SCRUB-UNAVAILABLE stat rm\n")
.expect("the unavailable marker");
assert!(reason.contains("stat, rm"), "{}", reason);
assert!(parse_scrub_unavailable("###TRIPLE-C-SCRUBBED 41").is_none());
assert!(parse_scrub_unavailable("").is_none());
}
#[test]
@@ -4537,10 +4993,12 @@ mod tests {
assert_eq!(ScrubOutcome::NotRunning.commit_log_suffix(), "");
assert!(!ScrubOutcome::TimedOut.commit_log_suffix().contains("MB"));
assert!(!ScrubOutcome::Failed.commit_log_suffix().contains("MB"));
assert!(!ScrubOutcome::Unavailable.commit_log_suffix().contains("MB"));
assert!(ScrubOutcome::Reclaimed(4096)
.commit_log_suffix()
.contains("MB"));
assert_ne!(ScrubOutcome::NotRunning, ScrubOutcome::Failed);
assert_ne!(ScrubOutcome::Unavailable, ScrubOutcome::Reclaimed(0));
}
#[test]
@@ -4552,11 +5010,16 @@ mod tests {
assert_eq!(ScrubOutcome::NotRunning.commit_log_suffix(), "");
assert!(!ScrubOutcome::TimedOut.commit_log_suffix().contains("MB"));
assert!(!ScrubOutcome::Failed.commit_log_suffix().contains("MB"));
// A scrub that really ran still reports, zero included — that zero is
// an answer about a container that was there to be scrubbed.
assert!(ScrubOutcome::Reclaimed(0)
.commit_log_suffix()
.contains("0.00 MB"));
// A scrub that really ran still reports, zero included — but H3 is
// that "0.00 MB dropped" was also what a scrub that *could not run*
// printed, and the two must not render the same. A genuine zero says it
// ran; the broken one says it could not.
let ran = ScrubOutcome::Reclaimed(0).commit_log_suffix();
assert!(ran.contains("ran"), "{}", ran);
assert!(!ran.contains("MB"), "a zero that reads as a figure: {}", ran);
let broken = ScrubOutcome::Unavailable.commit_log_suffix();
assert!(broken.contains("could not run"), "{}", broken);
assert_ne!(ran, broken);
assert!(ScrubOutcome::Reclaimed(2 * 1_048_576)
.commit_log_suffix()
.contains("2.00 MB"));
app/src-tauri/src/logging.rs
+65 -2
View File
@@ -1,6 +1,11 @@
use std::fs;
use std::path::PathBuf;
/// The level the dispatch is built with, and the level restored by hand if
/// installing it fails — see the failure branch in [`init`] for why that
/// matters more than it looks.
const LOG_LEVEL: log::LevelFilter = log::LevelFilter::Info;
/// Returns the log directory path: `<data_dir>/triple-c/logs/`
fn log_dir() -> Option<PathBuf> {
dirs::data_dir().map(|d| d.join("triple-c").join("logs"))
@@ -33,7 +38,7 @@ pub fn init() {
message
))
})
.level(log::LevelFilter::Info)
.level(LOG_LEVEL)
.chain(std::io::stderr());
if let Some((_path, file)) = &log_file_path {
@@ -41,7 +46,28 @@ pub fn init() {
}
if let Err(e) = dispatch.apply() {
eprintln!("Failed to initialise logger: {}", e);
// H2's other half. `fern::Dispatch::apply` calls `log::set_boxed_logger`
// and only then `log::set_max_level`, so a failure returns with the
// global filter still at its default, `LevelFilter::Off`. That is not
// merely "no log output": every `log::info!(…)` expands to
// `if Info <= max_level() { … }`, so at `Off` the macro never evaluates
// its own arguments. Anything a call site put in an argument list —
// a function call, an `await`, a side effect — silently stops
// happening, app-wide, because a logger could not be installed.
//
// Call sites must not put effects in log arguments (see the
// pre-migration scrub in `migration_commands.rs`), but "the whole
// program's log macros are dead and nothing said so" is its own
// hazard, so the level this dispatch was configured with is restored
// by hand. Nothing is listening — `log`'s default logger is a no-op —
// but the macros evaluate, and the one thing that *is* guaranteed to
// reach the user, the stderr line below, says what happened.
eprintln!(
"Failed to initialise logger: {}. Log output is disabled for this run; \
log macros still evaluate their arguments.",
e
);
log::set_max_level(LOG_LEVEL);
}
// Install a panic hook that writes to the log file so crashes are captured.
@@ -71,3 +97,40 @@ pub fn init() {
log::info!("Logging to {}", path.display());
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn a_logger_that_could_not_be_installed_still_leaves_the_macros_evaluating() {
// H2: `log::info!(…)` expands to `if Info <= max_level() { … }`, so at
// `LevelFilter::Off` the arguments are never evaluated. `fern` returns
// before `set_max_level` when `apply()` fails, which leaves exactly
// that state — and a call site that folded an effect into an argument
// list then stops performing it, app-wide, because a log file could not
// be opened. The failure branch restores the level for that reason.
//
// Asserted on the level itself rather than by driving `init`, which
// installs a process-global logger and a panic hook and can only run
// once per process.
assert_ne!(LOG_LEVEL, log::LevelFilter::Off);
// The property that makes the above worth asserting, demonstrated
// against the macro itself: a side effect in an argument list runs only
// while the level admits the record.
let mut ran = false;
let effect = |v: &mut bool| {
*v = true;
0
};
let previous = log::max_level();
log::set_max_level(log::LevelFilter::Off);
log::info!("{}", effect(&mut ran));
assert!(!ran, "the premise is wrong: arguments evaluated at LevelFilter::Off");
log::set_max_level(LOG_LEVEL);
log::info!("{}", effect(&mut ran));
assert!(ran, "arguments did not evaluate at the level this module configures");
log::set_max_level(previous);
}
}