Skip to content

fix(tracing): use actual operation timestamps in OpenTelemetry spans #1320

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 1 commit into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
27 changes: 16 additions & 11 deletions nemoguardrails/tracing/adapters/opentelemetry.py
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@

import warnings
from importlib.metadata import version
from typing import TYPE_CHECKING, Optional, Type
from typing import TYPE_CHECKING, Type

if TYPE_CHECKING:
from nemoguardrails.tracing import InteractionLog
Expand Down Expand Up @@ -203,17 +203,22 @@ def _create_span(
spans,
trace_id,
):
with self.tracer.start_as_current_span(
start_time_ns = int(span_data.start_time * 1_000_000_000)
end_time_ns = int(span_data.end_time * 1_000_000_000)

span = self.tracer.start_span(
span_data.name,
context=parent_context,
) as span:
for key, value in span_data.metrics.items():
span.set_attribute(key, value)
start_time=start_time_ns,
)

for key, value in span_data.metrics.items():
span.set_attribute(key, value)

span.set_attribute("span_id", span_data.span_id)
span.set_attribute("trace_id", trace_id)
span.set_attribute("duration", span_data.duration)

span.set_attribute("span_id", span_data.span_id)
span.set_attribute("trace_id", trace_id)
span.set_attribute("start_time", span_data.start_time)
span.set_attribute("end_time", span_data.end_time)
span.set_attribute("duration", span_data.duration)
spans[span_data.span_id] = span

spans[span_data.span_id] = span
span.end(end_time=end_time_ns)
137 changes: 137 additions & 0 deletions tests/test_opentelemetry_timing_behavior.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,137 @@
# SPDX-FileCopyrightText: Copyright (c) 2023 NVIDIA CORPORATION & AFFILIATES. All rights reserved.
# SPDX-License-Identifier: Apache-2.0
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

import time
from typing import List

import pytest
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor

from nemoguardrails.eval.models import Span
from nemoguardrails.tracing import InteractionLog
from nemoguardrails.tracing.adapters.opentelemetry import OpenTelemetryAdapter


class InMemorySpanExporter:
"""Simple in-memory span exporter to capture spans for testing."""

def __init__(self):
self.spans: List = []

def export(self, spans):
self.spans.extend(spans)
return 0 # Success

def shutdown(self):
pass


class TestOpenTelemetryTimingBehavior:
"""
Test that verifies OpenTelemetry spans are created with correct timestamps.

This test focuses on the ACTUAL timing behavior, not implementation details.
It will fail with the old broken code (retrospective timing) and pass with
the fixed code (historical timing).
"""

def setup_method(self):
self.exporter = InMemorySpanExporter()
self.tracer_provider = TracerProvider()
self.tracer_provider.add_span_processor(SimpleSpanProcessor(self.exporter))

trace._TRACER_PROVIDER = None
trace.set_tracer_provider(self.tracer_provider)

self.adapter = OpenTelemetryAdapter()

def teardown_method(self):
# Clean up - reset to no-op
trace._TRACER_PROVIDER = None
trace.set_tracer_provider(trace.NoOpTracerProvider())

def test_spans_use_historical_timestamps_not_current_time(self):
"""
Test that spans are created with historical timestamps from span_data,
not with the current time when transform() is called.

This test will:
- FAIL with old broken code (uses current time)
- PASS with fixed code (uses historical time)
"""
historical_start = 1234567890.5 # January 1, 2009
historical_end = 1234567892.0 # 1.5 seconds later

interaction_log = InteractionLog(
id="timing_test",
activated_rails=[],
events=[],
trace=[
Span(
name="historical_operation",
span_id="span_1",
parent_id=None,
start_time=historical_start,
end_time=historical_end,
duration=1.5,
metrics={"test_metric": 42},
)
],
)

current_time_before = time.time()

self.adapter.transform(interaction_log)

current_time_after = time.time()

assert len(self.exporter.spans) == 1
captured_span = self.exporter.spans[0]

actual_start_time = captured_span.start_time / 1_000_000_000
actual_end_time = captured_span.end_time / 1_000_000_000

assert (
abs(actual_start_time - historical_start) < 0.001
), f"Span start time ({actual_start_time}) should match historical time ({historical_start})"

assert (
abs(actual_end_time - historical_end) < 0.001
), f"Span end time ({actual_end_time}) should match historical time ({historical_end})"

time_diff_start = abs(actual_start_time - current_time_before)
time_diff_end = abs(actual_end_time - current_time_after)

assert time_diff_start > 1000000, (
f"Span start time should be very different from current time. "
f"Difference: {time_diff_start} seconds. This suggests the old bug is present."
)

assert time_diff_end > 1000000, (
f"Span end time should be very different from current time. "
f"Difference: {time_diff_end} seconds. This suggests the old bug is present."
)
actual_duration = actual_end_time - actual_start_time
expected_duration = historical_end - historical_start
assert (
abs(actual_duration - expected_duration) < 0.001
), f"Span duration should be {expected_duration}s, got {actual_duration}s"

assert captured_span.name == "historical_operation"
assert captured_span.attributes.get("test_metric") == 42
assert captured_span.attributes.get("span_id") == "span_1"
assert captured_span.attributes.get("trace_id") == "timing_test"
Loading