From c65c959d15e241ef71cdc80b9a75be2a2e5c74db Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 24 Feb 2026 19:06:26 +0000 Subject: [PATCH 1/4] Initial plan From 44aca2e1b266adc099ca97cfc70253c93b8df4f8 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 24 Feb 2026 19:15:34 +0000 Subject: [PATCH 2/4] Add start_time and end_time parameters to OpenTelemetry scope classes This change implements support for custom start and end times on OpenTelemetry spans, mirroring the Node.js PR #205. Changes include: - Add TimeInput type alias supporting int (nanoseconds), float (seconds), tuple (HrTime), and datetime - Update OpenTelemetryScope base class with start_time and end_time constructor parameters - Add set_end_time() method for setting end time after construction - Update InferenceScope, InvokeAgentScope, ExecuteToolScope, and OutputScope to forward parameters - Add comprehensive unit tests for custom start/end time functionality Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --- .../observability/core/__init__.py | 4 +- .../observability/core/execute_tool_scope.py | 22 +- .../observability/core/inference_scope.py | 16 +- .../observability/core/invoke_agent_scope.py | 20 +- .../observability/core/opentelemetry_scope.py | 104 ++++++- .../core/spans_scopes/output_scope.py | 14 +- .../core/test_custom_start_end_time.py | 253 ++++++++++++++++++ 7 files changed, 421 insertions(+), 12 deletions(-) create mode 100644 tests/observability/core/test_custom_start_end_time.py diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py index e19cf8e9..47245187 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py @@ -24,7 +24,7 @@ from .invoke_agent_details import InvokeAgentDetails from .invoke_agent_scope import InvokeAgentScope from .middleware.baggage_builder import BaggageBuilder -from .opentelemetry_scope import OpenTelemetryScope +from .opentelemetry_scope import OpenTelemetryScope, TimeInput from .request import Request from .source_metadata import SourceMetadata from .tenant_details import TenantDetails @@ -47,6 +47,8 @@ "SpanProcessor", # Base scope class "OpenTelemetryScope", + # Type aliases + "TimeInput", # Specific scope classes "ExecuteToolScope", "InvokeAgentScope", 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 f502cee0..6a5ab8d2 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 @@ -15,7 +15,7 @@ SERVER_ADDRESS_KEY, SERVER_PORT_KEY, ) -from .opentelemetry_scope import OpenTelemetryScope +from .opentelemetry_scope import OpenTelemetryScope, TimeInput from .request import Request from .tenant_details import TenantDetails from .tool_call_details import ToolCallDetails @@ -31,6 +31,8 @@ def start( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ) -> "ExecuteToolScope": """Creates and starts a new scope for tool execution tracing. @@ -41,11 +43,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 (ms epoch, Date, or HrTime). Useful when + recording a tool call after execution has already completed. + end_time: Optional explicit end time (ms epoch, Date, or HrTime). 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 +63,8 @@ def __init__( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ): """Initialize the tool execution scope. @@ -64,6 +75,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 (ms epoch, Date, or HrTime). Useful when + recording a tool call after execution has already completed. + end_time: Optional explicit end time (ms epoch, Date, or HrTime). When provided, + the span will use this timestamp when disposed instead of the current + wall-clock time. """ super().__init__( kind="Internal", @@ -72,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, ) # 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 79294ea6..df7fc1db 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 @@ -19,7 +19,7 @@ GEN_AI_USAGE_OUTPUT_TOKENS_KEY, ) from .inference_call_details import InferenceCallDetails -from .opentelemetry_scope import OpenTelemetryScope +from .opentelemetry_scope import OpenTelemetryScope, TimeInput from .request import Request from .tenant_details import TenantDetails from .utils import safe_json_dumps @@ -35,6 +35,8 @@ def start( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ) -> "InferenceScope": """Creates and starts a new scope for inference tracing. @@ -45,11 +47,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 (ms epoch, Date, or HrTime) + end_time: Optional explicit end time (ms epoch, Date, or HrTime) 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 +64,8 @@ def __init__( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ): """Initialize the inference scope. @@ -68,6 +76,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 (ms epoch, Date, or HrTime) + end_time: Optional explicit end time (ms epoch, Date, or HrTime) """ super().__init__( @@ -77,6 +87,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 f9bf82ee..df08bf21 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 @@ -32,7 +32,7 @@ ) from .invoke_agent_details import InvokeAgentDetails from .models.caller_details import CallerDetails -from .opentelemetry_scope import OpenTelemetryScope +from .opentelemetry_scope import OpenTelemetryScope, TimeInput from .request import Request from .tenant_details import TenantDetails from .utils import safe_json_dumps, validate_and_normalize_ip @@ -50,6 +50,8 @@ def start( request: Request | None = None, caller_agent_details: AgentDetails | None = None, caller_details: CallerDetails | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ) -> "InvokeAgentScope": """Create and start a new scope for agent invocation tracing. @@ -60,12 +62,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 (ms epoch, Date, or HrTime) + end_time: Optional explicit end time (ms epoch, Date, or HrTime) 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 +85,8 @@ def __init__( request: Request | None = None, caller_agent_details: AgentDetails | None = None, caller_details: CallerDetails | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ): """Initialize the agent invocation scope. @@ -84,6 +96,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 (ms epoch, Date, or HrTime) + end_time: Optional explicit end time (ms epoch, Date, or HrTime) """ activity_name = INVOKE_AGENT_OPERATION_NAME if invoke_agent_details.details.agent_name: @@ -97,6 +111,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 90b3e84b..55066934 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 @@ -6,6 +6,7 @@ import logging import os import time +from datetime import datetime from threading import Lock from typing import TYPE_CHECKING, Any @@ -48,6 +49,12 @@ # Create logger for this module - inherits from 'microsoft_agents_a365.observability.core' logger = logging.getLogger(__name__) +# TimeInput is a type alias for types that can be used as span timestamps. +# OpenTelemetry Python SDK accepts int (nanoseconds since epoch), float (seconds since epoch), +# or a tuple of (seconds, nanoseconds) as HrTime. +# We extend this to also accept datetime objects for convenience. +TimeInput = int | float | tuple[int, int] | datetime | None + class OpenTelemetryScope: """Base class for OpenTelemetry tracing scopes in the SDK.""" @@ -80,6 +87,8 @@ def __init__( agent_details: "AgentDetails | None" = None, tenant_details: "TenantDetails | None" = None, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ): """Initialize the OpenTelemetry scope. @@ -91,9 +100,20 @@ 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. Can be: + - int: nanoseconds since epoch + - float: seconds since epoch + - tuple[int, int]: HrTime as (seconds, nanoseconds) + - datetime: Python datetime object + Useful when recording an operation after it has already completed. + end_time: Optional explicit end time in the same format as start_time. + 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._wall_clock_start_ms = time.time() * 1000 # milliseconds + self._custom_start_time: TimeInput = start_time + self._custom_end_time: TimeInput = end_time self._has_ended = False self._error_type: str | None = None self._exception: Exception | None = None @@ -119,7 +139,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._time_input_to_ns(start_time) if start_time else None + + 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 +258,71 @@ def record_attributes(self, attributes: dict[str, Any] | list[tuple[str, Any]]) if key and key.strip(): self._span.set_attribute(key, value) + @staticmethod + def _time_input_to_ns(t: TimeInput) -> int | None: + """Convert a TimeInput value to nanoseconds since epoch. + + OpenTelemetry Python SDK accepts int (nanoseconds since epoch) for span + start_time and end_time parameters. + + Args: + t: TimeInput value which can be: + - int: nanoseconds since epoch (returned as-is) + - float: seconds since epoch + - tuple[int, int]: HrTime as (seconds, nanoseconds) + - datetime: Python datetime object + + Returns: + Nanoseconds since epoch, or None if input is None + """ + if t is None: + return None + if isinstance(t, int): + # Assume nanoseconds if it's an integer + return t + if isinstance(t, float): + # Convert seconds to nanoseconds + return int(t * 1_000_000_000) + if isinstance(t, tuple) and len(t) == 2: + # HrTime: (seconds, nanoseconds) + seconds, nanos = t + return seconds * 1_000_000_000 + nanos + if isinstance(t, datetime): + return int(t.timestamp() * 1_000_000_000) + logger.warning( + f"_time_input_to_ns received unexpected TimeInput " + f"(type={type(t).__name__}); returning None" + ) + return None + + @staticmethod + def _time_input_to_ms(t: TimeInput) -> float | None: + """Convert a TimeInput value to milliseconds since epoch. + + Used for duration calculations. + + Args: + t: TimeInput value (see _time_input_to_ns for accepted types) + + Returns: + Milliseconds since epoch, or None if input is None + """ + ns = OpenTelemetryScope._time_input_to_ns(t) + return ns / 1_000_000 if ns is not None else None + + def set_end_time(self, end_time: TimeInput) -> 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 nanoseconds since epoch, seconds since epoch, + HrTime tuple (seconds, nanoseconds), or 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 +330,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._time_input_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 6f01c42c..4f526058 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 @@ -4,7 +4,7 @@ from ..agent_details import AgentDetails from ..constants import GEN_AI_OUTPUT_MESSAGES_KEY from ..models.response import Response -from ..opentelemetry_scope import OpenTelemetryScope +from ..opentelemetry_scope import OpenTelemetryScope, TimeInput from ..tenant_details import TenantDetails from ..utils import safe_json_dumps @@ -20,6 +20,8 @@ def start( tenant_details: TenantDetails, response: Response, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ) -> "OutputScope": """Creates and starts a new scope for output tracing. @@ -29,11 +31,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 (ms epoch, Date, or HrTime) + end_time: Optional explicit end time (ms epoch, Date, or HrTime) 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 +45,8 @@ def __init__( tenant_details: TenantDetails, response: Response, parent_id: str | None = None, + start_time: TimeInput = None, + end_time: TimeInput = None, ): """Initialize the output scope. @@ -50,6 +56,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 (ms epoch, Date, or HrTime) + end_time: Optional explicit end time (ms epoch, Date, or HrTime) """ super().__init__( kind="Client", @@ -58,6 +66,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 00000000..cb824c02 --- /dev/null +++ b/tests/observability/core/test_custom_start_end_time.py @@ -0,0 +1,253 @@ +# 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 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_nanoseconds(self): + """Test that constructor-provided start and end times are recorded on the span.""" + # Use nanoseconds since epoch + custom_start_ns = 1700000000000000000 # 2023-11-14T22:13:20Z + custom_end_ns = 1700000005000000000 # 5 seconds later + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start_ns, + end_time=custom_end_ns, + ) + scope.dispose() + + span = self._get_finished_span() + + # OTel Python SDK stores times as nanoseconds (int) + span_start_ns = span.start_time + span_end_ns = span.end_time + + # Verify start and end times are close to what we provided + self.assertAlmostEqual(span_start_ns, custom_start_ns, delta=1000) # 1μs tolerance + self.assertAlmostEqual(span_end_ns, custom_end_ns, delta=1000) + + 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_custom_start_and_end_time_with_float_seconds(self): + """Test that float seconds are correctly converted to span timestamps.""" + # Float seconds since epoch + custom_start_sec = 1700000000.0 # 2023-11-14T22:13:20Z + custom_end_sec = 1700000005.5 # 5.5 seconds later + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start_sec, + end_time=custom_end_sec, + ) + scope.dispose() + + span = self._get_finished_span() + + expected_start_ns = int(custom_start_sec * 1_000_000_000) + expected_end_ns = int(custom_end_sec * 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_custom_start_and_end_time_with_hrtime_tuple(self): + """Test that HrTime tuples (seconds, nanoseconds) are correctly handled.""" + # HrTime: (seconds, nanoseconds) + custom_start: tuple[int, int] = (1700000000, 0) # 2023-11-14T22:13:20Z + custom_end: tuple[int, int] = (1700000005, 500000000) # 5.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 = custom_start[0] * 1_000_000_000 + custom_start[1] + expected_end_ns = custom_end[0] * 1_000_000_000 + custom_end[1] + + 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_ns = 1700000040000000000 + initial_end_ns = 1700000045000000000 # 5 seconds after start + later_end_ns = 1700000048000000000 # 8 seconds after start + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start_ns, + end_time=initial_end_ns, + ) + # Override the end time + scope.set_end_time(later_end_ns) + scope.dispose() + + span = self._get_finished_span() + + span_end_ns = span.end_time + self.assertAlmostEqual(span_end_ns, later_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.""" + import time + + 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_ns = 1700000000000000000 + + scope = ExecuteToolScope.start( + self.tool_details, + self.agent_details, + self.tenant_details, + start_time=custom_start_ns, + ) + scope.dispose() + + span = self._get_finished_span() + + span_start_ns = span.start_time + + # Start time should match what we provided + self.assertAlmostEqual(span_start_ns, custom_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:])) From a2f33854e6c4fa9f8799be2cb93084f8b441c7d1 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 24 Feb 2026 19:18:19 +0000 Subject: [PATCH 3/4] Address code review feedback - Remove unused _wall_clock_start_ms variable - Fix documentation to accurately describe TimeInput accepted formats - Remove unused time import Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --- .../observability/core/execute_tool_scope.py | 18 ++++++++++-------- .../observability/core/inference_scope.py | 10 ++++++---- .../observability/core/invoke_agent_scope.py | 10 ++++++---- .../observability/core/opentelemetry_scope.py | 2 -- 4 files changed, 22 insertions(+), 18 deletions(-) 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 6a5ab8d2..8b92e2b0 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 @@ -43,11 +43,12 @@ 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 (ms epoch, Date, or HrTime). Useful when + start_time: Optional explicit start time. Accepts int (nanoseconds since epoch), + float (seconds since epoch), tuple[int, int] (HrTime), or datetime. Useful when recording a tool call after execution has already completed. - end_time: Optional explicit end time (ms epoch, Date, or HrTime). When provided, - the span will use this timestamp when disposed instead of the current - wall-clock time. + end_time: Optional explicit end time in the same formats as start_time. When + provided, the span will use this timestamp when disposed instead of the + current wall-clock time. Returns: A new ExecuteToolScope instance @@ -75,11 +76,12 @@ 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 (ms epoch, Date, or HrTime). Useful when + start_time: Optional explicit start time. Accepts int (nanoseconds since epoch), + float (seconds since epoch), tuple[int, int] (HrTime), or datetime. Useful when recording a tool call after execution has already completed. - end_time: Optional explicit end time (ms epoch, Date, or HrTime). When provided, - the span will use this timestamp when disposed instead of the current - wall-clock time. + end_time: Optional explicit end time in the same formats as start_time. When + provided, the span will use this timestamp when disposed instead of the + current wall-clock time. """ super().__init__( kind="Internal", 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 df7fc1db..e50863e7 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 @@ -47,8 +47,9 @@ 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 (ms epoch, Date, or HrTime) - end_time: Optional explicit end time (ms epoch, Date, or HrTime) + start_time: Optional explicit start time. Accepts int (nanoseconds since epoch), + float (seconds since epoch), tuple[int, int] (HrTime), or datetime. + end_time: Optional explicit end time in the same formats as start_time. Returns: A new InferenceScope instance @@ -76,8 +77,9 @@ 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 (ms epoch, Date, or HrTime) - end_time: Optional explicit end time (ms epoch, Date, or HrTime) + start_time: Optional explicit start time. Accepts int (nanoseconds since epoch), + float (seconds since epoch), tuple[int, int] (HrTime), or datetime. + end_time: Optional explicit end time in the same formats as start_time. """ super().__init__( 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 df08bf21..20456054 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 @@ -62,8 +62,9 @@ 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 (ms epoch, Date, or HrTime) - end_time: Optional explicit end time (ms epoch, Date, or HrTime) + start_time: Optional explicit start time. Accepts int (nanoseconds since epoch), + float (seconds since epoch), tuple[int, int] (HrTime), or datetime. + end_time: Optional explicit end time in the same formats as start_time. Returns: A new InvokeAgentScope instance @@ -96,8 +97,9 @@ 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 (ms epoch, Date, or HrTime) - end_time: Optional explicit end time (ms epoch, Date, or HrTime) + start_time: Optional explicit start time. Accepts int (nanoseconds since epoch), + float (seconds since epoch), tuple[int, int] (HrTime), or datetime. + end_time: Optional explicit end time in the same formats as start_time. """ activity_name = INVOKE_AGENT_OPERATION_NAME if invoke_agent_details.details.agent_name: 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 55066934..71dd6b50 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,6 @@ import logging import os -import time from datetime import datetime from threading import Lock from typing import TYPE_CHECKING, Any @@ -111,7 +110,6 @@ def __init__( instead of the current wall-clock time. """ self._span: Span | None = None - self._wall_clock_start_ms = time.time() * 1000 # milliseconds self._custom_start_time: TimeInput = start_time self._custom_end_time: TimeInput = end_time self._has_ended = False From 8354142efc03b46cbc765824b8bfec564bb73f83 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 24 Feb 2026 19:28:03 +0000 Subject: [PATCH 4/4] Simplify TimeInput type to just use datetime Based on user feedback, simplify the start_time/end_time parameters to only accept datetime objects instead of the complex TimeInput union type. This is more Pythonic and consistent with existing code in the LangChain tracer. Changes: - Remove TimeInput type alias - Change start_time/end_time parameters to datetime | None - Add simple _datetime_to_ns() conversion method - Remove unused _time_input_to_ns() and _time_input_to_ms() methods - Update all scope subclasses to use datetime | None - Simplify tests to only use datetime Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --- .../observability/core/__init__.py | 4 +- .../observability/core/execute_tool_scope.py | 26 ++--- .../observability/core/inference_scope.py | 21 ++-- .../observability/core/invoke_agent_scope.py | 21 ++-- .../observability/core/opentelemetry_scope.py | 97 +++++------------ .../core/spans_scopes/output_scope.py | 20 ++-- .../core/test_custom_start_end_time.py | 102 +++--------------- 7 files changed, 82 insertions(+), 209 deletions(-) diff --git a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py index 47245187..e19cf8e9 100644 --- a/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py +++ b/libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/__init__.py @@ -24,7 +24,7 @@ from .invoke_agent_details import InvokeAgentDetails from .invoke_agent_scope import InvokeAgentScope from .middleware.baggage_builder import BaggageBuilder -from .opentelemetry_scope import OpenTelemetryScope, TimeInput +from .opentelemetry_scope import OpenTelemetryScope from .request import Request from .source_metadata import SourceMetadata from .tenant_details import TenantDetails @@ -47,8 +47,6 @@ "SpanProcessor", # Base scope class "OpenTelemetryScope", - # Type aliases - "TimeInput", # Specific scope classes "ExecuteToolScope", "InvokeAgentScope", 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 8b92e2b0..f22c02fe 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, @@ -15,7 +17,7 @@ SERVER_ADDRESS_KEY, SERVER_PORT_KEY, ) -from .opentelemetry_scope import OpenTelemetryScope, TimeInput +from .opentelemetry_scope import OpenTelemetryScope from .request import Request from .tenant_details import TenantDetails from .tool_call_details import ToolCallDetails @@ -31,8 +33,8 @@ def start( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "ExecuteToolScope": """Creates and starts a new scope for tool execution tracing. @@ -43,11 +45,10 @@ 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. Accepts int (nanoseconds since epoch), - float (seconds since epoch), tuple[int, int] (HrTime), or datetime. Useful when + 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 in the same formats as start_time. When - provided, the span will use this timestamp when disposed instead of the + 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: @@ -64,8 +65,8 @@ def __init__( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the tool execution scope. @@ -76,11 +77,10 @@ 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. Accepts int (nanoseconds since epoch), - float (seconds since epoch), tuple[int, int] (HrTime), or datetime. Useful when + 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 in the same formats as start_time. When - provided, the span will use this timestamp when disposed instead of the + 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__( 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 e50863e7..a137ff14 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 @@ -19,7 +20,7 @@ GEN_AI_USAGE_OUTPUT_TOKENS_KEY, ) from .inference_call_details import InferenceCallDetails -from .opentelemetry_scope import OpenTelemetryScope, TimeInput +from .opentelemetry_scope import OpenTelemetryScope from .request import Request from .tenant_details import TenantDetails from .utils import safe_json_dumps @@ -35,8 +36,8 @@ def start( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "InferenceScope": """Creates and starts a new scope for inference tracing. @@ -47,9 +48,8 @@ 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. Accepts int (nanoseconds since epoch), - float (seconds since epoch), tuple[int, int] (HrTime), or datetime. - end_time: Optional explicit end time in the same formats as start_time. + 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 @@ -65,8 +65,8 @@ def __init__( tenant_details: TenantDetails, request: Request | None = None, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the inference scope. @@ -77,9 +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. Accepts int (nanoseconds since epoch), - float (seconds since epoch), tuple[int, int] (HrTime), or datetime. - end_time: Optional explicit end time in the same formats as start_time. + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. """ super().__init__( 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 20456054..fa8b8abe 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 ( @@ -32,7 +33,7 @@ ) from .invoke_agent_details import InvokeAgentDetails from .models.caller_details import CallerDetails -from .opentelemetry_scope import OpenTelemetryScope, TimeInput +from .opentelemetry_scope import OpenTelemetryScope from .request import Request from .tenant_details import TenantDetails from .utils import safe_json_dumps, validate_and_normalize_ip @@ -50,8 +51,8 @@ def start( request: Request | None = None, caller_agent_details: AgentDetails | None = None, caller_details: CallerDetails | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "InvokeAgentScope": """Create and start a new scope for agent invocation tracing. @@ -62,9 +63,8 @@ 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. Accepts int (nanoseconds since epoch), - float (seconds since epoch), tuple[int, int] (HrTime), or datetime. - end_time: Optional explicit end time in the same formats as start_time. + 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 @@ -86,8 +86,8 @@ def __init__( request: Request | None = None, caller_agent_details: AgentDetails | None = None, caller_details: CallerDetails | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the agent invocation scope. @@ -97,9 +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. Accepts int (nanoseconds since epoch), - float (seconds since epoch), tuple[int, int] (HrTime), or datetime. - end_time: Optional explicit end time in the same formats as start_time. + 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: 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 71dd6b50..e0365e9a 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 @@ -48,12 +48,6 @@ # Create logger for this module - inherits from 'microsoft_agents_a365.observability.core' logger = logging.getLogger(__name__) -# TimeInput is a type alias for types that can be used as span timestamps. -# OpenTelemetry Python SDK accepts int (nanoseconds since epoch), float (seconds since epoch), -# or a tuple of (seconds, nanoseconds) as HrTime. -# We extend this to also accept datetime objects for convenience. -TimeInput = int | float | tuple[int, int] | datetime | None - class OpenTelemetryScope: """Base class for OpenTelemetry tracing scopes in the SDK.""" @@ -78,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, @@ -86,8 +94,8 @@ def __init__( agent_details: "AgentDetails | None" = None, tenant_details: "TenantDetails | None" = None, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the OpenTelemetry scope. @@ -99,19 +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. Can be: - - int: nanoseconds since epoch - - float: seconds since epoch - - tuple[int, int]: HrTime as (seconds, nanoseconds) - - datetime: Python datetime object + 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 in the same format as start_time. + 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._custom_start_time: TimeInput = start_time - self._custom_end_time: TimeInput = end_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 @@ -138,7 +142,7 @@ def __init__( span_context = parent_context if parent_context else context.get_current() # Convert custom start time to OTel-compatible format (nanoseconds since epoch) - otel_start_time = self._time_input_to_ns(start_time) if start_time else None + otel_start_time = self._datetime_to_ns(start_time) self._span = tracer.start_span( activity_name, @@ -256,59 +260,7 @@ def record_attributes(self, attributes: dict[str, Any] | list[tuple[str, Any]]) if key and key.strip(): self._span.set_attribute(key, value) - @staticmethod - def _time_input_to_ns(t: TimeInput) -> int | None: - """Convert a TimeInput value to nanoseconds since epoch. - - OpenTelemetry Python SDK accepts int (nanoseconds since epoch) for span - start_time and end_time parameters. - - Args: - t: TimeInput value which can be: - - int: nanoseconds since epoch (returned as-is) - - float: seconds since epoch - - tuple[int, int]: HrTime as (seconds, nanoseconds) - - datetime: Python datetime object - - Returns: - Nanoseconds since epoch, or None if input is None - """ - if t is None: - return None - if isinstance(t, int): - # Assume nanoseconds if it's an integer - return t - if isinstance(t, float): - # Convert seconds to nanoseconds - return int(t * 1_000_000_000) - if isinstance(t, tuple) and len(t) == 2: - # HrTime: (seconds, nanoseconds) - seconds, nanos = t - return seconds * 1_000_000_000 + nanos - if isinstance(t, datetime): - return int(t.timestamp() * 1_000_000_000) - logger.warning( - f"_time_input_to_ns received unexpected TimeInput " - f"(type={type(t).__name__}); returning None" - ) - return None - - @staticmethod - def _time_input_to_ms(t: TimeInput) -> float | None: - """Convert a TimeInput value to milliseconds since epoch. - - Used for duration calculations. - - Args: - t: TimeInput value (see _time_input_to_ns for accepted types) - - Returns: - Milliseconds since epoch, or None if input is None - """ - ns = OpenTelemetryScope._time_input_to_ns(t) - return ns / 1_000_000 if ns is not None else None - - def set_end_time(self, end_time: TimeInput) -> None: + 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 @@ -316,8 +268,7 @@ def set_end_time(self, end_time: TimeInput) -> None: the operation is known before the scope is disposed. Args: - end_time: The end time as nanoseconds since epoch, seconds since epoch, - HrTime tuple (seconds, nanoseconds), or datetime object. + end_time: The end time as a datetime object. """ self._custom_end_time = end_time @@ -329,7 +280,7 @@ def _end(self) -> None: logger.info(f"Span ended: '{self._span.name}' ({span_id})") # Convert custom end time to OTel-compatible format (nanoseconds since epoch) - otel_end_time = self._time_input_to_ns(self._custom_end_time) + 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: 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 4f526058..873a9dc9 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,10 +1,12 @@ # 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 -from ..opentelemetry_scope import OpenTelemetryScope, TimeInput +from ..opentelemetry_scope import OpenTelemetryScope from ..tenant_details import TenantDetails from ..utils import safe_json_dumps @@ -20,8 +22,8 @@ def start( tenant_details: TenantDetails, response: Response, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ) -> "OutputScope": """Creates and starts a new scope for output tracing. @@ -31,8 +33,8 @@ 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 (ms epoch, Date, or HrTime) - end_time: Optional explicit end time (ms epoch, Date, or HrTime) + 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 @@ -45,8 +47,8 @@ def __init__( tenant_details: TenantDetails, response: Response, parent_id: str | None = None, - start_time: TimeInput = None, - end_time: TimeInput = None, + start_time: datetime | None = None, + end_time: datetime | None = None, ): """Initialize the output scope. @@ -56,8 +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 (ms epoch, Date, or HrTime) - end_time: Optional explicit end time (ms epoch, Date, or HrTime) + start_time: Optional explicit start time as a datetime object. + end_time: Optional explicit end time as a datetime object. """ super().__init__( kind="Client", diff --git a/tests/observability/core/test_custom_start_end_time.py b/tests/observability/core/test_custom_start_end_time.py index cb824c02..080e4caf 100644 --- a/tests/observability/core/test_custom_start_end_time.py +++ b/tests/observability/core/test_custom_start_end_time.py @@ -5,6 +5,7 @@ import os import sys +import time import unittest from datetime import UTC, datetime from pathlib import Path @@ -78,31 +79,6 @@ def _get_finished_span(self): self.assertTrue(finished_spans, "Expected at least one span to be created") return finished_spans[-1] - def test_custom_start_and_end_time_with_nanoseconds(self): - """Test that constructor-provided start and end times are recorded on the span.""" - # Use nanoseconds since epoch - custom_start_ns = 1700000000000000000 # 2023-11-14T22:13:20Z - custom_end_ns = 1700000005000000000 # 5 seconds later - - scope = ExecuteToolScope.start( - self.tool_details, - self.agent_details, - self.tenant_details, - start_time=custom_start_ns, - end_time=custom_end_ns, - ) - scope.dispose() - - span = self._get_finished_span() - - # OTel Python SDK stores times as nanoseconds (int) - span_start_ns = span.start_time - span_end_ns = span.end_time - - # Verify start and end times are close to what we provided - self.assertAlmostEqual(span_start_ns, custom_start_ns, delta=1000) # 1μs tolerance - self.assertAlmostEqual(span_end_ns, custom_end_ns, delta=1000) - 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) @@ -128,84 +104,31 @@ def test_custom_start_and_end_time_with_datetime(self): self.assertAlmostEqual(span_start_ns, expected_start_ns, delta=1000) self.assertAlmostEqual(span_end_ns, expected_end_ns, delta=1000) - def test_custom_start_and_end_time_with_float_seconds(self): - """Test that float seconds are correctly converted to span timestamps.""" - # Float seconds since epoch - custom_start_sec = 1700000000.0 # 2023-11-14T22:13:20Z - custom_end_sec = 1700000005.5 # 5.5 seconds later - - scope = ExecuteToolScope.start( - self.tool_details, - self.agent_details, - self.tenant_details, - start_time=custom_start_sec, - end_time=custom_end_sec, - ) - scope.dispose() - - span = self._get_finished_span() - - expected_start_ns = int(custom_start_sec * 1_000_000_000) - expected_end_ns = int(custom_end_sec * 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_custom_start_and_end_time_with_hrtime_tuple(self): - """Test that HrTime tuples (seconds, nanoseconds) are correctly handled.""" - # HrTime: (seconds, nanoseconds) - custom_start: tuple[int, int] = (1700000000, 0) # 2023-11-14T22:13:20Z - custom_end: tuple[int, int] = (1700000005, 500000000) # 5.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 = custom_start[0] * 1_000_000_000 + custom_start[1] - expected_end_ns = custom_end[0] * 1_000_000_000 + custom_end[1] - - 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_ns = 1700000040000000000 - initial_end_ns = 1700000045000000000 # 5 seconds after start - later_end_ns = 1700000048000000000 # 8 seconds after start + 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_ns, - end_time=initial_end_ns, + start_time=custom_start, + end_time=initial_end, ) # Override the end time - scope.set_end_time(later_end_ns) + 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, later_end_ns, delta=1000) + 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.""" - import time - before = time.time_ns() scope = ExecuteToolScope.start( self.tool_details, @@ -227,22 +150,23 @@ def test_wall_clock_time_used_when_no_custom_times(self): def test_only_start_time_provided(self): """Test that only custom start time can be provided without end time.""" - custom_start_ns = 1700000000000000000 + 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_ns, + 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, custom_start_ns, delta=1000) + 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