diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 2ceca3dfe..2953f66df 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -1837,8 +1837,34 @@ jobs: - name: Dump tilt + stack logs on failure if: failure() run: | - echo "--- tilt.log (last 300 lines: coord + host-agent streams) ---" - tail -300 var/integration/tilt.log 2>/dev/null || true + # Full log minus the two DEBUG heartbeat spam lines that + # drown everything (the disagreement alarm fires 2/s for + # harness=none sessions); cap defensively at 20k lines. + echo "--- tilt.log (filtered, last 20000 lines) ---" + grep -vE "disagreement alarm|op deferred \(retryable\)" \ + var/integration/tilt.log 2>/dev/null | tail -20000 || true + # The control-plane's end state: which sessions/ops are + # wedged and what they're holding. + echo "--- sessions table ---" + docker exec "$(docker ps -q --filter ancestor=postgres:16 | head -1)" \ + psql -U engram -d engram -c \ + "SELECT id, status, host_id IS NOT NULL AS bound_host, sandbox_id, \ + park_rung, mem_budget_mib, evict_attempts, missing_strikes, \ + created_at, last_active_at FROM sessions ORDER BY created_at" \ + 2>/dev/null || true + echo "--- session_ops (non-terminal) ---" + docker exec "$(docker ps -q --filter ancestor=postgres:16 | head -1)" \ + psql -U engram -d engram -c \ + "SELECT id, session_id, kind, state, attempts, not_before, claimed_by \ + FROM session_ops WHERE state IN ('queued','running') ORDER BY id" \ + 2>/dev/null || true + echo "--- snapshots (latest 15) ---" + docker exec "$(docker ps -q --filter ancestor=postgres:16 | head -1)" \ + psql -U engram -d engram -c \ + "SELECT id, session_id, recoverable, disk_manifest_id IS NOT NULL AS has_disk, \ + memory_manifest_id IS NOT NULL AS has_mem, created_at \ + FROM snapshots ORDER BY created_at DESC LIMIT 15" \ + 2>/dev/null || true - name: Tear down stack if: always() diff --git a/crates/engram-coordinator/src/api/snapshot.rs b/crates/engram-coordinator/src/api/snapshot.rs index 701297cba..92551f011 100644 --- a/crates/engram-coordinator/src/api/snapshot.rs +++ b/crates/engram-coordinator/src/api/snapshot.rs @@ -742,8 +742,13 @@ pub(crate) async fn try_cancel_nominated_eviction( let meta = &state.services.meta; // Cancel any still-queued evict ops first (rung 1 proper). This also // frees the op lane so the short-lived ascent claim below can land - // (the exclusive claim requires no queued op). - let _ = meta.op_cancel_queued(id, OpKind::Evict).await; + // (the exclusive claim requires no queued op). The RESULT threads + // into the ascent: it is the causal half of the non-parked gate + // (cancelled-a-queued-evict = the eviction never ran). + let cancelled_nomination = meta + .op_cancel_queued(id, OpKind::Evict) + .await + .unwrap_or(false); // ADR 0079 (review finding #2): the ascent MUST run under a REAL op // claim, not the old `op_running_for == None` probe + unfenced @@ -767,7 +772,9 @@ pub(crate) async fn try_cancel_nominated_eviction( .await { Ok(Some(claim)) => { - let res = ascend_evicting_to_active(state, id, claim.fence()).await; + let res = + ascend_evicting_to_active_with(state, id, claim.fence(), cancelled_nomination) + .await; match &res { Ok(_) => claim.finish(OpState::Done, None).await, Err(e) => claim.finish(OpState::Failed, Some(&e.to_string())).await, @@ -801,15 +808,35 @@ pub(crate) async fn ascend_evicting_to_active( state: &SharedState, id: SessionId, fence: SessionFence, +) -> Result { + ascend_evicting_to_active_with(state, id, fence, false).await +} + +/// [`ascend_evicting_to_active`] with the caller's own nomination-cancel +/// result threaded in: [`try_cancel_nominated_eviction`] must cancel +/// queued evicts BEFORE acquiring its short-lived claim (the exclusive +/// claim needs a free lane), which would otherwise eat the causal +/// evidence the non-parked gate below keys on. +pub(crate) async fn ascend_evicting_to_active_with( + state: &SharedState, + id: SessionId, + fence: SessionFence, + caller_cancelled_nomination: bool, ) -> Result { use engram_core::types::session_op::OpKind; // The user is back: any queued evict op (nomination, rung descent) - // is stale. Idempotent with the caller's own cancel. - let _ = state - .services - .meta - .op_cancel_queued(id, OpKind::Evict) - .await; + // is stale. Idempotent with the caller's own cancel — and the + // RESULT is load-bearing for the non-parked arm below: cancelling a + // queued evict is the causal proof the eviction has NOT run (a + // capture that landed finishes its op — it never leaves a queued + // row behind). + let cancelled_nomination = caller_cancelled_nomination + || state + .services + .meta + .op_cancel_queued(id, OpKind::Evict) + .await + .unwrap_or(false); // ADR 0074 rung 2 (parked-paused ascent): if this session was parked // by PAUSING the VM in place (park_rung == 2), the sandbox is still // bound and alive — un-pause it BEFORE flipping the row back to @@ -843,6 +870,66 @@ pub(crate) async fn ascend_evicting_to_active( .fenced_set_session_park_rung(id, fence.epoch as i64, 0, None) .await; ::metrics::counter!(crate::metrics::EVICTION_UNPARKED_PAUSED_TOTAL).increment(1); + } else { + // ADR 0101 C gave `Evicting` a THIRD shape beyond the nomination + // window and the parked-paused VM: the post-capture SETTLE + // window — the evict op already completed (capture landed, VM + // destroyed or doomed) and the session stays `Evicting` until + // the next heartbeat's eviction-final advert settles it Idle. + // Cancelling "the eviction" here is meaningless (it already + // happened), and flipping Active advertised a session over a + // destroyed sandbox — the e2e stack caught it on main the day + // Phase C landed: no `evicted` event, "sandbox not found" on + // the first exec, and the wedged row held its reservation until + // the fleet read as full. + // + // Two gates, BOTH required (the probe alone raced the pipeline + // destroy: post-capture the FC process can still be momentarily + // alive — alive-but-doomed, PR #845 diagnostics run): + // + // 1. CAUSAL: this ascent (or its wire caller) actually + // cancelled a QUEUED evict op. A capture that landed + // finishes its op, so a cancellable queued row is proof the + // eviction never ran and the VM was never touched. No row to + // cancel → the Evicting state belongs to machinery that + // already ran (settle window / crash-orphan the scanner + // owns) → refuse. + // 2. LIVENESS: positive `probe_sandbox` proof, for the residual + // shapes where a queued row exists over a dead VM (a + // scanner-minted retry after a failed settle on a lost + // host). + // + // Refusal is cheap: the caller retries, the settle lands Idle + // within a heartbeat, and the normal snapshot resume takes + // over. + if !cancelled_nomination { + tracing::info!(session_id = %id, + "ascent: no queued evict to cancel — the eviction already ran \ + (post-capture settle window / scanner-owned row); not \ + ascending, the settle lands Idle and the resume retries"); + return Ok(false); + } + let Some(sandbox_id) = row.as_ref().and_then(|r| r.sandbox_id) else { + tracing::debug!(session_id = %id, + "ascent: evicting session has no bound sandbox; leaving it to the settle"); + return Ok(false); + }; + match state.services.host.probe_sandbox(sandbox_id).await { + Ok(p) if p.known_to_backend && p.process_alive => {} + Ok(p) => { + tracing::info!(session_id = %id, %sandbox_id, + known = p.known_to_backend, alive = p.process_alive, + "ascent: evicting session's VM is gone; not ascending — \ + resume retries after the settle/scanner"); + return Ok(false); + } + Err(e) => { + tracing::info!(session_id = %id, %sandbox_id, error = %e, + "ascent: liveness probe failed; not ascending without proof \ + of a live VM — resume retries after the settle/scanner"); + return Ok(false); + } + } } let result = match crate::session_ops::transition_with_fence(state, id, fence, SessionState::Active) @@ -2736,6 +2823,20 @@ mod evicting_gate_tests { let id = SessionId::new(); let (state, mini, _local) = crate::state::tests::build_state_for_session(evicting_session(id)); + // The nomination window has a LIVE VM and a cancellable QUEUED + // evict (requeued-with-backoff shape, lane free) — the ascent's + // two-gate check (ADR 0101 C settle-window fix) refuses phantom + // sandboxes and op-less Evicting rows. + crate::state::tests::bind_live_sandbox(&state, &mini).await; + let nom = mini + .ops + .seed_running(id, engram_core::types::session_op::OpKind::Evict); + assert!(mini.ops.requeue_with_backoff( + nom.id, + nom.epoch.expect("epoch"), + std::time::Duration::from_secs(3600), + "test: park the nomination as a queued row", + )); ensure_active(&state, id).await.expect("cancel path"); @@ -2950,27 +3051,37 @@ mod evicting_gate_tests { ); } - /// Review finding #9: a direct /resume on an Evicting session with NO - /// running evict op (the nomination window, or a parked-paused VM - /// whose evict op is already Done) ASCENDS to Active — the resume op - /// holds the one-running slot, so Evicting can only be the cancelable - /// nomination/park case. It no longer Retry-forever-behind-a- - /// nonexistent-evict. (The genuine "an evict op is RUNNING" ordering - /// case stays a retryable conflict — see - /// `resume_queued_behind_evict_runs_after_it_settles`.) + /// ADR 0101 C settle window at the RPC boundary: a resume racing the + /// post-capture window (session `Evicting`, evict op already Done, + /// NO cancellable nomination, VM destroyed) must surface a RETRYABLE + /// conflict — never the pre-fix bogus ascent that flipped Active + /// over a destroyed sandbox (PR #845 diagnostics run: "sandbox not + /// found" on the next exec). The verb's Evicting arm refuses the + /// ascent (no queued evict to cancel) and retries behind the settle; + /// with no settle in this fixture, the observe times out into the + /// retryable 409 the wire caller polls on. (The nomination-window + /// ascent lives in `ensure_active_cancels_a_nominated_eviction_inline` + /// and `session_verbs::resume_verb_ascends_evicting_instead_of_retrying`.) #[tokio::test] - async fn resume_during_evicting_nomination_ascends_to_active() { + async fn resume_during_settle_window_is_retryable_never_a_bogus_ascent() { let id = SessionId::new(); - let (state, _local) = build_state_for_session(evicting_session(id)); + let (state, _mini, _local) = + crate::state::tests::build_state_for_session(evicting_session(id)); + // No sandbox in the backend, no queued evict op: the post-capture + // settle window exactly as the D5 pipeline leaves it. - enqueue_and_observe_resume_for(&state, id, Duration::from_secs(5)) + let err = enqueue_and_observe_resume_for(&state, id, Duration::from_secs(2)) .await - .expect("a nomination-window Evicting resume must ascend, not conflict"); + .expect_err("a settle-window resume must not ascend"); + assert!( + matches!(err, ApiError::Conflict(_)), + "retryable conflict expected, got: {err}", + ); let after = state.services.meta.get_session(id).await.unwrap(); assert_eq!( after.status, - SessionState::Active, - "the resume verb ascends the nomination back to Active", + SessionState::Evicting, + "the session stays Evicting for the settle — never Active over a dead VM", ); } diff --git a/crates/engram-coordinator/src/idle_evictor.rs b/crates/engram-coordinator/src/idle_evictor.rs index 52a7bd82a..226953c29 100644 --- a/crates/engram-coordinator/src/idle_evictor.rs +++ b/crates/engram-coordinator/src/idle_evictor.rs @@ -4001,6 +4001,92 @@ mod tests { ); } + /// ADR 0101 C's third `Evicting` shape — the post-capture settle + /// window (capture landed, VM DESTROYED, session honestly `Evicting` + /// until a later heartbeat's advert settles it Idle) — must NOT be + /// ascendable: pre-fix, a resume racing that window flipped the row + /// `Active` over a destroyed sandbox (main's e2e stack: no `evicted` + /// event, "sandbox not found" on first exec, the wedged row held its + /// reservation until the fleet read as full). The ascent now probes + /// VM liveness and refuses without positive proof. + #[tokio::test] + async fn ascent_refuses_the_post_capture_settle_window() { + let session_id = engram_core::SessionId::new(); + let sandbox_root = TempDir::new().unwrap(); + let session = evicting_session(session_id); + let (state, meta) = build_state_and_meta(session, sandbox_root.path()); + let sandbox_id = state.services.host.create(process_spec()).await.unwrap(); + state + .services + .meta + .assign_session_sandbox(session_id, Some(sandbox_id)) + .await + .unwrap(); + let host_id = state + .host_registry + .host_of(sandbox_id) + .expect("sandbox routed"); + meta.session.lock().host_id = Some(host_id); + seed_host_with_free_ram(&meta, host_id, 60_000); + + // The nomination window (VM alive, a cancellable QUEUED evict — + // here in its requeued-with-backoff shape, lane free): the + // ascent must still work — the "user came back in time" fast + // path the two-gate check must not break. + assert_eq!(meta.session.lock().status, SessionState::Evicting); + let nom = meta.ops.seed_running(session_id, OpKind::Evict); + assert!(meta.ops.requeue_with_backoff( + nom.id, + nom.epoch.expect("epoch"), + std::time::Duration::from_secs(3600), + "test: park the nomination as a queued row", + )); + let ascended = crate::api::snapshot::try_cancel_nominated_eviction(&state, session_id) + .await + .expect("ascent (live VM)"); + assert!( + ascended, + "a live-VM nomination window (queued evict) still ascends" + ); + assert_eq!(meta.session.lock().status, SessionState::Active); + + // Now construct the settle window exactly as the D5 pipeline + // leaves it: status Evicting, sandbox still BOUND in PG, VM + // already destroyed on the host, no evict op running. + meta.session.lock().status = SessionState::Evicting; + state + .services + .host + .destroy(sandbox_id, engram_core::traits::SessionFence::unfenced()) + .await + .expect("destroy"); + assert!( + !state + .services + .host + .list() + .await + .unwrap() + .contains(&sandbox_id), + "the sandbox is gone (post-capture)" + ); + + wait_for_op_lane_free(&meta, session_id).await; + // The wire-path ascent (what a resume racing the settle runs). + let ascended = crate::api::snapshot::try_cancel_nominated_eviction(&state, session_id) + .await + .expect("ascent probe"); + assert!( + !ascended, + "the post-capture settle window must not ascend to Active" + ); + assert_eq!( + meta.session.lock().status, + SessionState::Evicting, + "session stays Evicting for the settle — never Active over a destroyed VM" + ); + } + /// PR #843 review (engrams): the admin drain must descend a parked /// session through the real contract — `Parked → Evicting` FIRST, /// then the NOMINATED descent op (`descend_parked_session`) — not a diff --git a/crates/engram-coordinator/src/session_verbs.rs b/crates/engram-coordinator/src/session_verbs.rs index a64132784..961d1f465 100644 --- a/crates/engram-coordinator/src/session_verbs.rs +++ b/crates/engram-coordinator/src/session_verbs.rs @@ -309,11 +309,14 @@ async fn resume_inner(ctx: &OpCtx<'_>) -> OpOutcome { // (Evicting, park_rung=2, evict op already Done) must ascend — un- // pause in ms — not Retry-forever behind a nonexistent evict. // Because THIS resume op holds the one-running slot, no evict - // pipeline is mid-capture: Evicting is the nomination window or a - // parked-paused VM, exactly the deliver verb's inline-ascent case - // (ADR 0074 rungs 1/2). Ascend under our fence; only if the ascent - // doesn't land Active (a genuine mid-eviction we couldn't cancel) - // do we fall to the ordered-behind-evict Retry. + // pipeline is mid-capture: Evicting is the nomination window, a + // parked-paused VM, or (ADR 0101 C) the post-capture SETTLE + // window — the ascent itself distinguishes them (it probes VM + // liveness and refuses the settle window, where the VM is + // already destroyed). Ascend under our fence; on `false` (mid- + // eviction we couldn't cancel, or awaiting the settle) fall to + // the Retry — the settle lands Idle within a heartbeat and the + // next attempt resumes from the snapshot. SessionState::Evicting => { match crate::api::snapshot::ascend_evicting_to_active(state, id, ctx.fence()).await { Ok(true) => OpOutcome::Done, @@ -763,10 +766,13 @@ async fn deliver(ctx: &OpCtx<'_>) -> OpOutcome { SessionState::Active => true, // ADR 0074 rungs 1+2, under the op: we HOLD the session's // one-running slot, so no evict pipeline is mid-capture — - // Evicting here is the nomination window or a parked-paused - // VM. Ascend inline (cancel queued evicts, un-pause a parked - // VM, flip Active) instead of burning a full evict+resume - // cycle on a session whose VM is alive. + // Evicting here is the nomination window, a parked-paused + // VM, or (ADR 0101 C) the post-capture settle window; the + // ascent probes VM liveness and refuses the last (false → + // the resume-enqueue arm below orders a resume behind the + // settle). Ascend inline (cancel queued evicts, un-pause a + // parked VM, flip Active) instead of burning a full + // evict+resume cycle on a session whose VM is alive. SessionState::Evicting => { match crate::api::snapshot::ascend_evicting_to_active(state, id, ctx.fence()).await { @@ -1913,6 +1919,10 @@ mod tests { let id = SessionId::new(); let (state, mini, _local) = crate::state::tests::build_state_for_session(evicting_session(id)); + // The nomination window has a LIVE VM and a cancellable queued + // evict — the ascent's two-gate check (ADR 0101 C settle-window + // fix) refuses phantom sandboxes and op-less Evicting rows. + crate::state::tests::bind_live_sandbox(&state, &mini).await; let op = match state .services @@ -1924,6 +1934,23 @@ mod tests { EnqueueOutcome::Claimed(op) => op, other => panic!("lane busy: {other:?}"), }; + // The nomination evict queues BEHIND the running resume op — + // exactly the shape the verb's inline ascent cancels. + assert!(matches!( + state + .services + .meta + .op_enqueue_and_claim( + id, + OpKind::Evict, + serde_json::json!({ "target": "idle", "allow_park": true, "nominated": false }), + None, + "test-pod", + ) + .await + .expect("enqueue nomination evict"), + EnqueueOutcome::Queued(_) + )); let op_id = op.id; crate::session_ops::drive_claimed(&state, op).await; diff --git a/crates/engram-coordinator/src/state.rs b/crates/engram-coordinator/src/state.rs index 029628fe7..147b78c5d 100644 --- a/crates/engram-coordinator/src/state.rs +++ b/crates/engram-coordinator/src/state.rs @@ -2058,6 +2058,37 @@ pub(crate) mod tests { (state, meta, local) } + /// Create a REAL sandbox in the state's process backend and bind it + /// to the MiniMeta session. Nomination-window fixtures need this + /// since the ascent's liveness gate (ADR 0101 C settle-window fix): + /// an `Evicting` row whose bound sandbox does not exist in the + /// backend is the post-capture settle window and correctly refuses + /// to ascend — a fixture with a phantom `SandboxId::new()` models + /// THAT, not the live nomination window. + pub(crate) async fn bind_live_sandbox( + state: &crate::state::SharedState, + mini: &Arc, + ) -> engram_core::SandboxId { + use engram_core::types::sandbox::{CpuLimit, DiskLimit, MemoryLimit, SandboxSpec}; + let spec = SandboxSpec { + image: "state-test".into(), + rootfs_source: None, + image_uri: None, + rootfs_manifest: None, + cpu: CpuLimit { vcpus: 1 }, + memory: MemoryLimit { max_mib: 256 }, + disk: DiskLimit { max_gib: 1 }, + ttl: None, + env: Default::default(), + workdir: None, + network: Default::default(), + aux_ro_drives: Vec::new(), + }; + let sb = state.services.host.create(spec).await.expect("create"); + mini.session.lock().sandbox_id = Some(sb); + sb + } + #[async_trait] impl MetadataStore for MiniMeta { /// ADR 0073: derive the idle-scan candidate from the mock's own diff --git a/docs/adr/0101-amortized-memory-durability.md b/docs/adr/0101-amortized-memory-durability.md index 728a498fd..295ac0eb8 100644 --- a/docs/adr/0101-amortized-memory-durability.md +++ b/docs/adr/0101-amortized-memory-durability.md @@ -306,3 +306,19 @@ The lesson for this ADR's ledger: **a new lifecycle state is a schema change for every hand-spelled status set in the system.** The typed enum was wildcard-audited in #837; the SQL literals were not. They now share one source. + +**Second same-day fallout (the settle-window ascent).** Phase C's honest +`Evicting` gave the state a third shape nobody re-audited: post-capture, +VM destroyed, settle pending. `ascend_evicting_to_active` (the ADR 0074 +rung-ascent) still assumed "Evicting = nomination window or parked-paused +VM" and flipped such sessions straight to `Active` over a destroyed +sandbox — a resume racing the ≤1-heartbeat settle window hit it every +time (no `evicted` event, "sandbox not found" on first exec, the wedged +row holding its reservation). The e2e stack suite caught it — but on +main, the day Phase C landed: the #836/#838-#841 batch was admin-merged +while their combined runs were red/cancelled, so the lane's verdict was +never enforced (the exact admin-mass-merge failure mode AGENTS.md warns +about). Fix: the ascent's non-parked arm now requires POSITIVE +`probe_sandbox` proof of a live VM and otherwise returns "not ascended" — +callers already retry, the settle lands Idle, and the normal snapshot +resume takes over.