From e4d6e34addec094d6760dd14f7f7ae85622cd37a Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Wed, 23 Sep 2026 18:22:56 -0400 Subject: [PATCH] fix(web): response_time_ms reads the same clock request_logging stamps request_logging now stamps request.start_time from perf_counter, but success_response still subtracted it from time.time(), so metadata reported ~1.8e12 ms. Found testing on ledpi. Co-Authored-By: Claude Opus 5.5 --- src/web_interface/api_helpers.py | 3 ++- test/web_interface/test_web_logging.py | 15 +++++++++++++++ 2 files changed, 17 insertions(+), 1 deletion(-) diff --git a/src/web_interface/api_helpers.py b/src/web_interface/api_helpers.py index be2b0771..fe6471e2 100644 --- a/src/web_interface/api_helpers.py +++ b/src/web_interface/api_helpers.py @@ -34,7 +34,8 @@ def success_response( # metadata block for responses that have neither. enriched = dict(metadata) if metadata is not None else {} if hasattr(request, 'start_time'): - enriched['response_time_ms'] = int((time.time() - request.start_time) * 1000) + # request_logging stamps start_time from perf_counter, not the wall clock. + enriched['response_time_ms'] = int((time.perf_counter() - request.start_time) * 1000) if metadata is not None or enriched: response_data['metadata'] = enriched diff --git a/test/web_interface/test_web_logging.py b/test/web_interface/test_web_logging.py index a9de0f0d..de980898 100644 --- a/test/web_interface/test_web_logging.py +++ b/test/web_interface/test_web_logging.py @@ -162,3 +162,18 @@ def test_duration_is_rounded(tiny_app, caplog): msg = caplog.records[-1].getMessage() duration = msg.rsplit("(", 1)[1] assert duration.endswith("ms)") and len(duration.split(".")[1]) == len("0ms)"), msg + + +def test_success_response_timing_uses_the_same_clock(): + # request_logging stamps request.start_time from perf_counter; a reader + # subtracting it from time.time() reported ~1.8e12 ms (found on a Pi). + from src.web_interface.api_helpers import success_response + app = Flask(__name__) + request_logging.init_app(app) + + @app.route('/timed') + def timed(): + return success_response(data={}, metadata={}) + + body = app.test_client().get('/timed').get_json() + assert 0 <= body['metadata']['response_time_ms'] < 10_000