# [AZ-776 follow-up] derkachi_1min AC-1/2/5/6 fail on Jetson — VioOutput.emitted_at_ns clock-mismatch with FC IMU timebase

> **SCOPE UPDATE (2026-05-26, cycle-4 planning)**
>
> After user decision to switch the primary replay path to user-supplied (video, CSV) pairs (see AZ-894 / AZ-895 / AZ-896 / AZ-897), the tlog-adapter path becomes **audit-only** and this ticket is **no longer bench-blocking**. It remains a real bug and stays open for any future tlog-only flight (flights that ship with a `.tlog` but no companion `data_imu.csv`).
>
> **Priority**: backlog (deprioritised from cycle-4 candidate)
> **Bench-blocking?**: no — AZ-894 supersedes
> **Production-blocking?**: no — production single-clock model never goes through the tlog adapter
> **Complexity**: unchanged (5 SP)

**Task**: AZ-848_jetson_eskf_out_of_order_regression
**Name**: Repair the VioOutput contract — emitted_at_ns must use the frame's timeline timestamp, not process monotonic_ns, so it aligns with the FC IMU timebase that C5 ESKF tracks alongside it
**Description**: On the Jetson e2e harness (`scripts/run-tests-jetson.sh`), four tests in `tests/e2e/replay/test_derkachi_1min.py` (AC-1, AC-5, AC-6 realtime, AC-6 asap) fail with identical deterministic root cause `EstimatorFatalError('eskf filter divergence on vio: mahalanobis²=109.765 > 100.0')` at frame 3, preceded by `c5.state.eskf_out_of_order` from `imu_window` (ts_ns=187_370_418_000 < last_added_ts_ns=1_187_232_637_925_619 — ~5–6 orders of magnitude apart). Plus 1 XPASS on `test_ac3_within_100m_80pct_of_ticks` (probable vacuous-pass — when the binary exits 1 on frame 3, the ≥80 % within 100 m assertion evaluates over zero emissions).

**Revised root cause (2026-05-26 evidence-based investigation)**: NOT an IMU-vs-IMU clock-source mismatch (the original hypothesis was incorrect — RAW_IMU.time_usec and SCALED_IMU2.time_boot_ms share the same FC-boot-relative timebase in the Derkachi tlog: 187–634 s). The actual mismatch is **VioOutput.emitted_at_ns** vs **ImuWindow.ts_end_ns**:

| Source | Code site | Value on Jetson | Timebase |
|---|---|---|---|
| `VioOutput.emitted_at_ns` | `klt_ransac.py:274` — `self._clock.monotonic_ns()` | ~1.187·10¹⁵ ns (≈ 13.7 days — Jetson uptime when the run started) | Process monotonic |
| `imu_window.ts_end_ns` | `tlog_replay_adapter.py:710` — `time_usec * 1000` | ~1.87·10¹¹ ns (≈ 187 s — Pixhawk boot-relative) | FC-boot-relative |

C5 ESKF tracks `_last_added_ts_ns` across BOTH `add_vio` and `add_fc_imu`. Frame 0: `add_vio` sets `_last_added_ts_ns = 1.187·10¹⁵`. Frame 1: `add_fc_imu` checks `1.87·10¹¹ + ~10⁸ < 1.187·10¹⁵` → out_of_order degraded → next add_vio with corrupted nominal state → mahalanobis² = 109.76 > 100 → fatal divergence at frame 3.

**Why this hides on Tier-1**: the test is `@pytest.mark.tier2_only` (skipped on workstation runs). Unit tests use mocked VIO with synthetic clocks, so the contract clash never surfaces.

**Why this hides on a short-uptime Jetson**: a Jetson booted < ~10 s ago would have monotonic_ns smaller than the FC's boot-relative timestamps; the inequality flips and the bug masquerades as "intermittent passes". The 13.7-day-uptime test box made it deterministic.

**Complexity**: 5 SP (revised up from 3 — the fix touches the C1 contract: `VioOutput.emitted_at_ns` semantics + every C1 strategy that populates it + `_docs/02_document/contracts/c1_vio/` doc + every consumer of `vio.emitted_at_ns` in C5 / C13 / FDR. Plus a determinism test that records monotonic_ns vs frame_ts_ns at frame 0 to lock the invariant in.)
**Dependencies**: AZ-776 (closed; produced the verification gap that hid this regression)
**Related**: AZ-883 (SCALED_IMU2 latent ts_ns=0 bug; uncovered during this investigation; separate ticket)
**Component**: c1_vio (`klt_ransac.py`, `bench/okvis2.py`, `bench/vins_mono.py`, `_facade_spine.py`) + `_types/nav.py` (VioOutput dataclass) + c5_state (`eskf_baseline.py:add_vio` consumes the field) + c13_fdr (consumes `emitted_at_ns` per the docstring's "adaptive-gating decisions")
**Tracker**: AZ-848 (https://denyspopov.atlassian.net/browse/AZ-848)
**Parent Epic**: (none — bug surfaced in cycle 3 Step 11)

Jira AZ-848 is the authoritative spec; this file is the in-workspace mirror.

## Symptom

On Jetson (`scripts/run-tests-jetson.sh`), four tests in `tests/e2e/replay/test_derkachi_1min.py` fail with identical root cause:

- `test_ac1_exits_0_jsonl_count_match`
- `test_ac5_determinism_two_runs_diff`
- `test_ac6_pace_realtime_60s_within_5pct`
- `test_ac6_pace_asap_under_30s`

All four assert `gps-denied-replay` exits 0; the binary actually exits 1 on frame 3 with:

```
ERROR c5_state.eskf_baseline c5.state.eskf_out_of_order
  source=imu_window ts_ns=187,370,418,000 last_added_ts_ns=1,187,232,637,925,619
ERROR c5_state.eskf_baseline c5.state.eskf_filter_divergence
  source=vio mahalanobis_sq=109.76467866548009 threshold_sq=100.0
ERROR runtime_root.replay_loop replay_loop.state_add_vio_fatal
  frame=3 EstimatorFatalError('eskf filter divergence on vio: mahalanobis²=109.765 > 100.0')
```

Mahalanobis distance is identical (109.765) across all four runs — fully deterministic on the Derkachi 1-min clip.

Additionally, `test_ac3_within_100m_80pct_of_ticks` reports XPASS (was `@xfail` referencing AZ-777). Appears to be a symptom of the same bug — with the binary exiting code 1 before any GPS-denied emissions land, the `≥ 80 % within 100 m` assertion evaluates against an empty population and passes vacuously. The XPASS is NOT honest evidence that AZ-777 has been completed.

## Origin — AZ-776 verification gap

Commit `8de2716 [AZ-776] Open-loop ESKF composition profile via c4_pose.enabled` removed `@pytest.mark.xfail` decorators from AC-1 (line 61), AC-2 (line 138), AC-5 (line 413), AC-6 realtime (line 453), AC-6 asap (line 479) of `test_derkachi_1min.py`. The AZ-776 spec (`_docs/02_tasks/done/AZ-776_eskf_open_loop_composition_profile.md`) claims under AC-7:

> `_run_replay_loop` in `runtime_root/__init__.py` is exercised end-to-end on Jetson by a non-`xfail` integration test (AC-1, AC-2, AC-5, AC-6 realtime, AC-6 asap in `tests/e2e/replay/test_derkachi_1min.py` un-xfail **and pass**).

This was not honored — AZ-776 closed without an honest Jetson run. Predates the `meta-rule.mdc` "Real Results, Not Simulated Ones" rule (added 2026-05) that would have caught it.

## Cycle-3 scope (not the cause)

Cycle-3 Step 11 (2026-05-24) surfaced this on the first full Jetson run since cycle 1. Cycle-3's only src change was commit `fd52cc9 [AZ-845][AZ-846][AZ-847] Refactor 02: relocate RouteSpec + widen lint` — four files, all in `_types/route.py` (new), `c11_tile_manager/route_client.py`, `replay_input/__init__.py`, `replay_input/tlog_route.py`. None of `c5_state`, `c8_fc_adapter`, `runtime_root` were touched. Most recent change to `c5_state/eskf_baseline.py` is AZ-389; to `c8_fc_adapter/tlog_replay_adapter.py` is AZ-398. Both pre-date cycle 1. The latent contract clash was always there — Jetson uptime + an un-`xfail`ed test combined to make it deterministic.

## Diagnosis evidence (2026-05-26)

`/tmp/inspect_tlog.py` (ad-hoc pymavlink probe against `_docs/00_problem/input_data/flight_derkachi/derkachi.tlog`) — outputs preserved in this session's chat history:

- 4326 RAW_IMU msgs, time_usec ∈ [187,274,914 ; 633,952,656] µs (boot-relative ~187s–~634s)
- 4330 SCALED_IMU2 msgs, time_boot_ms ∈ [187,274 ; 633,954] ms (same timebase, same range)
- Both IMU types share the FC's boot timebase → original "two-IMU-clock-source mismatch" hypothesis is REFUTED
- `klt_ransac.py:274` populates `VioOutput.emitted_at_ns = self._clock.monotonic_ns()` → 1.187·10¹⁵ ns on the test Jetson (uptime 13.7 days)
- `_types/nav.py:158` documents this contract explicitly: "`emitted_at_ns` is `time.monotonic_ns` at output time."
- `eskf_baseline.py:492` reads `ts_ns = vio.emitted_at_ns` and stores it in `_last_added_ts_ns` — the same field that `add_fc_imu` checks against `imu_window.ts_end_ns` (FC-boot-relative)
- Confirmed: the inequality direction MATCHES the AZ-848 error log (`ts_ns=187,370,418,000 < last_added_ts_ns=1,187,232,637,925,619`)

## Affected files

- `src/gps_denied_onboard/_types/nav.py` — `VioOutput.emitted_at_ns` field + docstring at line 158 (contract change site)
- `src/gps_denied_onboard/components/c1_vio/klt_ransac.py:274,425,463,592–619` — every site that fills `emitted_at_ns`
- `src/gps_denied_onboard/components/c1_vio/bench/okvis2.py`, `vins_mono.py` — other C1 strategies that fill `emitted_at_ns`
- `src/gps_denied_onboard/components/c1_vio/_facade_spine.py` — `frame_ts_ns(frame)` is the existing helper that should be the new source of truth
- `src/gps_denied_onboard/components/c5_state/eskf_baseline.py:492,502,565` — already reads `vio.emitted_at_ns`; no API change needed once the field's semantics are fixed
- `src/gps_denied_onboard/components/c13_fdr/**` — read `emitted_at_ns` per the docstring's "adaptive-gating decisions"; behavior change must be evaluated
- `_docs/02_document/contracts/c1_vio/` — contract docs need re-version (semantic change to a public field)
- `tests/e2e/replay/test_derkachi_1min.py` — the failing tests; AC-3 XPASS handling per AC-4 below

## Repro

```
bash scripts/run-tests-jetson.sh
# pytest report (after ~5 min):
#   tests/e2e/replay/test_derkachi_1min.py::test_ac1_exits_0_jsonl_count_match FAILED
#   tests/e2e/replay/test_derkachi_1min.py::test_ac5_determinism_two_runs_diff FAILED
#   tests/e2e/replay/test_derkachi_1min.py::test_ac6_pace_realtime_60s_within_5pct FAILED
#   tests/e2e/replay/test_derkachi_1min.py::test_ac6_pace_asap_under_30s FAILED
#   tests/e2e/replay/test_derkachi_1min.py::test_ac3_within_100m_80pct_of_ticks XPASS
```

## Acceptance Criteria

| # | Criterion |
|---|-----------|
| AC-1 | The `VioOutput.emitted_at_ns` contract docstring (`_types/nav.py:158`) no longer says "monotonic_ns at output time"; the field's semantics are documented as "the frame's timeline timestamp aligned with C8 FC IMU timebase, so C5 ESKF can compare against `imu_window.ts_end_ns` without a clock-source mismatch". A version bump is recorded in `_docs/02_document/contracts/c1_vio/`. |
| AC-2 | Every C1 strategy (`klt_ransac.py`, `bench/okvis2.py`, `bench/vins_mono.py`) populates `emitted_at_ns` from the frame's timestamp (via `frame_ts_ns(frame)` or the strategy's own equivalent), NOT from `monotonic_ns()`. A unit test per strategy asserts the field value equals `frame_ts_ns(frame)`. |
| AC-3 | A determinism test reads two consecutive frames' `VioOutput.emitted_at_ns` values and asserts they are equal to `frame_ts_ns(frame_n)` and `frame_ts_ns(frame_n+1)` respectively — locking the new invariant. |
| AC-4 | Fix lands and `test_derkachi_1min.py::test_ac1_exits_0_jsonl_count_match` PASSES on Jetson with `RUN_REPLAY_E2E=1` — no `@xfail` re-add. |
| AC-5 | `test_ac5_determinism_two_runs_diff`, `test_ac6_pace_realtime_60s_within_5pct`, `test_ac6_pace_asap_under_30s` also PASS on Jetson. |
| AC-6 | XPASS on `test_ac3_within_100m_80pct_of_ticks` is investigated. If symptom of the same bug, returns to honest XFAIL referencing AZ-777 once binary exits 0 cleanly. If genuine pass, AZ-777 is closed instead. |
| AC-7 | C13 FDR consumers of `emitted_at_ns` are audited — any code path that relied on the field being monotonic-clock-wall-time has its behavior preserved via an explicit `time.monotonic_ns()` recorded under a different name (e.g., `recorded_at_ns`) or its expectation is documented as "frame timeline; not wall clock". |
| AC-8 | `meta-rule.mdc` "Real Results" gate is honored — no ticket may close `Done` until the operator has eyes on a green Jetson run log line. |

## Notes

- Tracker context: surfaced `cycle: 3, step: 11` on 2026-05-24; root cause re-diagnosed 2026-05-26 (operator-supervised investigation against the actual Derkachi tlog).
- Local unit suite (`pytest tests/unit/`) passes 2303 / 0 fail / 86 legitimate skips after C12 cold-start threshold relax (`05f1143 [AZ-844]`).
- Cycle 3 Step 11 verdict was PASS for cycle-3-scope; this ticket captures the wider Jetson regression for next cycle.
- Local mirror created retroactively 2026-05-24 (cycle 3 Step 12 entry) — Jira AZ-848 filed 2026-05-24 was the original signal; mirror was missing.
- 2026-05-26: spec materially revised after evidence-based investigation refuted the original "two-IMU-clock-source mismatch" hypothesis. The corrected diagnosis points at the C1 contract (`VioOutput.emitted_at_ns` semantics), not at the C8 adapter. The SCALED_IMU2 latent bug surfaced during this investigation is split out as AZ-883 to keep this ticket's scope tight.

## References

- Jira: https://denyspopov.atlassian.net/browse/AZ-848
- Run-tests report: `_docs/03_implementation/run_tests_step11_report.md` (Cycle 3 closeout, lines 617–635)
- Origin spec: `_docs/02_tasks/done/AZ-776_eskf_open_loop_composition_profile.md`
- Related: AZ-777 (the XFAIL the AC-6 XPASS originally referenced); AZ-883 (SCALED_IMU2 latent bug)
