From f76a196aef5c4bc447b5efc3d7109fe648d8bfaa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Markus=20Brandst=C3=A4tter?= Date: Mon, 2 Nov 2026 09:24:09 +0100 Subject: [PATCH] fix(telemetry): resolve offset-naive datetime crashes in pruning, ingestion, and doctor CLI --- backend/app/cli/doctor.py | 11 ++- backend/app/telemetry/service.py | 34 ++++++-- backend/tests/test_telemetry.py | 78 ++++++++++++++++++- .../.openspec.yaml | 2 + .../design.md | 30 +++++++ .../proposal.md | 27 +++++++ .../specs/central-telemetry/spec.md | 12 +++ .../specs/pi-diagnostics-cli/spec.md | 8 ++ .../tasks.md | 13 ++++ 9 files changed, 203 insertions(+), 12 deletions(-) create mode 100644 openspec/changes/fix-telemetry-datetime-timezone-handling/.openspec.yaml create mode 100644 openspec/changes/fix-telemetry-datetime-timezone-handling/design.md create mode 100644 openspec/changes/fix-telemetry-datetime-timezone-handling/proposal.md create mode 100644 openspec/changes/fix-telemetry-datetime-timezone-handling/specs/central-telemetry/spec.md create mode 100644 openspec/changes/fix-telemetry-datetime-timezone-handling/specs/pi-diagnostics-cli/spec.md create mode 100644 openspec/changes/fix-telemetry-datetime-timezone-handling/tasks.md diff --git a/backend/app/cli/doctor.py b/backend/app/cli/doctor.py index 82b1770..f5c0228 100644 --- a/backend/app/cli/doctor.py +++ b/backend/app/cli/doctor.py @@ -30,6 +30,13 @@ def format_bytes(size: float) -> str: return f"{size:.2f} PB" +def _normalize_timeline_ts(ts: datetime) -> datetime: + """Normalize datetime to timezone-aware UTC for safe sorting across naive and aware timestamps.""" + if ts.tzinfo is None: + return ts.replace(tzinfo=timezone.utc) + return ts.astimezone(timezone.utc) + + async def show_summary() -> None: """Display system and cross-client health overview.""" settings = get_settings() @@ -156,7 +163,7 @@ async def show_trace(trace_id: str) -> None: msg = f"[{evt.level}] [{evt.category}] [{evt.error_code or 'GENERIC'}] {evt.message}{ctx_str}" timeline_items.append((evt.created_at, msg)) - timeline_items.sort(key=lambda item: item[0]) + timeline_items.sort(key=lambda item: _normalize_timeline_ts(item[0])) for ts, line in timeline_items: print(f" [{ts.strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}] {line}") print("==================================================") @@ -263,7 +270,7 @@ async def generate_llm_prompt(trace_id: Optional[str] = None) -> None: ctx_detail = f" (Context: {evt.context_json})" if evt.context_json else "" timeline_items.append((evt.created_at, f"[{evt.level}] {evt.message}{ctx_detail}")) - timeline_items.sort(key=lambda item: item[0]) + timeline_items.sort(key=lambda item: _normalize_timeline_ts(item[0])) if not timeline_items: print("No timeline steps available.") else: diff --git a/backend/app/telemetry/service.py b/backend/app/telemetry/service.py index 5675621..be91cfb 100644 --- a/backend/app/telemetry/service.py +++ b/backend/app/telemetry/service.py @@ -23,9 +23,15 @@ async def prune_telemetry_records(session: AsyncSession, retention_days: Optiona days = retention_days if retention_days is not None else settings.server_events_retention_days if days and days > 0: cutoff = datetime.now(timezone.utc) - timedelta(days=days) - await session.execute(delete(ServerEvent).where(ServerEvent.created_at < cutoff)) - await session.execute(delete(DiagnosticEvent).where(DiagnosticEvent.created_at < cutoff)) - await session.execute(delete(SyncSummary).where(SyncSummary.started_at < cutoff)) + await session.execute( + delete(ServerEvent).where(ServerEvent.created_at < cutoff).execution_options(synchronize_session=False) + ) + await session.execute( + delete(DiagnosticEvent).where(DiagnosticEvent.created_at < cutoff).execution_options(synchronize_session=False) + ) + await session.execute( + delete(SyncSummary).where(SyncSummary.started_at < cutoff).execution_options(synchronize_session=False) + ) async def log_server_event( @@ -39,6 +45,7 @@ async def log_server_event( ) -> None: """Append a server event and occasionally prune old rows.""" row = ServerEvent( + created_at=datetime.now(timezone.utc), level=level[:16], category=category[:64], message=message, @@ -68,13 +75,16 @@ async def upsert_client_ping( ct = client_type[:32] cv = client_version[:64] bv = backend_version[:32] + sync_at = last_sync_at + if sync_at is not None and sync_at.tzinfo is None: + sync_at = sync_at.replace(tzinfo=timezone.utc) stmt = insert(ClientConnection).values( user_email=user_email, client_type=ct, client_version=cv, last_seen_at=now, - last_sync_at=last_sync_at, + last_sync_at=sync_at, last_sync_ok=last_sync_ok, backend_version_at_ping=bv, ) @@ -124,9 +134,12 @@ async def ingest_telemetry_batch( """Persist batch of diagnostic events and sync summaries reported by a client.""" now = datetime.now(timezone.utc) for evt in events: + evt_created = evt.created_at or now + if evt_created.tzinfo is None: + evt_created = evt_created.replace(tzinfo=timezone.utc) row = DiagnosticEvent( trace_id=evt.trace_id, - created_at=evt.created_at or now, + created_at=evt_created, user_email=user_email, client_type=evt.client_type[:32] if evt.client_type else "", device_name=evt.device_name[:128] if evt.device_name else "", @@ -139,14 +152,21 @@ async def ingest_telemetry_batch( session.add(row) for sm in summaries: + started_at = sm.started_at + if started_at.tzinfo is None: + started_at = started_at.replace(tzinfo=timezone.utc) + completed_at = sm.completed_at or now + if completed_at.tzinfo is None: + completed_at = completed_at.replace(tzinfo=timezone.utc) + stmt = insert(SyncSummary).values( trace_id=sm.trace_id[:64], user_email=user_email, client_type=sm.client_type[:32] if sm.client_type else "", client_version=sm.client_version[:64] if sm.client_version else "", device_name=sm.device_name[:128] if sm.device_name else "", - started_at=sm.started_at, - completed_at=sm.completed_at or now, + started_at=started_at, + completed_at=completed_at, duration_ms=sm.duration_ms, status=sm.status[:16] if sm.status else "ok", files_scanned=sm.files_scanned, diff --git a/backend/tests/test_telemetry.py b/backend/tests/test_telemetry.py index c7e4ddc..9e8d9c7 100644 --- a/backend/tests/test_telemetry.py +++ b/backend/tests/test_telemetry.py @@ -144,11 +144,16 @@ def test_telemetry_api_routes(client): token = login_r.json()["access_token"] headers = {"Authorization": f"Bearer {token}"} - # 2. Ingest telemetry batch + # 2. Ingest telemetry batch with relative timestamps + now = datetime.now(timezone.utc) + started_iso = (now - timedelta(minutes=10)).isoformat() + completed_iso = (now - timedelta(minutes=9)).isoformat() + payload = { "events": [ { "trace_id": "sync-api-test-01", + "created_at": completed_iso, "client_type": "desktop-macos", "device_name": "TestMac", "level": "ERROR", @@ -164,8 +169,8 @@ def test_telemetry_api_routes(client): "client_type": "desktop-macos", "client_version": "1.3.2", "device_name": "TestMac", - "started_at": "2026-09-16T21:00:00Z", - "completed_at": "2026-09-16T21:01:00Z", + "started_at": started_iso, + "completed_at": completed_iso, "duration_ms": 60000, "status": "failed", "files_scanned": 100, @@ -210,3 +215,70 @@ def test_telemetry_api_routes(client): assert len(evt_res_filtered.json()) >= 1 assert evt_res_filtered.json()[0]["trace_id"] == "sync-api-test-01" + +@pytest.mark.asyncio +async def test_log_server_event_and_pruning_timezone_handling(session_factory): + """Verify log_server_event does not crash on offset-naive vs aware comparisons during pruning.""" + from app.telemetry.service import log_server_event + + async with session_factory() as session: + # Logging a server event triggers flush followed by prune_telemetry_records + await log_server_event( + session, + level="WARNING", + category="oauth.refresh", + message="Test server warning", + detail={"trace": "test-trace"}, + user_email="test@example.com", + ) + await session.commit() + + +@pytest.mark.asyncio +async def test_ingest_telemetry_batch_with_naive_timestamps(session_factory): + """Verify ingest_telemetry_batch normalizes offset-naive timestamps without raising errors.""" + from app.telemetry.schemas import DiagnosticEventItem, SyncSummaryItem + from app.telemetry.service import ingest_telemetry_batch + + naive_now = datetime.now() # offset-naive + events = [ + DiagnosticEventItem( + trace_id="sync-naive-01", + created_at=naive_now, + client_type="desktop-linux", + message="Naive event test", + ) + ] + summaries = [ + SyncSummaryItem( + trace_id="sync-naive-01", + started_at=naive_now - timedelta(minutes=5), + completed_at=naive_now, + client_type="desktop-linux", + status="ok", + ) + ] + + async with session_factory() as session: + await ingest_telemetry_batch( + session, + user_email="test@example.com", + events=events, + summaries=summaries, + ) + await session.commit() + + +def test_doctor_cli_timeline_mixed_timestamp_sorting(): + """Verify doctor CLI timeline normalizer handles mixed naive and aware datetimes cleanly.""" + from app.cli.doctor import _normalize_timeline_ts + + naive_ts = datetime(2026, 11, 2, 10, 0, 0) + aware_ts = datetime(2026, 11, 2, 10, 0, 1, tzinfo=timezone.utc) + + items = [(aware_ts, "second"), (naive_ts, "first")] + items.sort(key=lambda item: _normalize_timeline_ts(item[0])) + + assert items[0][1] == "first" + assert items[1][1] == "second" + diff --git a/openspec/changes/fix-telemetry-datetime-timezone-handling/.openspec.yaml b/openspec/changes/fix-telemetry-datetime-timezone-handling/.openspec.yaml new file mode 100644 index 0000000..a7587c5 --- /dev/null +++ b/openspec/changes/fix-telemetry-datetime-timezone-handling/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-11-02 diff --git a/openspec/changes/fix-telemetry-datetime-timezone-handling/design.md b/openspec/changes/fix-telemetry-datetime-timezone-handling/design.md new file mode 100644 index 0000000..dcb9449 --- /dev/null +++ b/openspec/changes/fix-telemetry-datetime-timezone-handling/design.md @@ -0,0 +1,30 @@ +## Context + +See `proposal.md` for motivation. SQLite stores and returns datetime values without timezone information by default, resulting in offset-naive Python `datetime` objects. When SQLAlchemy ORM executes `session.execute(delete(...))` within a session containing recently flushed rows, it uses `synchronize_session='evaluate'`, which evaluates the SQL where clause in Python against objects in the session's identity map. If the where clause compares against an offset-aware datetime (such as `cutoff = datetime.now(timezone.utc) - timedelta(days=days)`), Python raises `TypeError: can't compare offset-naive and offset-aware datetimes`. Additionally, sorting timelines in `brandybox-doctor` fails if entries contain mixed naive and aware datetimes. + +## Goals / Non-Goals + +**Goals:** +- Eliminate `TypeError` crashes during `log_server_event` and telemetry batch ingestion pruning. +- Prevent timeline sort crashes in `brandybox-doctor --trace` and `brandybox-doctor --llm-prompt`. +- Ensure telemetry test cases use dynamic relative timestamps so they do not expire under retention policies. + +**Non-Goals:** +- Altering the SQLite database schema or migration scripts. +- Modifying client-side payload formats. + +## Decisions + +### Decision 1: Set `synchronize_session=False` on retention cleanup queries +Bulk deletion queries in `prune_telemetry_records` do not need ORM session synchronization because they delete expired records (e.g. older than 30 days) rather than currently active session entities. Setting `.execution_options(synchronize_session=False)` prevents SQLAlchemy from performing Python-side condition evaluation on in-memory objects. + +### Decision 2: Set explicit UTC timestamps on `ServerEvent` creation +`log_server_event` will pass `created_at=datetime.now(timezone.utc)` explicitly instead of relying on `server_default=func.now()`, ensuring the Python object in session memory is always timezone-aware UTC. + +### Decision 3: Normalize naive datetimes during ingestion and timeline sorting +In `ingest_telemetry_batch`, any event or summary timestamp lacking `tzinfo` is coerced to UTC using `.replace(tzinfo=timezone.utc)`. In `doctor.py`, timeline sort keys normalize timestamps through a helper function before comparison. + +## Risks / Trade-offs + +- [Risk: In-memory session staleness with `synchronize_session=False`] → Mitigation: Telemetry pruning targets records older than the retention threshold (e.g., 30 days), which never overlaps with newly created session rows. +- [Risk: Client sends local time without timezone] → Mitigation: Assuming UTC for naive timestamps (`.replace(tzinfo=timezone.utc)`) is standard across BrandyBox APIs and preserves chronological consistency. diff --git a/openspec/changes/fix-telemetry-datetime-timezone-handling/proposal.md b/openspec/changes/fix-telemetry-datetime-timezone-handling/proposal.md new file mode 100644 index 0000000..6f7cfa9 --- /dev/null +++ b/openspec/changes/fix-telemetry-datetime-timezone-handling/proposal.md @@ -0,0 +1,27 @@ +## Why + +Telemetry logging and pruning in `backend/app/telemetry/service.py` crashes with `TypeError: can't compare offset-naive and offset-aware datetimes` whenever `log_server_event` is called or when naive datetimes are ingested. Furthermore, `brandybox-doctor` timeline sorting crashes when ordering mixed naive and aware timestamps, and `test_telemetry.py::test_telemetry_api_routes` failed due to hardcoded timestamps falling outside the 30-day retention pruning window. Resolving timezone normalization and bulk deletion session synchronization prevents server crashes on logging events, ensures telemetry pruning functions reliably, and eliminates time-bomb test failures. + +## What Changes + +- Explicitly pass `created_at=datetime.now(timezone.utc)` when creating `ServerEvent` records in `backend/app/telemetry/service.py:log_server_event`. +- Execute bulk retention deletions in `prune_telemetry_records` with `synchronize_session=False` to prevent SQLAlchemy ORM in-memory evaluation mismatches across timezone formats. +- Normalize client timestamps in `ingest_telemetry_batch` to UTC aware datetimes if naive timestamps are supplied. +- Normalize timeline timestamps to UTC before sorting in `backend/app/cli/doctor.py` (`show_trace` and `generate_llm_prompt`). +- Update `backend/tests/test_telemetry.py` to use dynamic, relative UTC timestamps for test telemetry batches and add regression tests for `log_server_event` pruning and naive datetime ingestion. + +## Capabilities + +### New Capabilities + + +### Modified Capabilities +- `central-telemetry`: Require the backend telemetry service and ingestion pipeline to normalize timestamps to UTC and safely prune retention records without offset-naive comparison crashes. +- `pi-diagnostics-cli`: Require `brandybox-doctor` to safely sort trace and prompt timelines regardless of whether constituent timestamps are naive or timezone-aware. + +## Impact + +- **Affected code**: `backend/app/telemetry/service.py`, `backend/app/cli/doctor.py`, `backend/tests/test_telemetry.py` +- **APIs**: No breaking API schema changes; `/api/telemetry/events` accepts both naive and aware ISO timestamps cleanly. +- **Dependencies**: No new dependencies. +- **Behavior**: Eliminates runtime `TypeError` crashes during server event logging, batch ingestion, and doctor CLI timeline generation. diff --git a/openspec/changes/fix-telemetry-datetime-timezone-handling/specs/central-telemetry/spec.md b/openspec/changes/fix-telemetry-datetime-timezone-handling/specs/central-telemetry/spec.md new file mode 100644 index 0000000..321fa4c --- /dev/null +++ b/openspec/changes/fix-telemetry-datetime-timezone-handling/specs/central-telemetry/spec.md @@ -0,0 +1,12 @@ +## MODIFIED Requirements + +### Requirement: Central diagnostic event ingestion API +The backend SHALL expose an authenticated endpoint allowing clients to submit batches of diagnostic events and sync summaries, normalizing client timestamps to timezone-aware UTC and safely executing retention pruning. + +#### Scenario: Client submits diagnostic batch +- **WHEN** a client POSTs an event batch to `/api/telemetry/events` with valid user authentication +- **THEN** the backend validates the payload, persists events and summaries into SQLite tables (`diagnostic_events` and `sync_summaries`), normalizes any offset-naive timestamps to UTC, executes retention pruning without comparison crashes, and returns HTTP 202 Accepted or 204 No Content. + +#### Scenario: Client submits events with naive timestamps +- **WHEN** a client submits events or sync summaries with offset-naive ISO timestamps +- **THEN** the backend coerces timestamps to UTC timezone-aware values without raising comparison errors during retention pruning or persistence. diff --git a/openspec/changes/fix-telemetry-datetime-timezone-handling/specs/pi-diagnostics-cli/spec.md b/openspec/changes/fix-telemetry-datetime-timezone-handling/specs/pi-diagnostics-cli/spec.md new file mode 100644 index 0000000..ff36213 --- /dev/null +++ b/openspec/changes/fix-telemetry-datetime-timezone-handling/specs/pi-diagnostics-cli/spec.md @@ -0,0 +1,8 @@ +## MODIFIED Requirements + +### Requirement: Correlated trace timeline command +The CLI SHALL provide a command to display the chronological sequence of client and server actions for a given trace identifier. + +#### Scenario: User inspects a specific sync run +- **WHEN** the user executes `brandybox-doctor --trace ` +- **THEN** the tool queries client diagnostic events and backend logs associated with `` and renders a unified, chronological timeline of operations and failure points, sorting mixed naive and timezone-aware timestamps safely without errors. diff --git a/openspec/changes/fix-telemetry-datetime-timezone-handling/tasks.md b/openspec/changes/fix-telemetry-datetime-timezone-handling/tasks.md new file mode 100644 index 0000000..23057d7 --- /dev/null +++ b/openspec/changes/fix-telemetry-datetime-timezone-handling/tasks.md @@ -0,0 +1,13 @@ +## 1. Backend Telemetry Service Fixes + +- [x] 1.1 In `backend/app/telemetry/service.py`, set `synchronize_session=False` on retention delete queries and pass explicit UTC `created_at` on `ServerEvent` instantiation; verify via unit test. +- [x] 1.2 In `backend/app/telemetry/service.py`, normalize incoming event and summary timestamps to timezone-aware UTC in `ingest_telemetry_batch`; verify with test ingestion of naive timestamps. + +## 2. Doctor CLI Timeline Normalization + +- [x] 2.1 In `backend/app/cli/doctor.py`, normalize timeline timestamps to UTC before sorting in `show_trace` and `generate_llm_prompt`; verify timeline output with mixed timestamps. + +## 3. Telemetry Test Suite & Regression Verification + +- [x] 3.1 Update `backend/tests/test_telemetry.py` to use relative UTC timestamps in `test_telemetry_api_routes` and add test cases for `log_server_event` pruning and naive datetime ingestion; verify with `pytest backend/tests/test_telemetry.py`. +- [x] 3.2 Run full QA suite (`./scripts/run-qa.sh` and `pytest backend`) to verify zero regressions across the codebase.