From c7be6416f2934aa5f1a3ae11f16b5a2a508b4932 Mon Sep 17 00:00:00 2001 From: Logan Cusano Date: Sun, 23 Aug 2026 01:30:01 -0400 Subject: [PATCH] Surface LLM correlation fields in debug view; fix unit-continuity path MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit /admin/debug/correlation stripped corr_consensus and the corr_llm_* fields that upload.py's consensus correlator writes onto the call doc, making it the one tool built to answer "is the LLM correlation tier alive" unable to answer it (2026-08-19 dump had to infer LLM state from commit dates instead of reading it off the data). admin.py's _call_summary() now includes corr_consensus, corr_llm_reasoning, corr_llm_action, corr_rules_action. The unit-continuity correlation path never wrote corr_matched_units, unlike fast/single and fast/disambig, so the debug view showed null for a match that was in fact unit-driven by construction. Now populated unconditionally on that path (server-26#16). Also traced the negative corr_incident_idle_min (-4.1 observed) to its root cause: the re-correlation sweep anchors `now` to the linking call's own started_at, and that back-dated value was being written straight into the incident's updated_at, letting it land before the incident's own started_at. Added _floor_at_started_at() so updated_at can never precede started_at. (commit 33a247d already fixed the recency *gates* misreading that negative value; this fixes the write that produced it.) Verified the skip_reason filter in recorrelation_sweep.py:63 is already correct, no change needed there. Added tests for the debug endpoint's LLM field passthrough, the unit-continuity corr_matched_units fix, and the updated_at floor — each confirmed to fail when its fix is reverted. 148 passed, 0 failed. Closes logan/server-26#24 Closes logan/server-26#16 --- .../app/internal/incident_correlator.py | 33 ++++++- drb-c2-core/app/routers/admin.py | 8 ++ .../tests/test_admin_debug_correlation.py | 91 +++++++++++++++++++ drb-c2-core/tests/test_correlator_gate.py | 73 +++++++++++++++ 4 files changed, 204 insertions(+), 1 deletion(-) create mode 100644 drb-c2-core/tests/test_admin_debug_correlation.py diff --git a/drb-c2-core/app/internal/incident_correlator.py b/drb-c2-core/app/internal/incident_correlator.py index 03ee7a2..eea75ce 100644 --- a/drb-c2-core/app/internal/incident_correlator.py +++ b/drb-c2-core/app/internal/incident_correlator.py @@ -278,6 +278,32 @@ def _idle_gate_minutes(inc: dict, now: datetime) -> float: return abs(_incident_idle_minutes(inc, now)) +def _floor_at_started_at(inc: dict, when: datetime) -> datetime: + """ + Clamp a candidate `updated_at` timestamp so it can never land before the + incident's own `started_at`. + + The re-correlation sweep anchors `now` to the linking call's own + `started_at` (server-26#24 / recorrelation_sweep.py) so that its window + math is correct regardless of when the sweep happens to run. But that + same back-dated `now` was also being written straight into `updated_at` + here — so an orphan whose real-world `started_at` predates the incident's + own `started_at` could set `updated_at` earlier than `started_at`, + producing the negative `corr_incident_idle_min` observed on 2026-08-19 + (commit 33a247d fixed the *gates* misreading that negative value, not + this write). `started_at` is never rewritten after creation, so it's a + safe floor: activity can never honestly be older than the incident itself. + """ + try: + raw = inc.get("started_at") or "" + started = datetime.fromisoformat(str(raw).replace("Z", "+00:00")) + if started.tzinfo is None: + started = started.replace(tzinfo=timezone.utc) + except Exception: + return when + return max(when, started) + + def _incident_span_minutes(inc: dict, now: datetime) -> float: """ Wall-clock minutes the incident has been open: from its `started_at` to the @@ -849,6 +875,11 @@ def _run_decision(ctx: dict) -> dict: corr_debug = { "corr_path": "unit-continuity", "corr_incident_idle_min": round(_incident_idle_minutes(best_unit_inc, now), 1), + # Unlike this file's other two paths (fast/single, fast/disambig), + # a match here is unit-driven by construction (call_unit_set & + # _unit_keys(...) is what built unit_candidates), so this is + # always populated rather than gated on fit_signal (server-26#16). + "corr_matched_units": _matching_units(call_units, best_unit_inc.get("units")), } logger.info( f"Correlator unit-continuity: call {call_id} → " @@ -1531,7 +1562,7 @@ async def _update_incident( # acknowledging. The incident now ages from its last SUBSTANTIVE call, and # thin traffic rides along without extending its life. if refresh_activity: - updates["updated_at"] = now.isoformat() + updates["updated_at"] = _floor_at_started_at(inc, now).isoformat() else: updates["last_thin_at"] = now.isoformat() if best_location: diff --git a/drb-c2-core/app/routers/admin.py b/drb-c2-core/app/routers/admin.py index 2291044..d9012c4 100644 --- a/drb-c2-core/app/routers/admin.py +++ b/drb-c2-core/app/routers/admin.py @@ -91,6 +91,14 @@ async def debug_correlation( "corr_matched_units": call.get("corr_matched_units"), "corr_sweep_count": call.get("corr_sweep_count"), "skip_reason": call.get("skip_reason"), + # LLM consensus tier fields — written by upload.py's + # _correlate_with_consensus / llm_correlator.py, but previously + # dropped here, making it impossible to tell from this endpoint + # whether the LLM correlation tier is actually running (server-26#24). + "corr_consensus": call.get("corr_consensus"), + "corr_llm_reasoning": call.get("corr_llm_reasoning"), + "corr_llm_action": call.get("corr_llm_action"), + "corr_rules_action": call.get("corr_rules_action"), } # ── Determine which systems have AI active ──────────────────────────────── diff --git a/drb-c2-core/tests/test_admin_debug_correlation.py b/drb-c2-core/tests/test_admin_debug_correlation.py new file mode 100644 index 0000000..6b02fca --- /dev/null +++ b/drb-c2-core/tests/test_admin_debug_correlation.py @@ -0,0 +1,91 @@ +""" +Unit tests for /admin/debug/correlation (server-26#24). + +The endpoint used to strip the LLM consensus tier's fields (corr_consensus, +corr_llm_reasoning, corr_llm_action, corr_rules_action) out of its response +even though upload.py / llm_correlator.py write them straight onto the call +doc via corr_debug — making this endpoint unable to answer "is the LLM +correlation tier actually running", the one thing it exists to answer. + +Firestore is fully mocked (patch app.routers.admin.fstore); the route +function is called directly, bypassing FastAPI's dependency injection, so +Query/Depends defaults are supplied explicitly. +""" +import pytest +from datetime import datetime, timezone +from unittest.mock import AsyncMock, patch +from app.routers import admin + +NOW = datetime(2026, 8, 20, 12, 0, 0, tzinfo=timezone.utc) + + +def _incident(call_ids): + return { + "incident_id": "inc-1", + "system_ids": ["sys-1"], + "call_ids": call_ids, + "updated_at": NOW.isoformat(), + "started_at": NOW.isoformat(), + "status": "active", + } + + +async def _run(incidents, calls_by_id, orphan_calls=None): + """Drive debug_correlation() with fstore fully mocked.""" + system = {"system_id": "sys-1", "ai_flags": {}} + + async def fake_collection_where(collection, conditions, order_by=None, limit_to=None, start_after=None): + if collection == "incidents": + return incidents + if collection == "calls": + return orphan_calls or [] + return [] + + async def fake_doc_get(collection, doc_id): + return calls_by_id.get(doc_id) + + with patch( + "app.routers.admin.get_flags", + new=AsyncMock(return_value={"stt_enabled": True, "correlation_enabled": True}), + ), patch("app.routers.admin.fstore") as mock_fstore: + mock_fstore.collection_list = AsyncMock(return_value=[system]) + mock_fstore.collection_where = AsyncMock(side_effect=fake_collection_where) + mock_fstore.doc_get = AsyncMock(side_effect=fake_doc_get) + return await admin.debug_correlation(limit=20, orphan_hours=48, _=None) + + +@pytest.mark.asyncio +async def test_debug_correlation_surfaces_llm_consensus_fields(): + """A call that went through the tiebreaker must show all four LLM fields.""" + call = { + "call_id": "call-1", + "corr_path": "fast/single", + "corr_consensus": "tiebreak", + "corr_llm_reasoning": "Same units on scene as the anchor call.", + "corr_llm_action": "link", + "corr_rules_action": "orphan", + } + result = await _run([_incident(["call-1"])], {"call-1": call}) + + detail = result["incidents"][0]["calls_detail"][0] + assert detail["corr_consensus"] == "tiebreak" + assert detail["corr_llm_reasoning"] == "Same units on scene as the anchor call." + assert detail["corr_llm_action"] == "link" + assert detail["corr_rules_action"] == "orphan" + + +@pytest.mark.asyncio +async def test_debug_correlation_llm_fields_absent_when_rules_only(): + """ + A call that never reached the LLM (GEMINI_API_KEY unset, thin call, or LLM + error) has corr_consensus == "rules_only" and no corr_llm_* fields — the + endpoint must pass that through as None rather than erroring, since this + is the normal/expected state whenever the tier is legitimately idle. + """ + call = {"call_id": "call-2", "corr_path": "fast/single", "corr_consensus": "rules_only"} + result = await _run([_incident(["call-2"])], {"call-2": call}) + + detail = result["incidents"][0]["calls_detail"][0] + assert detail["corr_consensus"] == "rules_only" + assert detail["corr_llm_reasoning"] is None + assert detail["corr_llm_action"] is None diff --git a/drb-c2-core/tests/test_correlator_gate.py b/drb-c2-core/tests/test_correlator_gate.py index 1714204..202ead5 100644 --- a/drb-c2-core/tests/test_correlator_gate.py +++ b/drb-c2-core/tests/test_correlator_gate.py @@ -333,6 +333,79 @@ async def test_signal_resolve_stamps_resolved_at(): assert updates["resolved_at"] == NOW.isoformat() +# --------------------------------------------------------------------------- +# Issue #16 — unit-continuity path must populate corr_matched_units +# +# fast/single and fast/disambig only set corr_matched_units when +# fit_signal == "unit_overlap"; unit-continuity has no such gate because a +# match there is unit-driven by construction (call_unit_set intersects the +# incident's units is literally how unit_candidates gets built) — so it must +# always populate the field, not conditionally. +# --------------------------------------------------------------------------- + +def test_unit_continuity_link_reports_matched_units(): + """ + Reproduces the server-26#16 production example: call units=["Post 1-2"] + should match an incident with units=["5-4", "9-0-8", "1-2"] via the + normalizer collapsing "Post 1-2" and "1-2" to the same key, on a + DIFFERENT talkgroup than the incident (so the fast/talkgroup path can't + fire first and this falls through to unit-continuity). + """ + inc = _incident(10.0) # idle 10min, within unit_continuity_max_idle_minutes (20) + inc["talkgroup_ids"] = ["1234"] + inc["units"] = ["5-4", "9-0-8", "1-2"] + decision = _run_decision(_ctx( + talkgroup_id=9999, # not in inc["talkgroup_ids"] — fast path can't match + all_active=[inc], recent=[], + call_units=["Post 1-2"], is_thin_call=False, call_severity="routine", + )) + assert decision["action"] == "link" + assert decision["corr_debug"]["corr_path"] == "unit-continuity" + assert decision["corr_debug"]["corr_matched_units"] == ["Post 1-2"] + + +# --------------------------------------------------------------------------- +# server-26#24 — updated_at must never precede started_at +# +# The re-correlation sweep anchors `now` to the linking call's own +# started_at, which can be earlier than the incident's own started_at. Left +# unclamped that produces updated_at < started_at on the incident doc, which +# is what caused corr_incident_idle_min: -4.1 in production (commit 33a247d +# fixed the gates reading that negative value, not this write). +# --------------------------------------------------------------------------- + +@pytest.mark.asyncio +async def test_updated_at_never_precedes_started_at(): + inc = _incident(5) # started_at == updated_at == NOW - 5min + inc["started_at"] = NOW.isoformat() # incident "started" at NOW + back_dated_now = NOW - timedelta(minutes=30) # a much older orphan call links in + with patch("app.internal.incident_correlator.fstore") as mock_fstore: + mock_fstore.doc_set = AsyncMock() + await _update_incident( + inc, "call-1", 9048, "sys-1", [], None, None, ["6-Adam"], [], None, + back_dated_now, + ) + updates = mock_fstore.doc_set.await_args.args[2] + assert updates["updated_at"] == NOW.isoformat(), ( + "updated_at must be floored at started_at, not the back-dated `now`" + ) + + +@pytest.mark.asyncio +async def test_updated_at_uses_now_when_now_is_later_than_started_at(): + """The normal case (now is not back-dated before started_at) is unaffected.""" + inc = _incident(5) + later_now = NOW + timedelta(minutes=1) + with patch("app.internal.incident_correlator.fstore") as mock_fstore: + mock_fstore.doc_set = AsyncMock() + await _update_incident( + inc, "call-1", 9048, "sys-1", [], None, None, ["6-Adam"], [], None, + later_now, + ) + updates = mock_fstore.doc_set.await_args.args[2] + assert updates["updated_at"] == later_now.isoformat() + + @pytest.mark.asyncio async def test_master_auto_resolve_stamps_resolved_at(): """maybe_resolve_parent closes a master once every child has resolved."""