From 2df21d23e9f7d37997c94670954b0c6aa89e06a1 Mon Sep 17 00:00:00 2001 From: Yvonne Yao Date: Sun, 30 Aug 2026 20:39:52 +1000 Subject: [PATCH] feat: log privacy and intake stage timings --- src/staylong/services/taskmaster.py | 27 +++++++++++++++++++++++++-- tests/services/test_taskmaster.py | 28 ++++++++++++++++++++++++++++ 2 files changed, 53 insertions(+), 2 deletions(-) diff --git a/src/staylong/services/taskmaster.py b/src/staylong/services/taskmaster.py index c79d8c2..beadacd 100644 --- a/src/staylong/services/taskmaster.py +++ b/src/staylong/services/taskmaster.py @@ -1,9 +1,11 @@ """Consent-governed orchestration for StayLong's single Taskmaster workflow.""" -from collections.abc import Mapping +import logging +from collections.abc import Callable, Mapping from dataclasses import dataclass, replace from datetime import datetime, timedelta from enum import StrEnum +from time import perf_counter from typing import Any, Protocol from uuid import uuid4 @@ -31,6 +33,13 @@ ) from staylong.services.reminders import Reminder, ReminderService, ReminderStatus +logger = logging.getLogger(__name__) + + +def _milliseconds(duration_seconds: float) -> int: + """Round a monotonic duration for compact, content-free operational logs.""" + return round(duration_seconds * 1_000) + class PrivacyGuard(Protocol): """Sanitizes user text before it enters persisted workflow state.""" @@ -194,6 +203,7 @@ def __init__( contact_drafts: ContactDraftDemoAdapter | None = None, reminders: ReminderService | None = None, privacy_guard: PrivacyGuard | None = None, + monotonic_clock: Callable[[], float] = perf_counter, ) -> None: self._intake_agent = intake_agent self._repository = repository @@ -203,6 +213,7 @@ def __init__( self.integration_mode = calendar.integration_mode self._reminders = reminders or ReminderService() self._privacy_guard = privacy_guard + self._monotonic_clock = monotonic_clock @property def repository(self) -> WorkflowRepository: @@ -217,10 +228,12 @@ def event_repository(self) -> EventRepository: def start(self, *, concern: str, now: datetime) -> WorkflowSnapshot: """Route danger before model use, otherwise begin the facts-only intake.""" case_id = uuid4().hex + started_at = self._monotonic_clock() # Emergency detection must remain deterministic and must never wait for a model. protected_concern = concern if self._privacy_guard is not None and route_concern(concern) != EMERGENCY_ROUTE: protected_concern = self._privacy_guard.redact(concern).redacted_text + privacy_finished_at = self._monotonic_clock() try: candidate_pack = self._intake_agent.prepare_assessment_pack(protected_concern) except EmergencyRouteRequired: @@ -230,6 +243,7 @@ def start(self, *, concern: str, now: datetime) -> WorkflowSnapshot: stage=WorkflowStage.EMERGENCY, ) return self._save(snapshot) + intake_finished_at = self._monotonic_clock() snapshot = WorkflowSnapshot( case_id=case_id, @@ -238,12 +252,21 @@ def start(self, *, concern: str, now: datetime) -> WorkflowSnapshot: questions=candidate_pack.information_to_confirm, _candidate_pack=candidate_pack, ) - return self._save_with_event( + saved = self._save_with_event( snapshot, event_type="concern.created", now=now, details={"source": "older-person"}, ) + persistence_finished_at = self._monotonic_clock() + logger.info( + "workflow.start.timing privacy_ms=%d intake_ms=%d persistence_ms=%d total_ms=%d", + _milliseconds(privacy_finished_at - started_at), + _milliseconds(intake_finished_at - privacy_finished_at), + _milliseconds(persistence_finished_at - intake_finished_at), + _milliseconds(persistence_finished_at - started_at), + ) + return saved def answer_intake( self, *, case_id: str, answers: Mapping[str, str], now: datetime diff --git a/tests/services/test_taskmaster.py b/tests/services/test_taskmaster.py index a3faae6..ccc8fe3 100644 --- a/tests/services/test_taskmaster.py +++ b/tests/services/test_taskmaster.py @@ -1,5 +1,6 @@ """Behaviour-first tests for the consent-governed StayLong Taskmaster flow.""" +import logging from datetime import UTC, datetime import pytest @@ -132,6 +133,33 @@ def test_workflow_redacts_concern_before_model_and_persistence() -> None: assert "[PHONE REDACTED]" in started.concern +def test_start_logs_only_stage_timings_without_concern_content( + caplog: pytest.LogCaptureFixture, +) -> None: + from staylong.services.taskmaster import InMemoryWorkflowRepository, TaskmasterWorkflow + + ticks = iter((10.0, 10.11, 10.33, 10.66)) + workflow = TaskmasterWorkflow( + intake_agent=IntakeAgent(provider=StaticProvider()), + repository=InMemoryWorkflowRepository(), + event_repository=InMemoryEventRepository(), + calendar=CalendarDemoAdapter(), + privacy_guard=StaticPrivacyGuard(), + monotonic_clock=lambda: next(ticks), + ) + + with caplog.at_level(logging.INFO, logger="staylong.services.taskmaster"): + workflow.start( + concern="Call 0412 345 678 about the dark hallway.", + now=NOW, + ) + + assert caplog.messages == [ + "workflow.start.timing privacy_ms=110 intake_ms=220 persistence_ms=330 total_ms=660" + ] + assert "0412 345 678" not in caplog.text + + def test_emergency_route_skips_gemma_privacy_call() -> None: from staylong.services.taskmaster import ( InMemoryWorkflowRepository,