From 45aae6ff19a4252861abc2befbf334449182bbf3 Mon Sep 17 00:00:00 2001 From: David Abram Date: Thu, 8 Oct 2026 19:46:28 +0200 Subject: [PATCH 1/4] context: Define observability log lock striping plan Capture the fixed-stripe synchronization design, concurrency and fallback requirements, documentation updates, and validation work for bounded log-lock memory. Plan: observability-log-lock-striping Tasks: T01, T02, T03 Co-authored-by: SCE --- .../plans/observability-log-lock-striping.md | 121 ++++++++++++++++++ 1 file changed, 121 insertions(+) create mode 100644 context/plans/observability-log-lock-striping.md diff --git a/context/plans/observability-log-lock-striping.md b/context/plans/observability-log-lock-striping.md new file mode 100644 index 000000000..4e616c250 --- /dev/null +++ b/context/plans/observability-log-lock-striping.md @@ -0,0 +1,121 @@ +# Plan: observability-log-lock-striping + +## Change summary + +`cli/src/services/observability.rs::file_log_lock` keeps a process-global `OnceLock>>>>`. Every distinct log path ever written adds an `Arc>` that is never evicted, so synchronization memory grows with the number of historical paths. This plan replaces the registry with a fixed `static LOG_LOCKS: [Mutex<()>; LOG_LOCK_STRIPES]` (64 stripes) selected by a deterministic hash of the path modulo the stripe count. It is a replacement of the lock-selection mechanism only; append, fallback, retention, permission, redaction, and formatting behavior are preserved. Same-process serialization only: no cross-process guarantee exists today and none is added. + +Investigation findings (recorded from the code before selecting the design; T01 re-confirms them while implementing): + +- Production callers: `append_log_line_with_cleanup` is reached only through `append_log_line`, which is reached only from `Logger::write_log_line` (`observability.rs`). `append_log_line_once_with_cleanup` is reached only from the v2 fallback closure inside `append_log_line_with_cleanup`. `file_log_lock` has exactly those two call sites. +- Ownership: `Logger` is a `Clone + Debug` plain value holding `ObservabilityConfig`, `log_dir`, and retention limit; it owns no shared state. App startup builds one in `app.rs` (`Logger::from_resolved_config`) and stores it in the app context, but `Clone` and `pub` construction let independent instances target the same path, so per-instance mutexes (Option A) would be unsound and would need new shared ownership. Option B (static striping) is selected as the smallest correct design. +- Concurrency: logging is synchronous `std::fs` I/O invoked from the main thread, `tokio::task::spawn_blocking` paths, and plain `std::thread` users, so the critical section stays a synchronous `std::sync::Mutex`; no async mutex. +- Deadlock hazard: today the v2 fallback runs while the primary path's guard is still held, and takes the v2 path's own lock. With striping the primary and v2 paths can hash to the same stripe, and `std::sync::Mutex` is not reentrant, so the fallback must run after the primary guard is released. This is the main correctness risk of the change. A regression here deadlocks instead of failing, so the same-stripe test must run in a bounded child process (T02), never in-process and never via a detached thread plus `recv_timeout` (the deadlocked thread would outlive the failed test). +- Poisoning failure domain: `lock()` is called only at the two sites in `append_log_line_with_cleanup` / `append_log_line_once_with_cleanup`. The guarded section is `persist_log_line` (returns `Result`, uses `?`, no panicking calls expected) plus the retention `cleanup` callback, which is the only caller-supplied code run under the guard and therefore the only realistic poisoning source (a panic inside cleanup). T01 re-confirms this by inspection. Today a poisoned lock affects one path; with 64 stripes it affects every path hashing to that stripe, including unrelated ones. This enlarged failure domain is a documented, accepted consequence; existing poisoned-lock handling is preserved unchanged (no `into_inner` recovery, no `clear_poison`, no new fallback). +- Test-process infrastructure: `cli/src/app.rs::app_output_boundary_uses_isolated_process` already re-executes `std::env::current_exe()` with `--exact --nocapture` and an env marker to run an isolated child. T02 reuses this pattern (std only, no new dependency). +- Behavior to preserve: lock-acquisition failure (poisoned stripe) is returned as `failed to lock log file '': ...` and does not trigger the fallback (the fallback is only reached from the `persist_log_line` error arm, after the lock was acquired); fallback is a single non-recursive `-v2` attempt whose combined error text is unchanged; retention cleanup runs only after a write that created the file and runs inside the guard of the path that was written; files are opened with owner-only `0o600` on Unix; redaction happens before `append_log_line`. +- Cross-process: no filesystem lock or cross-process guarantee exists or is documented; `context/sce/cli-observability-contract.md` only says "serializes writes independently per path", which becomes inaccurate once paths can share a stripe. + +## Acceptance criteria + +- [ ] AC1: No path-keyed lock registry remains in `observability.rs`; synchronization storage is a fixed-size `[Mutex<()>; N]` static independent of the number of distinct log paths, with no per-path `Arc`/`Mutex` allocation, no `dyn`, no boxed callbacks, no `unsafe`, and no new dependency. + - Validate: `nix shell nixpkgs#ripgrep -c rg -n "BTreeMap|OnceLock|Arc': ...` and does not attempt the fallback. + - Validate: code inspection of the guard scope in `append_log_line_with_cleanup` (guard dropped before `attempt_v2_log_fallback` is called, no guard live across it); the same-stripe fallback child test (steps 3-5); the existing combined-error test (step 6); the poisoned-lock test (step 7). +- [ ] AC4b: Same-stripe fallback regression is deterministic and bounded: the test builds a primary path whose `v2_log_path` maps to the same stripe using the production `log_lock_stripe` selection, forces primary failure, and runs in an isolated child process with a finite parent-enforced timeout; the child is killed and reaped on timeout; timeout, unexpected termination, or wrong output fails the test; success requires the fallback file to exist with the expected content. + - Validate: the test passes under `observability`; temporarily holding the primary guard across the fallback makes it fail by timeout (not hang) and leaves no orphan child. +- [ ] AC4c: Poisoning semantics are preserved and documented: a poisoned stripe still yields `failed to lock log file '': ...` with no fallback and no silent recovery; no new recovery or fallback code is introduced; the enlarged (per-stripe rather than per-path) failure domain is stated in the plan assumptions and durable context. + - Validate: focused poisoned-stripe test (if practical, see T02); `rg -n "into_inner|clear_poison|PoisonError" cli/src/services/observability.rs` shows no new recovery logic; inspection of `context/sce/cli-observability-contract.md`. +- [ ] AC5: Retention-after-creation, owner-only Unix permissions, and redaction-before-persistence behave as before under the new locking. + - Validate: `observability` tests covering retention, `0o600` permissions, and redaction pass; no existing test is removed or weakened (`git diff main` shows only additions to the test module). +- [ ] AC6: Durable context states the ownership model, constant memory bound, same-process guarantee, absence of cross-process coordination, and stripe-collision contention trade-off. + - Validate: inspection of `context/sce/cli-observability-contract.md` (and `context/overview.md`/`context/glossary.md` only if they already describe per-path locking). +- [ ] AC7: The concurrency tests are not flaky. + - Validate: the targeted logging concurrency tests pass on 20 consecutive runs. + +### Full validation + +- All existing observability tests remain unchanged and pass (`git diff main` shows only additions to the test module). +- The same-stripe fallback regression executes in a subprocess with a bounded timeout (AC4b); the targeted concurrency tests are repeated 20 times (AC7). +- Review the diff for new dynamic dispatch, heap allocations on the lock-selection path, `unsafe`, dependencies, or unnecessary abstractions: `nix shell nixpkgs#ripgrep -c rg -n "dyn |Box<|Arc<|unsafe|Vec<" ` over the changed lock-selection code, and `git diff main -- cli/Cargo.toml cli/Cargo.lock` empty. +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml` +- `nix develop -c ./scripts/run-cli-cargo.sh clippy --manifest-path cli/Cargo.toml --all-targets --all-features -- -D warnings` +- `nix flake check` +- `nix build .#ci-checks` +- `git diff --check` + +### Context sync + +- `context/sce/cli-observability-contract.md` must replace "serializes writes independently per path" with the striped same-process model and the explicit no-cross-process statement. +- `context/context-map.md` annotation for that file is updated only if its summary text becomes inaccurate. + +## Task context synchronization lifecycle + +Persist this field in every plan; this is durable plan state, not chat state: + +- **Task context synchronization:** every task carries `pending | synced | blocked`. + A completed task must be `synced` before another task can start or the plan can + finish. +- For `blocked`, record **Blocker**, **Required action**, and **Retry condition** + beside the status. Never infer `synced` from conversation history; write every + lifecycle transition to the plan file. + +## Constraints and non-goals + +- **In scope:** `cli/src/services/observability.rs` (lock selection, the two append functions, inline tests) and the durable context named under Context sync. +- **Out of scope:** OpenTelemetry integration, other observability refactors, log formats/filenames/schema, retention policy, public configuration, logging queues, background workers, new runtimes, filesystem/cross-process locks. +- **Constraints:** std-only; static dispatch; keep generic `F: FnOnce(&Path) -> Result<()>` cleanup callbacks; no `dyn`, boxed callbacks, `unsafe`, new dependencies, or lint suppressions; the hash must be deterministic and independent of mutable global state (e.g. `std::hash::DefaultHasher::new()` with its fixed keys, not `RandomState`); `Cargo` runs go through `nix develop -c ./scripts/run-cli-cargo.sh`; tests stay a minimal focused set using the real implementation and no sleeps or timing assertions. +- **Non-goal:** guaranteeing cross-process serialization, per-instance lock ownership, or eviction caches. + +## Assumptions + +- 64 stripes (`LOG_LOCK_STRIPES`) is adequate; the exact count only affects collision contention, not correctness. +- Poisoned-lock behavior stays as today (error `failed to lock log file '': ...`, no fallback, no recovery). The failure domain changes from one path to every path on the poisoned stripe (~1/64 of paths per poisoned stripe). Poisoning requires a panic while the guard is held; the only caller-supplied code under the guard is the retention `cleanup` callback, so poisoning is not expected in normal logging. This is accepted, not mitigated, in this plan. +- Releasing the primary guard before the v2 fallback is acceptable: the fallback writes a different file, and the only previously-held-lock effect was ordering against other primary writers, which the fallback never touched. The fallback attempt is no longer atomic with the primary failure with respect to other writers; this is not observable beyond line ordering across two different files. +- Two stripes are never held at once by one call, so there is no lock-order inversion between stripes. +- The child-process timeout is bounded (a few seconds, generous for CI) and is a failure bound only, never a correctness assertion on timing. +- The existing contract doc, not a new ADR, is the right durable home for the model; no decision record is required. + +## Task stack + +- [ ] T01: `Replace the path registry with fixed lock striping and release the guard before fallback` (status:todo) + - Task ID: T01 + - Scope: In — in `observability.rs`, add `const LOG_LOCK_STRIPES: usize = 64` and `static LOG_LOCKS: [Mutex<()>; LOG_LOCK_STRIPES] = [const { Mutex::new(()) }; LOG_LOCK_STRIPES]`; a small `log_lock_stripe(path) -> &'static Mutex<()>` using a deterministic std hash modulo the stripe count; remove `file_log_lock`, the `BTreeMap`/`Arc`/`OnceLock` imports, and the registry; update `append_log_line_with_cleanup` so the primary guard is dropped before the v2 fallback is attempted on both success and failure paths (scope the guard in an inner block/helper covering lock + persist + retention, returning the persist result; call `attempt_v2_log_fallback` only after that scope ends, and never when lock acquisition itself failed) and `append_log_line_once_with_cleanup` takes the stripe directly; keep error strings, retention-inside-guard, and lock-failure-skips-fallback behavior; keep existing poisoned-lock error handling unchanged (no recovery, no new fallback) and confirm by inspection that only the cleanup callback can panic under the guard; add a doc comment stating same-process-only synchronization, no cross-process guarantee, that stripe collisions only add contention, and that a poisoned stripe now affects all paths on that stripe. Out — tests beyond keeping existing ones green, context docs, any other observability change. + - Dependencies: none + - Done when: the registry is gone, both append functions use the static stripes, the fallback cannot nest a lock on the same stripe (AC4a ordering holds), poisoned-lock handling is unchanged, no `dyn`/`Box`/`unsafe`/new dependency is introduced, and all existing `observability` tests pass unchanged. + - Verify: `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability`; `nix shell nixpkgs#ripgrep -c rg -n "BTreeMap|OnceLock|Arc': ...`, no `-v2` file is created, and nothing recovers the lock; use a path/stripe unique to the test so other tests are unaffected, and skip with a recorded rationale in the plan only if it cannot be isolated from the shared static; (e) retention under concurrent creation and `0o600` permissions on Unix (`#[cfg(unix)]`); (f) a secret in a logged record is redacted in the persisted file. Out — production behavior changes, correctness assertions on elapsed time, test-only copies of the locking logic, new dependencies, detached-thread-plus-`recv_timeout` harnesses, background workers. + - Same-stripe child-process test (d2) requirements: + 1. Build a primary path in a temp dir whose `v2_log_path(primary)` maps to the same stripe, using the production `log_lock_stripe` (compare by index or `std::ptr::eq` on the returned stripe); search deterministically over candidate file names (bounded loop) until one collides, and assert the collision before running. + 2. Force primary persistence to fail (e.g. a directory occupying the primary file name) so the fallback is triggered. + 3. Run the scenario in a child: parent re-executes `std::env::current_exe()` with `--exact --nocapture` and an env marker, mirroring `cli/src/app.rs::app_output_boundary_uses_isolated_process`; without the marker the child test is a no-op that passes. The child performs the real `append_log_line_with_cleanup` call, then prints a fixed success sentinel. + 4. Parent uses `Command::spawn` + a bounded `try_wait` polling loop against a finite deadline (std only; sleeps are only poll intervals, never assertions). + 5. On deadline expiry the parent calls `kill()` then `wait()` so the child is reaped, then fails the test with captured output. + 6. Timeout, non-success exit status or signal termination, or missing/incorrect sentinel output fails the test. + 7. On success the parent asserts the `-v2` fallback file exists with the exact expected line content and that the primary path is still the blocking directory. + 8. Child state (temp dir, env such as `HOME`/`XDG_*`) is isolated like the existing pattern; stdout/stderr are captured via pipes and drained so a full pipe cannot itself cause a hang. + - Dependencies: T01 + - Done when: each listed case has a deterministic test against the real implementation, all pass, the same-stripe child test fails by bounded timeout (not by hanging) if the guard were held across the fallback, no orphan child remains, and no existing test is removed or weakened. + - Verify: `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability`; repeat the targeted concurrency and fallback tests 20 times in a loop to detect flakiness; temporarily mutate T01 to hold the primary guard across the fallback and confirm the child test fails by timeout, then revert. + - Context synchronization: pending + +- [ ] T03: `Document the striped log-lock ownership model` (status:todo) + - Task ID: T03 + - Scope: In — update `context/sce/cli-observability-contract.md` (and its `context/context-map.md` annotation only if inaccurate) to state: static 64-stripe `Mutex<()>` ownership, constant memory independent of path count, same-process serialization of identical paths across threads and independent `Logger` instances, stripe-collision contention trade-off, guard released before the v2 fallback (lock-ordering contract), the enlarged poisoning failure domain (a poisoned stripe fails every path on it, unchanged error text, no recovery), and the explicit absence of cross-process coordination. Out — broad documentation refactoring, other context files. + - Dependencies: T01 + - Done when: the contract no longer says writes are serialized "independently per path" and contains the accurate model, the bound, the guarantee, the non-guarantee, and the trade-off, in current-state wording. + - Verify: inspect the changed lines in `context/sce/cli-observability-contract.md`; `git diff --check`. + - Context synchronization: pending + +## Open questions + +None. The request fully specifies scope, design, and constraints; the one design hazard (same-stripe fallback deadlock) is handled inside T01 and proven by the bounded child-process test in T02. From 4080e940f31f2feffff08e04d2e2e59e86082abf Mon Sep 17 00:00:00 2001 From: David Abram Date: Thu, 8 Oct 2026 19:54:14 +0200 Subject: [PATCH 2/4] observability: Replace per-path lock registry with fixed lock striping Reduce lock-registry overhead by hashing log paths across a fixed set of static mutexes. Scope the primary lock so fallback writes occur only after it is released, while retaining retention cleanup and poisoned-lock behavior. Plan: observability-log-lock-striping, T01 Co-authored-by: SCE --- cli/src/services/observability.rs | 64 ++++++++++--------- .../plans/observability-log-lock-striping.md | 10 ++- 2 files changed, 42 insertions(+), 32 deletions(-) diff --git a/cli/src/services/observability.rs b/cli/src/services/observability.rs index ed37f9ac8..b2ae457ab 100644 --- a/cli/src/services/observability.rs +++ b/cli/src/services/observability.rs @@ -1,11 +1,12 @@ use std::{ cmp::Ordering, - collections::BTreeMap, + collections::hash_map::DefaultHasher, fmt::Write as FmtWrite, fs::{self, OpenOptions}, + hash::{Hash, Hasher}, io::{self, ErrorKind, Write}, path::{Path, PathBuf}, - sync::{Arc, Mutex, OnceLock}, + sync::Mutex, time::SystemTime, }; @@ -339,23 +340,26 @@ where .with_context(|| format!("failed to create log directory '{}'", parent.display()))?; } - let lock = file_log_lock(path); - let _guard = lock.lock().map_err(|error| { - anyhow::anyhow!("failed to lock log file '{}': {error}", path.display()) - })?; + let primary_error = { + let _guard = log_lock_stripe(path).lock().map_err(|error| { + anyhow::anyhow!("failed to lock log file '{}': {error}", path.display()) + })?; - match persist_log_line(path, redacted_line) { - Ok(write_target) => { - run_log_retention_after_creation(path, write_target, cleanup); - Ok(()) + match persist_log_line(path, redacted_line) { + Ok(write_target) => { + run_log_retention_after_creation(path, write_target, cleanup); + return Ok(()); + } + Err(primary_error) => primary_error, } - Err(primary_error) => attempt_v2_log_fallback( - path, - redacted_line, - &primary_error, - |fallback_path, line| append_log_line_once_with_cleanup(fallback_path, line, cleanup), - ), - } + }; + + attempt_v2_log_fallback( + path, + redacted_line, + &primary_error, + |fallback_path, line| append_log_line_once_with_cleanup(fallback_path, line, cleanup), + ) } fn attempt_v2_log_fallback( @@ -386,8 +390,7 @@ where .with_context(|| format!("failed to create log directory '{}'", parent.display()))?; } - let lock = file_log_lock(path); - let _guard = lock.lock().map_err(|error| { + let _guard = log_lock_stripe(path).lock().map_err(|error| { anyhow::anyhow!("failed to lock log file '{}': {error}", path.display()) })?; @@ -573,17 +576,18 @@ fn collect_managed_log_files(log_dir: &Path) -> Result<(Vec, Vec Ok((managed_files, errors)) } -fn file_log_lock(path: &Path) -> Arc> { - static FILE_LOG_LOCKS: OnceLock>>>> = OnceLock::new(); - let locks = FILE_LOG_LOCKS.get_or_init(|| Mutex::new(BTreeMap::new())); - let mut locks = locks - .lock() - .unwrap_or_else(std::sync::PoisonError::into_inner); - Arc::clone( - locks - .entry(path.to_path_buf()) - .or_insert_with(|| Arc::new(Mutex::new(()))), - ) +const LOG_LOCK_STRIPES: usize = 64; + +static LOG_LOCKS: [Mutex<()>; LOG_LOCK_STRIPES] = [const { Mutex::new(()) }; LOG_LOCK_STRIPES]; + +fn log_lock_stripe_index(path: &Path) -> usize { + let mut hasher = DefaultHasher::new(); + path.hash(&mut hasher); + (hasher.finish() % LOG_LOCK_STRIPES as u64) as usize +} + +fn log_lock_stripe(path: &Path) -> &'static Mutex<()> { + &LOG_LOCKS[log_lock_stripe_index(path)] } #[cfg(unix)] diff --git a/context/plans/observability-log-lock-striping.md b/context/plans/observability-log-lock-striping.md index 4e616c250..5ba4793b6 100644 --- a/context/plans/observability-log-lock-striping.md +++ b/context/plans/observability-log-lock-striping.md @@ -83,13 +83,19 @@ Persist this field in every plan; this is durable plan state, not chat state: ## Task stack -- [ ] T01: `Replace the path registry with fixed lock striping and release the guard before fallback` (status:todo) +- [x] T01: `Replace the path registry with fixed lock striping and release the guard before fallback` (status:done) + - Completed: 2026-10-08 + - Files changed: `cli/src/services/observability.rs` + - Result: Replaced `file_log_lock` registry with `LOG_LOCK_STRIPES = 64` / `static LOG_LOCKS` and `log_lock_stripe_index`/`log_lock_stripe` (deterministic `DefaultHasher::new()`); `append_log_line_with_cleanup` scopes the primary guard in an inner block that returns on success and yields the persist error, so `attempt_v2_log_fallback` runs only after the guard is dropped and never after lock-acquisition failure; `append_log_line_once_with_cleanup` uses the stripe directly. Poisoned-lock error text unchanged; only the retention `cleanup` callback runs caller code under the guard. + - Verify: `observability` tests passed (8/8); `rg "BTreeMap|OnceLock|Arc; LOG_LOCK_STRIPES] = [const { Mutex::new(()) }; LOG_LOCK_STRIPES]`; a small `log_lock_stripe(path) -> &'static Mutex<()>` using a deterministic std hash modulo the stripe count; remove `file_log_lock`, the `BTreeMap`/`Arc`/`OnceLock` imports, and the registry; update `append_log_line_with_cleanup` so the primary guard is dropped before the v2 fallback is attempted on both success and failure paths (scope the guard in an inner block/helper covering lock + persist + retention, returning the persist result; call `attempt_v2_log_fallback` only after that scope ends, and never when lock acquisition itself failed) and `append_log_line_once_with_cleanup` takes the stripe directly; keep error strings, retention-inside-guard, and lock-failure-skips-fallback behavior; keep existing poisoned-lock error handling unchanged (no recovery, no new fallback) and confirm by inspection that only the cleanup callback can panic under the guard; add a doc comment stating same-process-only synchronization, no cross-process guarantee, that stripe collisions only add contention, and that a poisoned stripe now affects all paths on that stripe. Out — tests beyond keeping existing ones green, context docs, any other observability change. - Dependencies: none - Done when: the registry is gone, both append functions use the static stripes, the fallback cannot nest a lock on the same stripe (AC4a ordering holds), poisoned-lock handling is unchanged, no `dyn`/`Box`/`unsafe`/new dependency is introduced, and all existing `observability` tests pass unchanged. - Verify: `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability`; `nix shell nixpkgs#ripgrep -c rg -n "BTreeMap|OnceLock|Arc Date: Thu, 8 Oct 2026 20:02:27 +0200 Subject: [PATCH 3/4] observability: Add regression coverage for striped log locking Exercise the real log persistence paths under concurrent writers, independent logger instances, fallback failures, poisoned locks, retention, file permissions, and redaction. Isolate same-stripe fallback and lock poisoning in bounded child processes so regressions fail deterministically without contaminating shared test state. Replace the stripe-index truncating cast with a checked conversion for clippy without changing behavior. Plan: observability-log-lock-striping Task: T02 Co-authored-by: SCE --- cli/src/services/observability.rs | 384 +++++++++++++++++- .../plans/observability-log-lock-striping.md | 10 +- 2 files changed, 391 insertions(+), 3 deletions(-) diff --git a/cli/src/services/observability.rs b/cli/src/services/observability.rs index b2ae457ab..a4d98127e 100644 --- a/cli/src/services/observability.rs +++ b/cli/src/services/observability.rs @@ -583,7 +583,7 @@ static LOG_LOCKS: [Mutex<()>; LOG_LOCK_STRIPES] = [const { Mutex::new(()) }; LOG fn log_lock_stripe_index(path: &Path) -> usize { let mut hasher = DefaultHasher::new(); path.hash(&mut hasher); - (hasher.finish() % LOG_LOCK_STRIPES as u64) as usize + usize::try_from(hasher.finish() % LOG_LOCK_STRIPES as u64).unwrap_or_default() } fn log_lock_stripe(path: &Path) -> &'static Mutex<()> { @@ -790,6 +790,388 @@ mod tests { assert!(!log_dir.exists()); } + const CHILD_DEADLINE: std::time::Duration = std::time::Duration::from_secs(30); + const CHILD_POLL_INTERVAL: std::time::Duration = std::time::Duration::from_millis(20); + const ENV_CHILD_PATH: &str = "SCE_LOG_LOCK_CHILD_PATH"; + const SAME_STRIPE_SENTINEL: &str = "SAME_STRIPE_FALLBACK_OK"; + const POISON_SENTINEL: &str = "POISONED_STRIPE_OK"; + + fn text_logger(log_dir: &Path) -> Logger { + Logger { + config: ObservabilityConfig { + level: LogLevel::Error, + format: LogFormat::Text, + log_to_file: true, + }, + log_dir: Some(log_dir.to_path_buf()), + log_file_retention_limit: 10, + } + } + + fn read_all_log_lines(log_dir: &Path) -> Vec { + let mut lines = Vec::new(); + for entry in fs::read_dir(log_dir).unwrap() { + let path = entry.unwrap().path(); + if path + .extension() + .is_some_and(|ext| ext == LOG_FILE_EXTENSION) + { + lines.extend(fs::read_to_string(path).unwrap().lines().map(String::from)); + } + } + lines + } + + fn run_bounded_child(test_name: &str, child_path: &Path) -> std::process::Output { + use std::io::Read; + use std::process::{Command, Stdio}; + + let sandbox = tempfile::tempdir().unwrap(); + let mut child = Command::new(std::env::current_exe().unwrap()) + .args(["--exact", test_name, "--nocapture"]) + .current_dir(sandbox.path()) + .env(ENV_CHILD_PATH, child_path) + .env("HOME", sandbox.path()) + .env("XDG_CONFIG_HOME", sandbox.path().join("config")) + .env("XDG_STATE_HOME", sandbox.path().join("state")) + .env("XDG_CACHE_HOME", sandbox.path().join("cache")) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + + let mut stdout_pipe = child.stdout.take().unwrap(); + let mut stderr_pipe = child.stderr.take().unwrap(); + let stdout_reader = std::thread::spawn(move || { + let mut buffer = Vec::new(); + let _ = stdout_pipe.read_to_end(&mut buffer); + buffer + }); + let stderr_reader = std::thread::spawn(move || { + let mut buffer = Vec::new(); + let _ = stderr_pipe.read_to_end(&mut buffer); + buffer + }); + + let deadline = std::time::Instant::now() + CHILD_DEADLINE; + let status = loop { + if let Some(status) = child.try_wait().unwrap() { + break Some(status); + } + if std::time::Instant::now() >= deadline { + child.kill().unwrap(); + child.wait().unwrap(); + break None; + } + std::thread::sleep(CHILD_POLL_INTERVAL); + }; + + let stdout = stdout_reader.join().unwrap(); + let stderr = stderr_reader.join().unwrap(); + let Some(status) = status else { + panic!( + "child '{test_name}' exceeded {CHILD_DEADLINE:?} and was killed\nstdout: {}\nstderr: {}", + String::from_utf8_lossy(&stdout), + String::from_utf8_lossy(&stderr) + ); + }; + + std::process::Output { + status, + stdout, + stderr, + } + } + + fn assert_child_succeeded(output: &std::process::Output, sentinel: &str) { + let stdout = String::from_utf8_lossy(&output.stdout); + assert!( + output.status.success() && stdout.contains(sentinel), + "child failed: {:?}\nstdout: {stdout}\nstderr: {}", + output.status, + String::from_utf8_lossy(&output.stderr) + ); + } + + fn blocked_primary_path(log_dir: &Path, stem: &str) -> PathBuf { + let primary = log_dir.join(format!("{stem}.log")); + fs::create_dir_all(&primary).unwrap(); + primary + } + + #[test] + fn concurrent_writers_to_one_path_produce_complete_unique_lines() { + const THREADS: usize = 8; + const LINES_PER_THREAD: usize = 50; + + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("sce-concurrent.log"); + let padding = "x".repeat(512); + + std::thread::scope(|scope| { + for thread in 0..THREADS { + let path = &path; + let padding = &padding; + scope.spawn(move || { + for index in 0..LINES_PER_THREAD { + let line = format!("t{thread}-l{index}-{padding}-end"); + append_log_line_with_cleanup(path, &line, |_| Ok(())).unwrap(); + } + }); + } + }); + + let contents = fs::read_to_string(&path).unwrap(); + let mut seen = std::collections::BTreeSet::new(); + for line in contents.lines() { + assert!(line.ends_with("-end"), "interleaved line: {line}"); + assert!(seen.insert(line.to_string()), "duplicated line: {line}"); + } + assert_eq!(seen.len(), THREADS * LINES_PER_THREAD); + } + + #[test] + fn independent_logger_instances_serialize_writes_to_one_path() { + const INSTANCES: usize = 4; + const RECORDS_PER_INSTANCE: usize = 25; + + let dir = tempfile::tempdir().unwrap(); + let loggers: Vec = (0..INSTANCES).map(|_| text_logger(dir.path())).collect(); + + std::thread::scope(|scope| { + for (instance, logger) in loggers.iter().enumerate() { + scope.spawn(move || { + for index in 0..RECORDS_PER_INSTANCE { + let event_id = format!("sce.test.i{instance}.r{index}"); + logger.error(&event_id, "concurrent record", &[], Some("shared")); + } + }); + } + }); + + let lines = read_all_log_lines(dir.path()); + assert_eq!(lines.len(), INSTANCES * RECORDS_PER_INSTANCE); + for line in &lines { + assert!(line.starts_with("timestamp="), "malformed line: {line}"); + assert!( + line.ends_with("message=concurrent record"), + "malformed line: {line}" + ); + } + let unique: std::collections::BTreeSet<&String> = lines.iter().collect(); + assert_eq!(unique.len(), lines.len()); + } + + #[test] + fn stripe_selection_is_stable_bounded_and_independent_of_path_count() { + assert_eq!(LOG_LOCKS.len(), LOG_LOCK_STRIPES); + + let mut used = std::collections::BTreeSet::new(); + for index in 0..5000 { + let path = PathBuf::from(format!("/tmp/sce-distinct/sce-{index}.log")); + let stripe = log_lock_stripe_index(&path); + assert!(stripe < LOG_LOCK_STRIPES); + assert_eq!(stripe, log_lock_stripe_index(&path)); + assert!(std::ptr::eq( + log_lock_stripe(&path), + LOG_LOCKS.get(stripe).unwrap() + )); + used.insert(stripe); + } + + assert!(used.len() > 1); + assert_eq!(LOG_LOCKS.len(), LOG_LOCK_STRIPES); + } + + #[test] + fn fallback_on_a_different_stripe_writes_the_v2_file() { + let dir = tempfile::tempdir().unwrap(); + let primary = (0..1000) + .map(|index| dir.path().join(format!("sce-diff-{index}.log"))) + .find(|candidate| { + !std::ptr::eq( + log_lock_stripe(candidate), + log_lock_stripe(&v2_log_path(candidate)), + ) + }) + .unwrap(); + fs::create_dir_all(&primary).unwrap(); + + append_log_line_with_cleanup(&primary, "fallback-line", |_| Ok(())).unwrap(); + + assert_eq!( + fs::read_to_string(v2_log_path(&primary)).unwrap(), + "fallback-line\n" + ); + assert!(primary.is_dir()); + } + + #[test] + fn fallback_failure_reports_combined_primary_and_v2_error() { + let dir = tempfile::tempdir().unwrap(); + let primary = blocked_primary_path(dir.path(), "sce-both-fail"); + let fallback = v2_log_path(&primary); + fs::create_dir_all(&fallback).unwrap(); + + let error = append_log_line_with_cleanup(&primary, "line", |_| Ok(())) + .unwrap_err() + .to_string(); + + assert!( + error.starts_with(&format!( + "primary log file persistence failed for '{}': ", + primary.display() + )), + "{error}" + ); + assert!( + error.contains(&format!( + "; v2 fallback log file persistence failed for '{}': ", + fallback.display() + )), + "{error}" + ); + } + + #[test] + fn same_stripe_fallback_completes_in_bounded_child_process() { + let dir = tempfile::tempdir().unwrap(); + let primary = (0..10_000) + .map(|index| dir.path().join(format!("sce-collide-{index}.log"))) + .find(|candidate| { + std::ptr::eq( + log_lock_stripe(candidate), + log_lock_stripe(&v2_log_path(candidate)), + ) + }) + .expect("a primary path whose v2 path shares its stripe"); + fs::create_dir_all(&primary).unwrap(); + + let output = run_bounded_child( + "services::observability::tests::isolated_same_stripe_fallback", + &primary, + ); + + assert_child_succeeded(&output, SAME_STRIPE_SENTINEL); + assert_eq!( + fs::read_to_string(v2_log_path(&primary)).unwrap(), + "same-stripe-line\n" + ); + assert!(primary.is_dir()); + } + + #[test] + fn isolated_same_stripe_fallback() { + let Some(primary) = std::env::var_os(ENV_CHILD_PATH).map(PathBuf::from) else { + return; + }; + assert!(std::ptr::eq( + log_lock_stripe(&primary), + log_lock_stripe(&v2_log_path(&primary)) + )); + + append_log_line_with_cleanup(&primary, "same-stripe-line", |_| Ok(())).unwrap(); + + println!("{SAME_STRIPE_SENTINEL}"); + } + + #[test] + fn poisoned_stripe_fails_lock_without_fallback_in_child_process() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("sce-poison.log"); + + let output = run_bounded_child( + "services::observability::tests::isolated_poisoned_stripe", + &path, + ); + + assert_child_succeeded(&output, POISON_SENTINEL); + assert!(!v2_log_path(&path).exists()); + } + + #[test] + fn isolated_poisoned_stripe() { + let Some(path) = std::env::var_os(ENV_CHILD_PATH).map(PathBuf::from) else { + return; + }; + + let poisoned = std::panic::catch_unwind(|| { + let _ = append_log_line_with_cleanup(&path, "first", |_| panic!("poison the stripe")); + }); + assert!(poisoned.is_err()); + + let error = append_log_line_with_cleanup(&path, "second", |_| Ok(())) + .unwrap_err() + .to_string(); + assert!( + error.starts_with(&format!("failed to lock log file '{}': ", path.display())), + "{error}" + ); + assert!(!v2_log_path(&path).exists()); + assert_eq!(fs::read_to_string(&path).unwrap(), "first\n"); + + println!("{POISON_SENTINEL}"); + } + + #[test] + fn retention_runs_once_for_concurrent_creation_of_one_path() { + const THREADS: usize = 8; + + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("sce-retention.log"); + let cleanups = std::sync::atomic::AtomicUsize::new(0); + + std::thread::scope(|scope| { + for thread in 0..THREADS { + let path = &path; + let cleanups = &cleanups; + scope.spawn(move || { + append_log_line_with_cleanup(path, &format!("line-{thread}"), |log_dir| { + assert_eq!(log_dir, path.parent().unwrap()); + cleanups.fetch_add(1, std::sync::atomic::Ordering::SeqCst); + Ok(()) + }) + .unwrap(); + }); + } + }); + + assert_eq!(cleanups.load(std::sync::atomic::Ordering::SeqCst), 1); + assert_eq!(fs::read_to_string(&path).unwrap().lines().count(), THREADS); + } + + #[cfg(unix)] + #[test] + fn created_log_file_is_owner_only() { + use std::os::unix::fs::PermissionsExt; + + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("sce-perms.log"); + + append_log_line_with_cleanup(&path, "line", |_| Ok(())).unwrap(); + + let mode = fs::metadata(&path).unwrap().permissions().mode(); + assert_eq!(mode & 0o777, 0o600); + } + + #[test] + fn secrets_are_redacted_before_they_reach_the_log_file() { + let dir = tempfile::tempdir().unwrap(); + let logger = text_logger(dir.path()); + + logger.error( + "sce.test.redaction", + "request failed", + &[("password", "hunter2-super-secret")], + None, + ); + + let lines = read_all_log_lines(dir.path()); + assert_eq!(lines.len(), 1); + assert!(lines[0].contains("[REDACTED]")); + assert!(!lines[0].contains("hunter2-super-secret")); + } + #[test] fn observability_fields_for_internal_error_carry_surface_and_full_source_chain() { let source = anyhow::anyhow!("root cause").context("failed to do the thing"); diff --git a/context/plans/observability-log-lock-striping.md b/context/plans/observability-log-lock-striping.md index 5ba4793b6..d292462f7 100644 --- a/context/plans/observability-log-lock-striping.md +++ b/context/plans/observability-log-lock-striping.md @@ -97,7 +97,13 @@ Persist this field in every plan; this is durable plan state, not chat state: - Verify: `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability`; `nix shell nixpkgs#ripgrep -c rg -n "BTreeMap|OnceLock|Arc': ...`, no v2 file, no recovery), retention-callback-runs-once under concurrent creation, `0o600` on Unix, redaction before persistence. No existing test changed. Also fixed a pedantic-clippy `cast_possible_truncation` in T01's `log_lock_stripe_index` (`usize::try_from(...).unwrap_or_default()`, same behavior on 64-bit). + - Verify: `observability` tests passed (20/20); 20 consecutive runs all passed; mutation holding the primary guard across the fallback made the same-stripe child test fail by 30s bounded timeout with the child killed and reaped (no orphan), then reverted; `clippy --all-targets --all-features -D warnings` passed; `git diff --check` clean. + - Context impact: none beyond T03 (tests only; the small stripe-index cast fix does not change documented behavior). + - Deviation: poisoned-stripe case runs in an isolated child so the shared static cannot be poisoned for other tests; the T01 cast fix was required for the clippy gate and is behavior-neutral. - Task ID: T02 - Scope: In — inline tests in `observability.rs` that call the real `append_log_line_with_cleanup`/`Logger` paths: (a) same-path multi-thread writes with exact complete-line count and per-line integrity; (b) multiple independent `Logger` clones/instances writing one path; (c) many (thousands of) distinct paths asserting stripe selection is stable, always in range, and the stripe array length is the constant; (d) fallback coverage: (d1) in-process, primary failure forcing the v2 fallback (e.g. a directory occupying the primary file name) with paths on different stripes, plus the combined error text when both fail; (d2) **same-stripe fallback regression in an isolated child process** (see below); (d2a) a focused poisoned-stripe test, if practical: poison the stripe of a temp path by panicking inside the `cleanup` callback of a write that creates the file (caught with `std::panic::catch_unwind` or a joined thread), then assert the next write to that path returns `failed to lock log file '': ...`, no `-v2` file is created, and nothing recovers the lock; use a path/stripe unique to the test so other tests are unaffected, and skip with a recorded rationale in the plan only if it cannot be isolated from the shared static; (e) retention under concurrent creation and `0o600` permissions on Unix (`#[cfg(unix)]`); (f) a secret in a logged record is redacted in the persisted file. Out — production behavior changes, correctness assertions on elapsed time, test-only copies of the locking logic, new dependencies, detached-thread-plus-`recv_timeout` harnesses, background workers. - Same-stripe child-process test (d2) requirements: @@ -112,7 +118,7 @@ Persist this field in every plan; this is durable plan state, not chat state: - Dependencies: T01 - Done when: each listed case has a deterministic test against the real implementation, all pass, the same-stripe child test fails by bounded timeout (not by hanging) if the guard were held across the fallback, no orphan child remains, and no existing test is removed or weakened. - Verify: `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability`; repeat the targeted concurrency and fallback tests 20 times in a loop to detect flakiness; temporarily mutate T01 to hold the primary guard across the fallback and confirm the child test fails by timeout, then revert. - - Context synchronization: pending + - Context synchronization: synced - [ ] T03: `Document the striped log-lock ownership model` (status:todo) - Task ID: T03 From a94ca95921f936ebe87f7ffb81b3d3914d52c4eb Mon Sep 17 00:00:00 2001 From: David Abram Date: Thu, 8 Oct 2026 20:18:51 +0200 Subject: [PATCH 4/4] observability: Record striped log-lock contract Document the fixed 64-stripe in-process locking model, fallback lock ordering, poisoning semantics, and absence of cross-process coordination. Record the completed acceptance criteria and validation evidence for the lock-striping work. Plan: observability-log-lock-striping (T03) Co-authored-by: SCE --- cli/src/services/observability.rs | 3 +- .../plans/observability-log-lock-striping.md | 68 +++++++++++++++---- context/sce/cli-observability-contract.md | 5 +- 3 files changed, 61 insertions(+), 15 deletions(-) diff --git a/cli/src/services/observability.rs b/cli/src/services/observability.rs index a4d98127e..3d117b754 100644 --- a/cli/src/services/observability.rs +++ b/cli/src/services/observability.rs @@ -583,7 +583,8 @@ static LOG_LOCKS: [Mutex<()>; LOG_LOCK_STRIPES] = [const { Mutex::new(()) }; LOG fn log_lock_stripe_index(path: &Path) -> usize { let mut hasher = DefaultHasher::new(); path.hash(&mut hasher); - usize::try_from(hasher.finish() % LOG_LOCK_STRIPES as u64).unwrap_or_default() + usize::try_from(hasher.finish() % LOG_LOCK_STRIPES as u64) + .expect("log lock stripe index must fit usize") } fn log_lock_stripe(path: &Path) -> &'static Mutex<()> { diff --git a/context/plans/observability-log-lock-striping.md b/context/plans/observability-log-lock-striping.md index d292462f7..cfaefa010 100644 --- a/context/plans/observability-log-lock-striping.md +++ b/context/plans/observability-log-lock-striping.md @@ -17,25 +17,25 @@ Investigation findings (recorded from the code before selecting the design; T01 ## Acceptance criteria -- [ ] AC1: No path-keyed lock registry remains in `observability.rs`; synchronization storage is a fixed-size `[Mutex<()>; N]` static independent of the number of distinct log paths, with no per-path `Arc`/`Mutex` allocation, no `dyn`, no boxed callbacks, no `unsafe`, and no new dependency. +- [x] AC1: No path-keyed lock registry remains in `observability.rs`; synchronization storage is a fixed-size `[Mutex<()>; N]` static independent of the number of distinct log paths, with no per-path `Arc`/`Mutex` allocation, no `dyn`, no boxed callbacks, no `unsafe`, and no new dependency. - Validate: `nix shell nixpkgs#ripgrep -c rg -n "BTreeMap|OnceLock|Arc': ...` and does not attempt the fallback. +- [x] AC4a: Lock ordering contract holds: (1) acquire the primary path's stripe; (2) run primary persistence and its retention cleanup; (3) release the primary guard on both success and failure; (4) only then, if primary persistence failed, attempt the v2 fallback; (5) acquire the fallback stripe separately; (6) if both writes fail, the combined `primary log file persistence failed for ...; v2 fallback log file persistence failed for ...` message is byte-identical to today; (7) primary lock acquisition failure returns `failed to lock log file '': ...` and does not attempt the fallback. - Validate: code inspection of the guard scope in `append_log_line_with_cleanup` (guard dropped before `attempt_v2_log_fallback` is called, no guard live across it); the same-stripe fallback child test (steps 3-5); the existing combined-error test (step 6); the poisoned-lock test (step 7). -- [ ] AC4b: Same-stripe fallback regression is deterministic and bounded: the test builds a primary path whose `v2_log_path` maps to the same stripe using the production `log_lock_stripe` selection, forces primary failure, and runs in an isolated child process with a finite parent-enforced timeout; the child is killed and reaped on timeout; timeout, unexpected termination, or wrong output fails the test; success requires the fallback file to exist with the expected content. +- [x] AC4b: Same-stripe fallback regression is deterministic and bounded: the test builds a primary path whose `v2_log_path` maps to the same stripe using the production `log_lock_stripe` selection, forces primary failure, and runs in an isolated child process with a finite parent-enforced timeout; the child is killed and reaped on timeout; timeout, unexpected termination, or wrong output fails the test; success requires the fallback file to exist with the expected content. - Validate: the test passes under `observability`; temporarily holding the primary guard across the fallback makes it fail by timeout (not hang) and leaves no orphan child. -- [ ] AC4c: Poisoning semantics are preserved and documented: a poisoned stripe still yields `failed to lock log file '': ...` with no fallback and no silent recovery; no new recovery or fallback code is introduced; the enlarged (per-stripe rather than per-path) failure domain is stated in the plan assumptions and durable context. +- [x] AC4c: Poisoning semantics are preserved and documented: a poisoned stripe still yields `failed to lock log file '': ...` with no fallback and no silent recovery; no new recovery or fallback code is introduced; the enlarged (per-stripe rather than per-path) failure domain is stated in the plan assumptions and durable context. - Validate: focused poisoned-stripe test (if practical, see T02); `rg -n "into_inner|clear_poison|PoisonError" cli/src/services/observability.rs` shows no new recovery logic; inspection of `context/sce/cli-observability-contract.md`. -- [ ] AC5: Retention-after-creation, owner-only Unix permissions, and redaction-before-persistence behave as before under the new locking. +- [x] AC5: Retention-after-creation, owner-only Unix permissions, and redaction-before-persistence behave as before under the new locking. - Validate: `observability` tests covering retention, `0o600` permissions, and redaction pass; no existing test is removed or weakened (`git diff main` shows only additions to the test module). -- [ ] AC6: Durable context states the ownership model, constant memory bound, same-process guarantee, absence of cross-process coordination, and stripe-collision contention trade-off. +- [x] AC6: Durable context states the ownership model, constant memory bound, same-process guarantee, absence of cross-process coordination, and stripe-collision contention trade-off. - Validate: inspection of `context/sce/cli-observability-contract.md` (and `context/overview.md`/`context/glossary.md` only if they already describe per-path locking). -- [ ] AC7: The concurrency tests are not flaky. +- [x] AC7: The concurrency tests are not flaky. - Validate: the targeted logging concurrency tests pass on 20 consecutive runs. ### Full validation @@ -120,14 +120,58 @@ Persist this field in every plan; this is durable plan state, not chat state: - Verify: `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability`; repeat the targeted concurrency and fallback tests 20 times in a loop to detect flakiness; temporarily mutate T01 to hold the primary guard across the fallback and confirm the child test fails by timeout, then revert. - Context synchronization: synced -- [ ] T03: `Document the striped log-lock ownership model` (status:todo) +- [x] T03: `Document the striped log-lock ownership model` (status:done) + - Completed: 2026-10-08 + - Files changed: `context/sce/cli-observability-contract.md` + - Result: Replaced "serializes writes independently per path" with a pointer to a new lock-model bullet (64 static `Mutex<()>` stripes, deterministic hash, constant memory, same-process serialization across threads and `Logger` instances, collision contention only, one stripe held at a time with the primary guard released before the v2 fallback, enlarged poisoning domain with unchanged error text/no fallback/no recovery, no cross-process coordination); v2 sentence now says "striped serialization". `context/context-map.md` annotation does not mention per-path locking, so left unchanged. + - Verify: inspected changed lines; `git diff --check` clean. + - Context impact: none beyond this task (this task is the context update). - Task ID: T03 - Scope: In — update `context/sce/cli-observability-contract.md` (and its `context/context-map.md` annotation only if inaccurate) to state: static 64-stripe `Mutex<()>` ownership, constant memory independent of path count, same-process serialization of identical paths across threads and independent `Logger` instances, stripe-collision contention trade-off, guard released before the v2 fallback (lock-ordering contract), the enlarged poisoning failure domain (a poisoned stripe fails every path on it, unchanged error text, no recovery), and the explicit absence of cross-process coordination. Out — broad documentation refactoring, other context files. - Dependencies: T01 - Done when: the contract no longer says writes are serialized "independently per path" and contains the accurate model, the bound, the guarantee, the non-guarantee, and the trade-off, in current-state wording. - Verify: inspect the changed lines in `context/sce/cli-observability-contract.md`; `git diff --check`. - - Context synchronization: pending + - Context synchronization: synced ## Open questions None. The request fully specifies scope, design, and constraints; the one design hazard (same-stripe fallback deadlock) is handled inside T01 and proven by the bounded child-process test in T02. + +## Validation Report + +**Status:** validated +**Date:** 2026-10-08 + +### Commands run + +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml observability` -> exit 0 (20/20 passed, incl. stripe selection, many-paths, same-stripe child, poisoned-stripe child, retention, 0o600, redaction) +- `observability` test run repeated 20 consecutive times -> 0 failures +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml` -> exit 0 (368 passed, 0 failed) +- `nix develop -c ./scripts/run-cli-cargo.sh clippy --manifest-path cli/Cargo.toml --all-targets --all-features -- -D warnings` -> exit 0 +- `nix flake check` -> exit 0 (all checks passed) +- `nix build .#ci-checks` -> exit 0 +- `git diff --check` -> exit 0 +- `rg -n "BTreeMap|OnceLock|Arc no hits +- `git diff d90415e0 -- cli/Cargo.toml cli/Cargo.lock` -> empty (plan commits only touch observability.rs and context) + +### Success-criteria verification + +- [x] AC1 -> registry removed; `static LOG_LOCKS: [Mutex<()>; 64]`; rg shows no BTreeMap/OnceLock/Arc/dyn/unsafe/Box hits; Cargo files unchanged by plan commits +- [x] AC2 -> concurrent same-path and independent-Logger tests pass +- [x] AC3 -> stripe-selection test (5000 paths, constant array length, stable index) passes +- [x] AC4 -> same-stripe bounded child test, different-stripe fallback, and combined-error tests pass +- [x] AC4a -> inspection of `append_log_line_with_cleanup` (observability.rs:343-363): guard scoped in an inner block, dropped before `attempt_v2_log_fallback`; lock failure returns via `?` without fallback; combined error text unchanged +- [x] AC4b -> child test with finite deadline and kill+wait passes; T02 recorded the mutation check (guard held across fallback fails by bounded timeout, no orphan); not re-run in this validation +- [x] AC4c -> poisoned-stripe child test passes; no into_inner/clear_poison/PoisonError in file; contract doc states the enlarged failure domain +- [x] AC5 -> retention, 0o600, and redaction tests pass; diff removals contain no test code +- [x] AC6 -> `context/sce/cli-observability-contract.md` lines 36-38 state ownership, constant bound, same-process guarantee, no cross-process coordination, collision contention +- [x] AC7 -> 20 consecutive runs, 0 failures + +### Failed checks and follow-ups + +- None. + +### Residual risks + +- A poisoned stripe fails all paths hashing to it (accepted and documented). +- The guard-held-across-fallback mutation check relies on T02's recorded evidence rather than a fresh run. diff --git a/context/sce/cli-observability-contract.md b/context/sce/cli-observability-contract.md index ddbcbbc82..12692b805 100644 --- a/context/sce/cli-observability-contract.md +++ b/context/sce/cli-observability-contract.md @@ -33,8 +33,9 @@ Runtime observability consumes the shared resolved observability config from `cl - Sessionless file logs route to `/sce-.log`; session-aware file logs route to `/sce--.log`. - Session filename sanitization preserves ASCII letters, digits, `-`, and `_`; percent-encodes every other UTF-8 byte as uppercase `%HH`; and represents an explicitly empty `Some("")` session ID with the reserved `%EMPTY` token. - `sce hooks diff-trace` and `conversation-trace` pass producer-native session context into this existing routing argument when available. Diff-trace logging never uses the AgentTraceDb-only `oc_`/`cc_`/`pi_` prefix; skipped conversation items use their own session; batch-wide conversation insert failures use the first valid insert's session. Agent Trace DB open failures use hook-specific error events (`sce.hooks.diff_trace.agent_trace_db_open_failed` and `sce.hooks.conversation_trace.agent_trace_db_open_failed`) and do not also emit their broader write/intake events for the same failure. Session IDs remain absent from rendered record fields unless separately supplied as fields. -- File routing creates the configured directory when needed, uses owner-only create permissions on Unix, and serializes writes independently per path. -- If file logging is enabled and the selected primary file cannot be opened, appended to, or flushed, the logger retries the complete rendered record exactly once at a sibling path with `-v2` inserted before `.log`: `sce--v2.log` or `sce---v2.log`. Existing v2 files use the same create-or-append and per-path serialization behavior. +- File routing creates the configured directory when needed, uses owner-only create permissions on Unix, and serializes writes through a fixed set of in-process lock stripes (see the next bullet). +- Log-file write synchronization is a static array of 64 `std::sync::Mutex<()>` stripes in `cli/src/services/observability.rs`; a path selects its stripe via a deterministic `DefaultHasher::new()` hash modulo the stripe count. Synchronization memory is constant and independent of the number of distinct log paths (no per-path allocation or eviction). Writes to the same path are serialized within one process across threads and independent `Logger` instances; distinct paths that hash to the same stripe only contend, they never fail. No cross-process coordination exists or is guaranteed. A call holds at most one stripe at a time: the primary path's guard covers persistence and retention cleanup and is released on success and failure before the v2 fallback acquires its own stripe, so primary and v2 paths sharing a stripe cannot deadlock. A poisoned stripe (a panic under the guard, realistically only inside the retention cleanup callback) fails every path on that stripe with the unchanged `failed to lock log file '': ...` error, does not trigger the fallback, and is never recovered. +- If file logging is enabled and the selected primary file cannot be opened, appended to, or flushed, the logger retries the complete rendered record exactly once at a sibling path with `-v2` inserted before `.log`: `sce--v2.log` or `sce---v2.log`. Existing v2 files use the same create-or-append and striped serialization behavior. - Successful v2 persistence suppresses the terminal `Failed to write SCE log file` diagnostic and leaves the CLI command result unchanged. If both persistence attempts fail, the logger emits one redacted terminal file-write diagnostic to stderr and continues fail-open; a partial primary append may therefore coexist with the complete fallback record. - Directory creation, primary lock acquisition, and retention cleanup failures do not trigger alternate-name generation. The fallback attempt is non-recursive: no v3, timestamped, random, or unbounded variants are tried. - After a successful write to a newly created primary or v2 SCE log file, the logger runs one best-effort retention pass over direct regular `*.log` children of `log_dir`. Existing-file appends do not scan or delete files. Cleanup keeps the resolved `log_file_retention_limit` newest files (default `10`). Files are ordered newest-first by filesystem modification time with path/name ordering as the deterministic tie-break, and older `.log` files are removed regardless of whether their names are SCE-owned.