diff --git a/SPECS/ARCHIVE/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering.md b/SPECS/ARCHIVE/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering.md new file mode 100644 index 00000000..c66da0d4 --- /dev/null +++ b/SPECS/ARCHIVE/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering.md @@ -0,0 +1,50 @@ +# PRD: BUG-T20 — Session Timeline can show negative duration due to incorrect entry ordering + +## Objective +Eliminate negative or inverted session durations in the Session Timeline by ensuring session detection always runs on timestamp-ascending audit entries, regardless of upstream ordering. + +## Background +`detect_sessions()` expects chronologically ascending entries. Some server paths currently pass newest-first arrays (or mixed ordering) into session detection, which can invert `started_at`/`ended_at` boundaries and produce impossible negative durations. + +## Deliverables +- Normalize audit entry ordering before session detection in the Web UI backend session path. +- Add defensive ordering behavior at the session computation layer so callers cannot accidentally produce invalid durations. +- Add regression tests that cover newest-first and mixed-order inputs and assert non-negative durations and stable latest-event semantics. +- Document the fix and verification evidence in the validation report. + +## Dependencies +- `src/mcpbridge_wrapper/webui/sessions.py` +- `src/mcpbridge_wrapper/webui/server.py` +- Existing Web UI test suites under `tests/unit/webui/` and `tests/integration/webui/` + +## Acceptance Criteria +- [ ] Session detection produces non-negative duration for newest-first and mixed-order entries. +- [ ] `/api/sessions` and websocket session payloads expose monotonic session boundaries (`started_at <= ended_at`). +- [ ] Regression tests fail before the fix and pass after the fix. +- [ ] Required quality gates pass: `PYTHONPATH=src pytest`, `ruff check src/`, `mypy src/`, `PYTHONPATH=src pytest --cov` (coverage >= 90%). + +## Validation Plan +1. Add/extend unit tests around session detection ordering assumptions. +2. Add/extend server-level tests to validate `/api/sessions` behavior with descending/mixed audit entries. +3. Run required quality gates and record outcomes in `SPECS/INPROGRESS/BUG-T20_Validation_Report.md`. +4. Confirm no regressions to previous BUG-T19 multi-process consistency behavior. + +## Implementation Plan +### Phase 1: Defensive ordering in session detection +- Enforce timestamp-ascending ordering inside session computation to make ordering contract explicit and robust. +- Preserve output ordering expected by dashboard consumers. + +### Phase 2: Server integration correctness +- Ensure all server paths that compute sessions use the normalized entry order. +- Keep payload shape unchanged. + +### Phase 3: Regression coverage +- Add tests for descending/mixed input ordering and non-negative duration guarantees. +- Add server-level test asserting API session ordering and duration correctness. + +--- +**Planned:** 2026-02-25 + +--- +**Archived:** 2026-02-25 +**Verdict:** PASS diff --git a/SPECS/ARCHIVE/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/BUG-T20_Validation_Report.md b/SPECS/ARCHIVE/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/BUG-T20_Validation_Report.md new file mode 100644 index 00000000..0368c450 --- /dev/null +++ b/SPECS/ARCHIVE/BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/BUG-T20_Validation_Report.md @@ -0,0 +1,38 @@ +# Validation Report: BUG-T20 + +## Task +Session Timeline can show negative duration due to incorrect entry ordering. + +## Implementation Summary +- Added defensive timestamp ordering in `detect_sessions()` so session grouping always runs on ascending timestamps, regardless of caller input order. +- Added robust timestamp parsing helper reuse in session extraction to keep boundary and tool timestamps consistent. +- Added unit regression coverage in `tests/unit/webui/test_sessions.py` for newest-first and mixed-order inputs, asserting non-negative durations and correct tool ordering. +- Added server/API regression coverage in `tests/unit/webui/test_server.py` for mixed-order audit rows, ensuring monotonic session boundaries and correct latest-event placement. + +## Quality Gates + +### 1) `PYTHONPATH=src pytest` +- Result: PASS +- Evidence: `651 passed, 5 skipped` + +### 2) `ruff check src/` +- Result: PASS +- Evidence: `All checks passed!` + +### 3) `mypy src/` +- Result: PASS +- Evidence: `Success: no issues found in 18 source files` + +### 4) `PYTHONPATH=src pytest --cov` +- Result: PASS +- Evidence: + - `651 passed, 5 skipped` + - `Required test coverage of 90.0% reached` + - `Total coverage: 91.33%` + +## Manual Validation Notes +- Verified reverse-ordered and mixed-ordered inputs now produce session windows where `start <= end`. +- Confirmed session tool lists are chronologically ordered, so timeline "latest event" aligns with the final tool entry in each session. + +## Verdict +PASS diff --git a/SPECS/ARCHIVE/INDEX.md b/SPECS/ARCHIVE/INDEX.md index 4b3c0162..c2070a83 100644 --- a/SPECS/ARCHIVE/INDEX.md +++ b/SPECS/ARCHIVE/INDEX.md @@ -1,11 +1,12 @@ # mcpbridge-wrapper Tasks Archive -**Last Updated:** 2026-02-25 (BUG-T19_Audit_Log_and_Session_Timeline_are_inconsistent_with_tool_charts_in_multi_process_runs) +**Last Updated:** 2026-02-25 (BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering) ## Archived Tasks | Task ID | Folder | Archived | Verdict | |---------|--------|----------|---------| +| BUG-T20 | [BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/](BUG-T20_Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering/) | 2026-02-25 | PASS | | BUG-T19 | [BUG-T19_Audit_Log_and_Session_Timeline_are_inconsistent_with_tool_charts_in_multi_process_runs/](BUG-T19_Audit_Log_and_Session_Timeline_are_inconsistent_with_tool_charts_in_multi_process_runs/) | 2026-02-25 | PASS | | BUG-T13 | [BUG-T13_Per-Tool_Latency_Statistics_does_not_show_params_when_capture_params_is_false/](BUG-T13_Per-Tool_Latency_Statistics_does_not_show_params_when_capture_params_is_false/) | 2026-02-25 | PASS | | BUG-T11 | [BUG-T11_Chart_Request_Timeline_never_shows_actual_events/](BUG-T11_Chart_Request_Timeline_never_shows_actual_events/) | 2026-02-25 | PASS | @@ -252,6 +253,7 @@ | [REVIEW_bug_t18_workplan_entry.md](_Historical/REVIEW_bug_t18_workplan_entry.md) | Review report for BUG-T18 | | [REVIEW_bug_t17_audit_log_rows_stay_unfolded.md](_Historical/REVIEW_bug_t17_audit_log_rows_stay_unfolded.md) | Review report for BUG-T17 | | [REVIEW_bug_t14_latency_rows.md](_Historical/REVIEW_bug_t14_latency_rows.md) | Review report for BUG-T14 | +| [REVIEW_bug_t20_session_timeline_ordering.md](_Historical/REVIEW_bug_t20_session_timeline_ordering.md) | Review report for BUG-T20 | | [REVIEW_bug_t19_audit_session_consistency.md](_Historical/REVIEW_bug_t19_audit_session_consistency.md) | Review report for BUG-T19 | | [REVIEW_bug_t13_capture_params_hint.md](_Historical/REVIEW_bug_t13_capture_params_hint.md) | Review report for BUG-T13 | | [REVIEW_bug_t11_request_timeline.md](_Historical/REVIEW_bug_t11_request_timeline.md) | Review report for BUG-T11 | @@ -263,6 +265,8 @@ | Date | Task ID | Action | |------|---------|--------| +| 2026-02-25 | BUG-T20 | Archived REVIEW_bug_t20_session_timeline_ordering report | +| 2026-02-25 | BUG-T20 | Archived Session_Timeline_can_show_negative_duration_due_to_incorrect_entry_ordering (PASS) | | 2026-02-25 | BUG-T19 | Archived REVIEW_bug_t19_audit_session_consistency report | | 2026-02-25 | BUG-T19 | Archived Audit_Log_and_Session_Timeline_are_inconsistent_with_tool_charts_in_multi_process_runs (PASS) | | 2026-02-25 | BUG-T13 | Archived REVIEW_bug_t13_capture_params_hint report | diff --git a/SPECS/ARCHIVE/_Historical/REVIEW_bug_t20_session_timeline_ordering.md b/SPECS/ARCHIVE/_Historical/REVIEW_bug_t20_session_timeline_ordering.md new file mode 100644 index 00000000..b611c3dc --- /dev/null +++ b/SPECS/ARCHIVE/_Historical/REVIEW_bug_t20_session_timeline_ordering.md @@ -0,0 +1,29 @@ +## REVIEW REPORT — BUG-T20 Session Timeline Ordering + +**Scope:** `origin/main..HEAD` +**Files:** 8 + +### Summary Verdict +- [x] Approve +- [ ] Approve with comments +- [ ] Request changes +- [ ] Block + +### Critical Issues +- None. + +### Secondary Issues +- None. + +### Architectural Notes +- Session ordering normalization is now enforced at the session computation layer (`detect_sessions`), not only at API-call sites, reducing the chance of future regressions from caller-side ordering assumptions. +- Existing API/websocket sorting behavior remains compatible and now benefits from defense in depth. + +### Tests +- `PYTHONPATH=src pytest` → PASS (`651 passed, 5 skipped`) +- `ruff check src/` → PASS +- `mypy src/` → PASS +- `PYTHONPATH=src pytest --cov` → PASS (`Total coverage: 91.33%`, threshold 90%) + +### Next Steps +- FOLLOW-UP skipped: no actionable review findings to add as new workplan tasks. diff --git a/SPECS/INPROGRESS/next.md b/SPECS/INPROGRESS/next.md index 531542c1..b2eae52b 100644 --- a/SPECS/INPROGRESS/next.md +++ b/SPECS/INPROGRESS/next.md @@ -2,12 +2,12 @@ ## Recently Archived +- **BUG-T20** — Session Timeline can show negative duration due to incorrect entry ordering (2026-02-25, PASS) - **BUG-T19** — Audit Log and Session Timeline are inconsistent with tool charts in multi-process runs (2026-02-25, PASS) - **BUG-T13** — Per-Tool Latency Statistics does not show params when `capture_params` is false (2026-02-25, PASS) -- **BUG-T11** — Chart Request Timeline never shows actual events (2026-02-25, PASS) ## Suggested Next Tasks -- BUG-T20 — Session Timeline can show negative duration due to incorrect entry ordering - BUG-T18 — Error Breakdown widget must be full width streatched - BUG-T4 — Repeated Xcode permission prompts for each short-lived MCP client process +- BUG-T1 — Kimi CLI MCP Connection Failure diff --git a/SPECS/Workplan.md b/SPECS/Workplan.md index 260c9ff6..50c45abb 100644 --- a/SPECS/Workplan.md +++ b/SPECS/Workplan.md @@ -1680,9 +1680,10 @@ Use export endpoints (`/api/audit/export/json` or `/api/audit/export/csv`) for a ### BUG-T20: Session Timeline can show negative duration due to incorrect entry ordering - **Type:** Bug / Web UI / Session Analytics -- **Status:** 🔴 Open +- **Status:** ✅ Fixed (2026-02-25) - **Priority:** P1 - **Discovered:** 2026-02-20 +- **Completed:** 2026-02-25 - **Component:** Session detection path (`webui/server.py`, `webui/sessions.py`) - **Affected Clients:** All clients using Session Timeline - **Affected Surface:** Session Timeline duration and ordering @@ -1703,10 +1704,10 @@ Session start/end ordering appears inverted. None. #### Resolution Path -- [ ] Normalize session input ordering to ascending timestamps before calling `detect_sessions()` -- [ ] Add defensive sorting (or contract enforcement) in session computation path -- [ ] Add regression test asserting non-negative session duration for mixed/newest-first inputs -- [ ] Validate timeline rendering shows monotonic ordering and correct latest event after reconnect/activity +- [x] Normalize session input ordering to ascending timestamps before calling `detect_sessions()` +- [x] Add defensive sorting (or contract enforcement) in session computation path +- [x] Add regression test asserting non-negative session duration for mixed/newest-first inputs +- [x] Validate timeline rendering shows monotonic ordering and correct latest event after reconnect/activity #### Related Items - **BUG-T19** — Shared audit/session consistency issue may amplify session timeline staleness diff --git a/src/mcpbridge_wrapper/webui/sessions.py b/src/mcpbridge_wrapper/webui/sessions.py index 4724c57e..458996cd 100644 --- a/src/mcpbridge_wrapper/webui/sessions.py +++ b/src/mcpbridge_wrapper/webui/sessions.py @@ -8,16 +8,24 @@ from typing import Any, Dict, List +def _entry_timestamp(entry: Dict[str, Any]) -> float: + """Parse a session entry timestamp for deterministic ordering.""" + try: + return float(entry.get("timestamp", 0.0)) + except (TypeError, ValueError): + return 0.0 + + def detect_sessions( entries: List[Dict[str, Any]], gap_seconds: float = 300.0, ) -> List[Dict[str, Any]]: - """Group sorted audit entries into sessions by idle gap. + """Group audit entries into sessions by idle gap. A session is a contiguous run of tool calls where no consecutive pair - is separated by more than ``gap_seconds``. Entries must already be - sorted by ``timestamp`` ascending; unsorted input produces undefined - groupings. + is separated by more than ``gap_seconds``. Inputs are normalized to + ``timestamp`` ascending order before grouping to ensure stable, + non-negative session boundaries even when callers pass newest-first rows. Args: entries: List of audit log entry dicts. Each entry must have a @@ -54,12 +62,14 @@ def detect_sessions( if not entries: return [] + ordered_entries = sorted(entries, key=_entry_timestamp) + sessions: List[Dict[str, Any]] = [] current_tools: List[Dict[str, Any]] = [] prev_ts: float = 0.0 - for entry in entries: - ts = float(entry.get("timestamp", 0.0)) + for entry in ordered_entries: + ts = _entry_timestamp(entry) # Start a new session if this is not the first entry and the gap is too large. if current_tools and (ts - prev_ts) > gap_seconds: @@ -81,7 +91,7 @@ def _extract_tool(entry: Dict[str, Any]) -> Dict[str, Any]: return { "request_id": entry.get("request_id"), "tool": entry.get("tool", ""), - "timestamp": float(entry.get("timestamp", 0.0)), + "timestamp": _entry_timestamp(entry), "timestamp_iso": entry.get("timestamp_iso", ""), "latency_ms": entry.get("latency_ms"), "error": entry.get("error"), diff --git a/tests/unit/webui/test_server.py b/tests/unit/webui/test_server.py index 0cd9fc7f..9de9678c 100644 --- a/tests/unit/webui/test_server.py +++ b/tests/unit/webui/test_server.py @@ -174,6 +174,57 @@ def test_sessions_endpoint_sorts_entries_chronologically(self, client, audit, mo assert session["end"] == 200.0 assert [t["request_id"] for t in session["tools"]] == ["req-1", "req-2"] + def test_sessions_endpoint_handles_mixed_order_and_preserves_latest_event( + self, client, audit, monkeypatch + ): + """Sessions API yields monotonic boundaries for mixed-order audit rows.""" + mixed_entries = [ + { + "timestamp": 600.0, + "timestamp_iso": "2026-02-25T10:10:00Z", + "tool": "NewestInFirstSession", + "request_id": "req-3", + "direction": "response", + }, + { + "timestamp": 100.0, + "timestamp_iso": "2026-02-25T10:01:40Z", + "tool": "OldestInFirstSession", + "request_id": "req-1", + "direction": "response", + }, + { + "timestamp": 350.0, + "timestamp_iso": "2026-02-25T10:05:50Z", + "tool": "MiddleInFirstSession", + "request_id": "req-2", + "direction": "response", + }, + { + "timestamp": 1400.0, + "timestamp_iso": "2026-02-25T10:23:20Z", + "tool": "OnlyInSecondSession", + "request_id": "req-4", + "direction": "response", + }, + ] + + monkeypatch.setattr(audit, "get_entries", lambda *args, **kwargs: mixed_entries) + + response = client.get("/api/sessions?limit=4&gap_seconds=300") + assert response.status_code == 200 + sessions = response.json()["sessions"] + assert len(sessions) == 2 + + first, second = sessions + assert first["start"] == 100.0 + assert first["end"] == 600.0 + assert [t["request_id"] for t in first["tools"]] == ["req-1", "req-2", "req-3"] + assert second["start"] == 1400.0 + assert second["end"] == 1400.0 + assert second["tools"][-1]["request_id"] == "req-4" + assert all(session["start"] <= session["end"] for session in sessions) + def test_export_audit_json(self, client, audit): """Test exporting audit as JSON.""" audit.log("XcodeRead") diff --git a/tests/unit/webui/test_sessions.py b/tests/unit/webui/test_sessions.py index 7a4fe3a7..fbdb6884 100644 --- a/tests/unit/webui/test_sessions.py +++ b/tests/unit/webui/test_sessions.py @@ -100,6 +100,38 @@ def test_multiple_sessions_start_end(self): assert result[1]["end"] == 2100.0 +class TestDetectSessionsInputOrdering: + """Input ordering is normalized to protect session boundaries.""" + + def test_newest_first_input_yields_non_negative_duration(self): + entries = [_entry(200.0, req_id="req-2"), _entry(100.0, req_id="req-1")] + result = detect_sessions(entries, gap_seconds=300) + + assert len(result) == 1 + session = result[0] + assert session["start"] == 100.0 + assert session["end"] == 200.0 + assert session["start"] <= session["end"] + assert [tool["request_id"] for tool in session["tools"]] == ["req-1", "req-2"] + + def test_mixed_order_input_still_splits_by_gap_correctly(self): + entries = [ + _entry(300.0, req_id="req-3"), + _entry(100.0, req_id="req-1"), + _entry(250.0, req_id="req-2"), + _entry(900.0, req_id="req-4"), + ] + result = detect_sessions(entries, gap_seconds=300) + + assert len(result) == 2 + assert result[0]["start"] == 100.0 + assert result[0]["end"] == 300.0 + assert [tool["request_id"] for tool in result[0]["tools"]] == ["req-1", "req-2", "req-3"] + assert result[1]["start"] == 900.0 + assert result[1]["end"] == 900.0 + assert all(session["start"] <= session["end"] for session in result) + + class TestDetectSessionsZeroGap: """Zero gap puts every call in its own session."""