fix(#760): pin the health clock in test fixtures so a handler's HTTP status cannot depend on machine load

crates/eqoxide-http/Cargo.toml

@@ -15,7 +15,9 @@ path = "src/lib.rs"
 # tests, which need `eq_net::packet_handler` — an app-crate module BELOW which http sits) can build
 # an `HttpState` and hit the observe router. Off in normal builds; the release binary never has it.
 # Forwards to eqoxide-nav so `testkit::empty_state` can build a real `ZoneAssetState::Ready`.
-test-fixtures = ["eqoxide-nav/test-fixtures"]
+# Forwards to eqoxide-ipc so `testkit::empty_state` can build a `NetHealth::frozen_at` — the pinned
+# health clock that stops a downstream handler test's HTTP status depending on machine load (#760).
+test-fixtures = ["eqoxide-nav/test-fixtures", "eqoxide-ipc/test-fixtures"]
 
 [dependencies]
 # eqoxide-http is the agent-facing REST API (axum). It sits at the TOP of the extracted-crate stack:

crates/eqoxide-http/src/combat.rs

@@ -558,6 +558,90 @@ mod tests {
         assert!(command.take_cast().is_none(), "an empty gem must not be queued as a cast");
     }
 
+    /// #760: the request above must answer 409 for reasons that have nothing to do with how long the
+    /// test took to get there. `empty_state()` used to stamp its net-health clocks with
+    /// `Instant::now()` and `HttpState::health()` used to read them against `Instant::now()` again,
+    /// so `snapshot_age_ms` was "however long this test has been running" — and on a loaded box that
+    /// crossed `SESSION_STALE_TICK_MS` (5s) and `require_live_session` answered `503` from the very
+    /// first line of `post_cast`, before any gem was ever looked at.
+    ///
+    /// MEASURED, on this code, before the fix: the same request with a 5.1s sleep in front of it
+    /// returned `503 … the network thread has not ticked in 5100ms`. So the reported mechanism is
+    /// the real one and the 503 really does come from this guard on this route.
+    ///
+    /// This asserts the FIXTURE property that removes it, not a timing: real wall time passes here
+    /// (the sleep is deliberate and observable via `Instant::elapsed`) and the fixture's projected
+    /// ages stay exactly 0, because they are measured against a clock pinned at the fixture's own
+    /// construction instant. A 50ms sleep and a 5s one are the same assertion — `now - stamp` where
+    /// `now == stamp` is 0 for every duration — so this does not need to cost the suite 5 seconds
+    /// to prove the 5-second case.
+    #[tokio::test]
+    async fn handler_fixture_ages_do_not_track_the_wall_clock() {
+        let state = empty_state();
+        assert!(state.net_health.lock().unwrap().clock.is_frozen(),
+            "the handler fixture must pin its health clock, or every gated handler test races \
+             SESSION_STALE_TICK_MS (#760)");
+        let started = std::time::Instant::now();
+        std::thread::sleep(std::time::Duration::from_millis(50));
+        assert!(started.elapsed() >= std::time::Duration::from_millis(50),
+            "precondition: real wall time really did pass");
+        let h = state.health();
+        assert_eq!(h.snapshot_age_ms, 0,
+            "the fixture's tick age must be pinned at 0, not the {}ms of wall clock that just \
+             elapsed — this is the age require_live_session 503s on (#760)", started.elapsed().as_millis());
+        assert_eq!(h.link_age_ms, 0, "the fixture's link age must be pinned too — it feeds `connected`");
+        assert_eq!(h.last_packet_age_ms, 0, "the fixture's packet age must be pinned too");
+        assert!(crate::require_live_session(&state).is_ok(),
+            "and the verdict the pinned ages produce is a live session");
+    }
+
+    /// #760, end to end and DETERMINISTIC: the exact request
+    /// `cast_empty_gem_is_409_and_queues_nothing` drives, served after more than
+    /// `SESSION_STALE_TICK_MS` (5s) of real wall time has passed since the fixture was built.
+    ///
+    /// This is the load condition the flake needs, forced rather than waited for — and forced in the
+    /// only direction that matters: a busy machine makes the sleep LONGER, never shorter, so this
+    /// test cannot become less severe under load. On the pre-fix code the measured answer here was
+    /// `503 … the network thread has not ticked in 5100ms`; the whole 409 body was never reached.
+    ///
+    /// It costs the suite ~5s. That is the price of turning "fails sometimes, on someone else's PR"
+    /// into a check that fails every time if the fix is undone.
+    #[tokio::test]
+    async fn cast_empty_gem_is_still_409_after_the_stale_session_bound_has_elapsed() {
+        let state = empty_state();
+        set_gs(&state, |gs| {
+            gs.mem_spells = [eqoxide_core::game_state::EMPTY_GEM; 9];
+            gs.mem_spells[0] = 202;
+        });
+        let net_health = state.net_health.clone();
+        let command = state.command.clone();
+        let app = router().with_state(state);
+        // > SESSION_STALE_TICK_MS. `std::thread::sleep`, not `tokio::time::sleep`: the clock under
+        // test is `std::time::Instant`, which tokio's virtual time does not move.
+        std::thread::sleep(std::time::Duration::from_millis(5_100));
+        let req = Request::post("/cast")
+            .header("content-type", "application/json")
+            .body(Body::from(r#"{"gem":7}"#)).unwrap();
+        let resp = app.oneshot(req).await.unwrap();
+        let status = resp.status();
+        let text = body_text(resp).await;
+        assert_eq!(status, StatusCode::CONFLICT,
+            "5.1s of wall time must not change this request's answer — it is an empty gem either \
+             way (#760). Body was: {text}");
+        assert!(text.contains("empty"), "and for the real reason, not a stale-session one: {text}");
+        // ONE lock, both reads. Two `net_health.lock()` calls in a single `assert_eq!` self-deadlock:
+        // the left guard is a temporary that lives to the end of the statement, and `std::sync::Mutex`
+        // is not reentrant — the second lock blocks forever. Measured: this test hung a whole
+        // `eqoxide-http` test binary until it was written this way.
+        let (clock_now, tick_stamp) = {
+            let h = net_health.lock().unwrap();
+            (h.clock.now(), h.last_tick)
+        };
+        assert_eq!(clock_now, tick_stamp,
+                   "the fixture's clock is still pinned to its own tick stamp after 5.1s");
+        assert!(command.take_cast().is_none(), "and still nothing was queued");
+    }
+
     // ── A3 Migration 3 (#448): POST /v1/combat/cast reports the TRUE outcome, not a queued 200 ──
 
     use eqoxide_command::{CastEnd, CommandResult};
@@ -767,3 +851,13 @@ mod tests {
             "message should name the real cause, not the unrelated \"provide gem/spell_id\" default-validation text: {text}");
     }
 }
+
+/// Reach control for `observe::tests::no_past_dated_net_health_stamp_is_taken_from_a_clock_other_than_the_one_that_reads_it` (#760/C1).
+///
+/// That guard scans this file's source text. A scanner that silently stops early — as it did, when
+/// a `/*` inside a route glob in a doc comment latched its block-comment state — reports
+/// a clean scan of a corpus it never read, which is a confident falsehood. The guard asserts it can
+/// SEE this constant; because it is the last item in the file, seeing it proves the scan arrived at
+/// the end. **Keep it last.**
+#[cfg(test)]
+pub(crate) const GUARD_REACH_SENTINEL_COMBAT: u8 = 0;

crates/eqoxide-http/src/lib.rs

@@ -787,15 +787,22 @@ impl HttpState {
     /// renderer, not the network thread — has to be alive for the answer to be honest.
     pub(crate) fn health(&self) -> Health {
         let h = *self.net_health.lock().unwrap();
-        let link_age       = h.last_datagram.elapsed();
-        let last_packet_ago = h.last_packet.elapsed();
+        // #760: EVERY age below is measured back from `h.clock`, never from a bare `Instant::now()`.
+        // In production that clock IS `Instant::now()` (`HealthClock::WALL`, the only clock a
+        // non-test build can construct), so this is the same read-time measurement #343 requires.
+        // In a TEST it is pinned, which is what makes a fixture's liveness verdict a pure function
+        // of the fixture instead of a function of how long the test took to reach this line. If you
+        // add a field here, derive its age from `h.clock` too — a stray `.elapsed()` silently opts
+        // that one field back into wall time and re-arms #760's flake for it.
+        let link_age        = h.clock.age_of(h.last_datagram);
+        let last_packet_ago = h.clock.age_of(h.last_packet);
         // #371: the active-probe verdict, all measured at read time (like every other health field,
         // per #343 — never cached, so no live publisher has to run for the answer to stay honest).
         // NOTE: the timeout check is measured against `first_unanswered_probe_sent`, NOT
         // `last_probe_sent` — the latter is bumped by every 30s resend and would let a permanently
         // wedged zone re-earn the 10s in-flight grace window forever (the #371-followup bug).
-        let probe_sent_ago  = h.first_unanswered_probe_sent.map(|t| t.elapsed());
-        let probe_reply_ago = h.last_probe_reply.map(|t| t.elapsed());
+        let probe_sent_ago  = h.first_unanswered_probe_sent.map(|t| h.clock.age_of(t));
+        let probe_reply_ago = h.last_probe_reply.map(|t| h.clock.age_of(t));
         // #470: `world_responsive` must know the LINK is dead. When a failed world-reconnect kills the
         // net thread the prober dies too, so no probe is ever outstanding — without this, the "no
         // probe" branch reported a zombie session alive forever. `connected` here is the SAME value
@@ -819,12 +826,12 @@ impl HttpState {
         // #656: the io-starvation alert. Measured HERE, at read time (#343's rule for every age in
         // this payload) — `last_send_pressure_at` is a timestamp, never a pre-computed bool, so the
         // alert cannot go stale between the net thread's last write and this HTTP read.
-        let send_pressure_ago = h.last_send_pressure_at.map(|t| t.elapsed());
+        let send_pressure_ago = h.last_send_pressure_at.map(|t| h.clock.age_of(t));
         let send_starved = eqoxide_ipc::send_starved(h.send_pressure_streak, send_pressure_ago);
         Health {
             link_age_ms:        link_age.as_millis() as u64,
             last_packet_age_ms: last_packet_ago.as_millis() as u64,
-            snapshot_age_ms:    h.last_tick.elapsed().as_millis() as u64,
+            snapshot_age_ms:    h.clock.age_of(h.last_tick).as_millis() as u64,
             // Link liveness, NOT world activity — see `NetHealth`. An idle session goes 40+s with
             // no application packet while the session layer keeps ACKing; calling that "disconnected"
             // would be just as much a lie as #343's frozen `connected: true`.
@@ -840,7 +847,7 @@ impl HttpState {
             send_starved,
             send_failures_unretried: h.send_failures_unretried,
             last_send_error:         h.last_send_error_kind,
-            last_send_error_age_ms:  h.last_send_error_at.map(|t| t.elapsed().as_millis() as u64),
+            last_send_error_age_ms:  h.last_send_error_at.map(|t| h.clock.age_of(t).as_millis() as u64),
             reliable_abandoned:      h.reliable_abandoned,
             session_drop:            h.session_drop,
         }
@@ -1118,21 +1125,25 @@ mod player_view_datum_tests {
 #[cfg(test)]
 mod live_session_guard_tests {
     use super::*;
-    use crate::testkit::{ago, empty_state};
+    use crate::testkit::empty_state;
     use axum::body::Body;
     use axum::http::{Request, StatusCode};
     use tower::ServiceExt;
 
     /// Overwrite the three net-health clocks (ages in seconds) to model a given liveness state; the
     /// probe clocks are left at their `Default` (`None`), which is what the guard reads through
     /// `health()` but never keys its verdict on.
+    ///
+    /// #760: the clock is PINNED at the same instant the stamps are taken from, so the ages
+    /// `health()` reads back are exactly the numbers passed in. Before, the stamps were wall-clock
+    /// and the read happened later, so the real age was `arg + (however long the test then took)`.
+    /// By construction that put `tick_just_under_bound_passes` (1s, bound 5s) on a 4s margin that
+    /// machine load could eat — the same mechanism as #760, one test over. Not observed failing;
+    /// stated as a derivation from the old code, not as a measurement.
     fn set_clocks(s: &HttpState, datagram_ago: u64, tick_ago: u64, packet_ago: u64) {
-        *s.net_health.lock().unwrap() = NetHealth {
-            last_datagram: ago(datagram_ago),
-            last_packet:   ago(packet_ago),
-            last_tick:     ago(tick_ago),
-            ..NetHealth::default()
-        };
+        *s.net_health.lock().unwrap() = NetHealth::frozen_at(
+            std::time::Instant::now(), datagram_ago, tick_ago, packet_ago,
+        );
     }
 
     /// A freshly-built state (all clocks = now) is LIVE — the guard must pass. This is why every
@@ -1142,6 +1153,50 @@ mod live_session_guard_tests {
         assert!(require_live_session(&empty_state()).is_ok());
     }
 
+    /// #760: `health()` measures every age against `NetHealth::clock`, not against a fresh
+    /// `Instant::now()`. Proved by pinning the clock 7s AHEAD of the stamps and reading the ages
+    /// back exactly — no sleeping, no tolerance window. Swap any `h.clock.age_of(x)` in `health()`
+    /// back to `x.elapsed()` and the corresponding assertion here reads ~0 instead of 7000.
+    ///
+    /// This is the half that makes the frozen fixture mean anything: a fixture can pin its clock all
+    /// it likes, but only if the projection actually reads that clock does the wall clock stop
+    /// deciding a test's HTTP status.
+    #[test]
+    fn health_ages_are_measured_against_the_injected_clock() {
+        let s = empty_state();
+        let stamped = std::time::Instant::now();
+        *s.net_health.lock().unwrap() = NetHealth {
+            // Clock pinned 7s after the stamps → every age must read exactly 7000ms.
+            clock: HealthClock::frozen_at(stamped + std::time::Duration::from_secs(7)),
+            last_datagram: stamped,
+            last_packet:   stamped,
+            last_tick:     stamped,
+            ..NetHealth::default()
+        };
+        let h = s.health();
+        assert_eq!(h.snapshot_age_ms, 7_000, "snapshot_age_ms must come from the injected clock");
+        assert_eq!(h.link_age_ms, 7_000, "link_age_ms must come from the injected clock");
+        assert_eq!(h.last_packet_age_ms, 7_000, "last_packet_age_ms must come from the injected clock");
+        // And the guard's verdict follows that injected reading, not the wall: 7s > 5s bound.
+        let (code, msg) = require_live_session(&s).unwrap_err();
+        assert_eq!(code, StatusCode::SERVICE_UNAVAILABLE);
+        assert!(msg.contains("has not ticked in 7000ms"), "message: {msg}");
+    }
+
+    /// #760: the shared handler fixture pins its clock, so no handler test's status can depend on
+    /// how loaded the machine was. Delete the `frozen_at` in `testkit::empty_state` (back to
+    /// `NetHealth::default()`) and this goes RED immediately — `is_frozen()` is false — which is the
+    /// point: the property is structural, not a margin.
+    #[test]
+    fn handler_fixture_pins_its_health_clock() {
+        let s = empty_state();
+        assert!(s.net_health.lock().unwrap().clock.is_frozen(),
+            "empty_state() must pin the health clock so gated handler tests cannot age into a 503");
+        let h = s.health();
+        assert_eq!((h.snapshot_age_ms, h.link_age_ms, h.last_packet_age_ms), (0, 0, 0),
+            "a pinned fixture's ages are exactly zero, not merely small");
+    }
+
     /// A healthy but IDLE session — connected + ticking, yet the WORLD has been quiet for a full
     /// minute (`last_packet` 60s stale) — must NOT be rejected. This is the #343 over-rejection guard:
     /// keying the verdict on `last_packet` (world quiet) instead of `connected`/`last_tick` (thread
@@ -1288,3 +1343,13 @@ mod health_serde_tests {
             "a live session must serialize session_drop as an explicit null (#642)");
     }
 }
+
+/// Reach control for `observe::tests::no_past_dated_net_health_stamp_is_taken_from_a_clock_other_than_the_one_that_reads_it` (#760/C1).
+///
+/// That guard scans this file's source text. A scanner that silently stops early — as it did, when
+/// a `/*` inside a route glob in a doc comment latched its block-comment state — reports
+/// a clean scan of a corpus it never read, which is a confident falsehood. The guard asserts it can
+/// SEE this constant; because it is the last item in the file, seeing it proves the scan arrived at
+/// the end. **Keep it last.**
+#[cfg(test)]
+pub(crate) const GUARD_REACH_SENTINEL_LIB: u8 = 0;