From 620028fa18843622d3e454bd40fb91a93e607dbf Mon Sep 17 00:00:00 2001 From: Suliman Abdulrazzaq <144490671+SulimanAbdulrazzaq@users.noreply.github.com> Date: Tue, 11 Aug 2026 19:53:53 +0300 Subject: [PATCH] fix(proxy): emit request log timestamps in UTC MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Description `RequestLog.timestamp` was serialized with `datetime.now().isoformat()`, which omits timezone information. Browsers then interpret the value as local time, so requests from a UTC container can display negative ages in non-UTC dashboards. Closes #2910 ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) ## Changes Made - Emit request-log timestamps from `datetime.now(timezone.utc)` so the ISO-8601 value includes `+00:00`. - Add a regression test that parses the emitted timestamp and requires a UTC offset. ## Testing - [x] New tests added for the regression - [x] `python -m compileall -q headroom/proxy/outcome.py tests/test_request_outcome.py` - [x] `git diff --check` - [ ] Unit tests pass (`pytest`) — the repository's Rust extension cannot build in this Windows environment because `link.exe` (MSVC) is unavailable; the focused test is included for CI. ### Test Output ```text python -m compileall -q headroom/proxy/outcome.py tests/test_request_outcome.py (pass) git diff --check (pass) uv run pytest tests/test_request_outcome.py -q blocked while building headroom-py: linker `link.exe` not found ``` ## Real Behavior Proof - Environment: Windows 11, Python 3.11; proxy timestamps are generated in `headroom/proxy/outcome.py`. - Exact command / steps: traced the Recent Requests write path and added a timestamp assertion in `tests/test_request_outcome.py` (CI will run with the project's Rust toolchain). - Observed result: the production call now emits an ISO-8601 timestamp with `+00:00`; the regression assertion requires an offset-aware UTC value, preventing browser timezone skew. - Not tested: full pytest suite locally because the MSVC linker is unavailable. ## Review Readiness - [x] I have performed a self-review - [x] This PR is ready for human review ## Checklist - [x] My code follows the project's style guidelines - [x] I have performed a self-review - [x] I have added tests that prove my fix is effective - [x] I did not edit `CHANGELOG.md` Signed-off-by: Suliman Abdulrazzaq --- headroom/proxy/outcome.py | 7 +++++-- tests/test_request_outcome.py | 17 +++++++++++++++++ 2 files changed, 22 insertions(+), 2 deletions(-) diff --git a/headroom/proxy/outcome.py b/headroom/proxy/outcome.py index e0b304d4c..5a23acc04 100644 --- a/headroom/proxy/outcome.py +++ b/headroom/proxy/outcome.py @@ -27,7 +27,7 @@ from __future__ import annotations import logging from dataclasses import dataclass, field -from datetime import datetime +from datetime import datetime, timezone from typing import Any from headroom.proxy.tool_schema_savings_policy import ( @@ -526,7 +526,10 @@ async def emit_request_outcome(handler: Any, outcome: RequestOutcome) -> None: request_logger.log( RequestLog( request_id=outcome.request_id, - timestamp=datetime.now().isoformat(), + # Request logs are consumed by browsers in arbitrary time zones. + # Include the UTC offset so relative-age calculations represent + # the same instant regardless of where the proxy runs. + timestamp=datetime.now(timezone.utc).isoformat(), provider=outcome.provider, model=outcome.model, input_tokens_original=outcome.original_tokens, diff --git a/tests/test_request_outcome.py b/tests/test_request_outcome.py index 09936a094..d2295a5ea 100644 --- a/tests/test_request_outcome.py +++ b/tests/test_request_outcome.py @@ -15,6 +15,7 @@ import asyncio import contextlib import logging from dataclasses import FrozenInstanceError +from datetime import datetime, timezone from typing import Any from unittest.mock import AsyncMock, MagicMock @@ -325,6 +326,22 @@ async def test_funnel_logs_request_with_derived_cache_hit() -> None: assert log_entry.cache_hit is True +@pytest.mark.asyncio +async def test_funnel_logs_request_timestamp_with_utc_offset() -> None: + """Recent-request timestamps must identify an absolute instant. + + A naive ISO timestamp is interpreted in the browser's local timezone, + which makes the dashboard show negative ages when the proxy and browser + use different timezone settings. + """ + h = _FunnelHarness() + await h._record_request_outcome(_outcome()) + + timestamp = datetime.fromisoformat(h.logger.logs[0].timestamp) + assert timestamp.tzinfo is not None + assert timestamp.utcoffset() == timezone.utc.utcoffset(timestamp) + + @pytest.mark.asyncio async def test_funnel_skips_request_log_when_logger_absent() -> None: """Same pattern as cost_tracker — optional surface."""