diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/execute_tool_scope.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/execute_tool_scope.py index f502cee..f22c02f 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/execute_tool_scope.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/execute_tool_scope.py @@ -1,6 +1,8 @@ # Copyright (c) Microsoft Corporation. # Licensed under the MIT License. +from datetime import datetime + from .agent_details import AgentDetails from .constants import ( EXECUTE_TOOL_OPERATION_NAME, @@ -31,6 +33,8 @@ def start( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "ExecuteToolScope": """Creates and starts a new scope for tool execution tracing. @@ -41,11 +45,18 @@ def start( request: Optional request details for additional context parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. Useful when + recording a tool call after execution has already completed. + end_time: Optional explicit end time as a datetime object. When provided, + the span will use this timestamp when disposed instead of the + current wall-clock time. Returns: A new ExecuteToolScope instance """ - return ExecuteToolScope(details, agent_details, tenant_details, request, parent_id) + return ExecuteToolScope( + details, agent_details, tenant_details, request, parent_id, start_time, end_time + ) def __init__( self, @@ -54,6 +65,8 @@ def __init__( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the tool execution scope. @@ -64,6 +77,11 @@ def __init__( request: Optional request details for additional context parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. Useful when + recording a tool call after execution has already completed. + end_time: Optional explicit end time as a datetime object. When provided, + the span will use this timestamp when disposed instead of the + current wall-clock time. """ super().__init__( kind="Internal", @@ -72,6 +90,8 @@ def __init__( agent_details=agent_details, tenant_details=tenant_details, parent_id=parent_id, + start_time=start_time, + end_time=end_time, ) # Extract details using deconstruction-like approach diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/inference_scope.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/inference_scope.py index 79294ea..a137ff1 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/inference_scope.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/inference_scope.py @@ -1,6 +1,7 @@ # Copyright (c) Microsoft Corporation. # Licensed under the MIT License. +from datetime import datetime from typing import List from .agent_details import AgentDetails @@ -35,6 +36,8 @@ def start( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "InferenceScope": """Creates and starts a new scope for inference tracing. @@ -45,11 +48,15 @@ def start( request: Optional request details for additional context parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. Returns: A new InferenceScope instance """ - return InferenceScope(details, agent_details, tenant_details, request, parent_id) + return InferenceScope( + details, agent_details, tenant_details, request, parent_id, start_time, end_time + ) def __init__( self, @@ -58,6 +65,8 @@ def __init__( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the inference scope. @@ -68,6 +77,8 @@ def __init__( request: Optional request details for additional context parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. """ super().__init__( @@ -77,6 +88,8 @@ def __init__( agent_details=agent_details, tenant_details=tenant_details, parent_id=parent_id, + start_time=start_time, + end_time=end_time, ) if request: diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/invoke_agent_scope.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/invoke_agent_scope.py index f9bf82e..fa8b8ab 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/invoke_agent_scope.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/invoke_agent_scope.py @@ -4,6 +4,7 @@ # Invoke agent scope for tracing agent invocation. import logging +from datetime import datetime from .agent_details import AgentDetails from .constants import ( @@ -50,6 +51,8 @@ def start( request: Request | None = None, caller_agent_details: AgentDetails | None = None, caller_details: CallerDetails | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "InvokeAgentScope": """Create and start a new scope for agent invocation tracing. @@ -60,12 +63,20 @@ def start( request: Optional request details for additional context caller_agent_details: Optional details of the caller agent caller_details: Optional details of the non-agentic caller + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. Returns: A new InvokeAgentScope instance """ return InvokeAgentScope( - invoke_agent_details, tenant_details, request, caller_agent_details, caller_details + invoke_agent_details, + tenant_details, + request, + caller_agent_details, + caller_details, + start_time, + end_time, ) def __init__( @@ -75,6 +86,8 @@ def __init__( request: Request | None = None, caller_agent_details: AgentDetails | None = None, caller_details: CallerDetails | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the agent invocation scope. @@ -84,6 +97,8 @@ def __init__( request: Optional request details for additional context caller_agent_details: Optional details of the caller agent caller_details: Optional details of the non-agentic caller + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. """ activity_name = INVOKE_AGENT_OPERATION_NAME if invoke_agent_details.details.agent_name: @@ -97,6 +112,8 @@ def __init__( activity_name=activity_name, agent_details=invoke_agent_details.details, tenant_details=tenant_details, + start_time=start_time, + end_time=end_time, ) endpoint, _, session_id = ( diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/opentelemetry_scope.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/opentelemetry_scope.py index 90b3e84..e0365e9 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/opentelemetry_scope.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/opentelemetry_scope.py @@ -5,7 +5,7 @@ import logging import os -import time +from datetime import datetime from threading import Lock from typing import TYPE_CHECKING, Any @@ -72,6 +72,20 @@ def _is_telemetry_enabled(cls) -> bool: enable_observability = os.getenv(ENABLE_A365_OBSERVABILITY, "").lower() return (env_value or enable_observability) in ("true", "1", "yes", "on") + @staticmethod + def _datetime_to_ns(dt: datetime | None) -> int | None: + """Convert a datetime to nanoseconds since epoch. + + Args: + dt: Python datetime object, or None + + Returns: + Nanoseconds since epoch, or None if input is None + """ + if dt is None: + return None + return int(dt.timestamp() * 1_000_000_000) + def __init__( self, kind: str, @@ -80,6 +94,8 @@ def __init__( agent_details: "AgentDetails | None" = None, tenant_details: "TenantDetails | None" = None, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the OpenTelemetry scope. @@ -91,9 +107,15 @@ def __init__( tenant_details: Optional tenant details parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. + Useful when recording an operation after it has already completed. + end_time: Optional explicit end time as a datetime object. + When provided, the span will use this timestamp when disposed + instead of the current wall-clock time. """ self._span: Span | None = None - self._start_time = time.time() + self._custom_start_time: datetime | None = start_time + self._custom_end_time: datetime | None = end_time self._has_ended = False self._error_type: str | None = None self._exception: Exception | None = None @@ -119,7 +141,15 @@ def __init__( parent_context = parse_parent_id_to_context(parent_id) span_context = parent_context if parent_context else context.get_current() - self._span = tracer.start_span(activity_name, kind=activity_kind, context=span_context) + # Convert custom start time to OTel-compatible format (nanoseconds since epoch) + otel_start_time = self._datetime_to_ns(start_time) + + self._span = tracer.start_span( + activity_name, + kind=activity_kind, + context=span_context, + start_time=otel_start_time, + ) # Log span creation if self._span: @@ -230,6 +260,18 @@ def record_attributes(self, attributes: dict[str, Any] | list[tuple[str, Any]]) if key and key.strip(): self._span.set_attribute(key, value) + def set_end_time(self, end_time: datetime) -> None: + """Set a custom end time for the scope. + + When set, dispose() will pass this value to span.end() instead of using + the current wall-clock time. This is useful when the actual end time of + the operation is known before the scope is disposed. + + Args: + end_time: The end time as a datetime object. + """ + self._custom_end_time = end_time + def _end(self) -> None: """End the span and record metrics.""" if self._span and self._is_telemetry_enabled() and not self._has_ended: @@ -237,7 +279,12 @@ def _end(self) -> None: span_id = f"{self._span.context.span_id:016x}" if self._span.context else "unknown" logger.info(f"Span ended: '{self._span.name}' ({span_id})") - self._span.end() + # Convert custom end time to OTel-compatible format (nanoseconds since epoch) + otel_end_time = self._datetime_to_ns(self._custom_end_time) + if otel_end_time is not None: + self._span.end(end_time=otel_end_time) + else: + self._span.end() def __enter__(self): """Enter the context manager and make span active.""" diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/spans_scopes/output_scope.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/spans_scopes/output_scope.py index 6f01c42..873a9dc 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/spans_scopes/output_scope.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/spans_scopes/output_scope.py @@ -1,6 +1,8 @@ # Copyright (c) Microsoft Corporation. # Licensed under the MIT License. +from datetime import datetime + from ..agent_details import AgentDetails from ..constants import GEN_AI_OUTPUT_MESSAGES_KEY from ..models.response import Response @@ -20,6 +22,8 @@ def start( tenant_details: TenantDetails, response: Response, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "OutputScope": """Creates and starts a new scope for output tracing. @@ -29,11 +33,13 @@ def start( response: The response details from the agent parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. Returns: A new OutputScope instance """ - return OutputScope(agent_details, tenant_details, response, parent_id) + return OutputScope(agent_details, tenant_details, response, parent_id, start_time, end_time) def __init__( self, @@ -41,6 +47,8 @@ def __init__( tenant_details: TenantDetails, response: Response, parent_id: str | None = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the output scope. @@ -50,6 +58,8 @@ def __init__( response: The response details from the agent parent_id: Optional parent Activity ID used to link this span to an upstream operation + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. """ super().__init__( kind="Client", @@ -58,6 +68,8 @@ def __init__( agent_details=agent_details, tenant_details=tenant_details, parent_id=parent_id, + start_time=start_time, + end_time=end_time, ) # Initialize accumulated messages list diff --git a/tests/observability/core/test_custom_start_end_time.py b/tests/observability/core/test_custom_start_end_time.py new file mode 100644 index 0000000..080e4ca --- /dev/null +++ b/tests/observability/core/test_custom_start_end_time.py @@ -0,0 +1,177 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. + +"""Tests for custom start and end time support on OpenTelemetry scopes.""" + +import os +import sys +import time +import unittest +from datetime import UTC, datetime +from pathlib import Path + +import pytest +from microsoft_agents_a365.observability.core import ( + AgentDetails, + ExecuteToolScope, + TenantDetails, + ToolCallDetails, + configure, + get_tracer_provider, +) +from microsoft_agents_a365.observability.core.config import _telemetry_manager +from microsoft_agents_a365.observability.core.opentelemetry_scope import OpenTelemetryScope +from opentelemetry.sdk.trace.export import SimpleSpanProcessor +from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter + + +class TestCustomStartEndTime(unittest.TestCase): + """Unit tests for custom start and end time support.""" + + @classmethod + def setUpClass(cls): + """Set up test environment once for all tests.""" + os.environ["ENABLE_A365_OBSERVABILITY"] = "true" + + configure( + service_name="test-custom-time-service", + service_namespace="test-namespace", + ) + # Create test data + cls.tenant_details = TenantDetails(tenant_id="12345678-1234-5678-1234-567812345678") + cls.agent_details = AgentDetails( + agent_id="test-agent-123", + agent_name="Test Agent", + agent_description="A test agent for custom time testing", + ) + cls.tool_details = ToolCallDetails( + tool_name="test_tool", + arguments='{"arg": "value"}', + tool_call_id="call-123", + ) + + def setUp(self): + super().setUp() + + # Reset TelemetryManager state to ensure fresh configuration + _telemetry_manager._tracer_provider = None + _telemetry_manager._span_processors = {} + OpenTelemetryScope._tracer = None + + # Reconfigure to get a fresh TracerProvider + configure( + service_name="test-custom-time-service", + service_namespace="test-namespace", + ) + + # Set up tracer to capture spans + self.span_exporter = InMemorySpanExporter() + tracer_provider = get_tracer_provider() + tracer_provider.add_span_processor(SimpleSpanProcessor(self.span_exporter)) + + def tearDown(self): + super().tearDown() + self.span_exporter.clear() + + def _get_finished_span(self): + """Get the last finished span from the exporter.""" + finished_spans = self.span_exporter.get_finished_spans() + self.assertTrue(finished_spans, "Expected at least one span to be created") + return finished_spans[-1] + + def test_custom_start_and_end_time_with_datetime(self): + """Test that datetime objects are correctly converted to span timestamps.""" + custom_start = datetime(2023, 11, 14, 22, 13, 20, tzinfo=UTC) + custom_end = datetime(2023, 11, 14, 22, 13, 25, tzinfo=UTC) # 5 seconds later + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start, + end_time=custom_end, + ) + scope.dispose() + + span = self._get_finished_span() + + expected_start_ns = int(custom_start.timestamp() * 1_000_000_000) + expected_end_ns = int(custom_end.timestamp() * 1_000_000_000) + + span_start_ns = span.start_time + span_end_ns = span.end_time + + self.assertAlmostEqual(span_start_ns, expected_start_ns, delta=1000) + self.assertAlmostEqual(span_end_ns, expected_end_ns, delta=1000) + + def test_set_end_time_overrides_end_time(self): + """Test that set_end_time overrides the end time when called before dispose.""" + custom_start = datetime(2023, 11, 14, 22, 13, 40, tzinfo=UTC) + initial_end = datetime(2023, 11, 14, 22, 13, 45, tzinfo=UTC) # 5 seconds after start + later_end = datetime(2023, 11, 14, 22, 13, 48, tzinfo=UTC) # 8 seconds after start + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start, + end_time=initial_end, + ) + # Override the end time + scope.set_end_time(later_end) + scope.dispose() + + span = self._get_finished_span() + + expected_end_ns = int(later_end.timestamp() * 1_000_000_000) + span_end_ns = span.end_time + self.assertAlmostEqual(span_end_ns, expected_end_ns, delta=1000) + + def test_wall_clock_time_used_when_no_custom_times(self): + """Test that wall-clock time is used when no custom times are provided.""" + before = time.time_ns() + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + ) + scope.dispose() + after = time.time_ns() + + span = self._get_finished_span() + + span_start_ns = span.start_time + span_end_ns = span.end_time + + # Span times should be within the before/after window + # Allow some tolerance for processing time + self.assertGreaterEqual(span_start_ns, before - 1_000_000) # 1ms tolerance + self.assertLessEqual(span_end_ns, after + 1_000_000) + + def test_only_start_time_provided(self): + """Test that only custom start time can be provided without end time.""" + custom_start = datetime(2023, 11, 14, 22, 13, 20, tzinfo=UTC) + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start, + ) + scope.dispose() + + span = self._get_finished_span() + + expected_start_ns = int(custom_start.timestamp() * 1_000_000_000) + span_start_ns = span.start_time + + # Start time should match what we provided + self.assertAlmostEqual(span_start_ns, expected_start_ns, delta=1000) + + # End time should be close to current time (not custom) + span_end_ns = span.end_time + self.assertGreater(span_end_ns, span_start_ns) + + +if __name__ == "__main__": + sys.exit(pytest.main([str(Path(__file__))] + sys.argv[1:]))