Skip to content

Commit 7d29bfa

Browse files
authored
fix(bigquery-analytics): stop exporting plugin-owned OTel spans (google#94) (#5)
When Agent Engine telemetry is enabled (GOOGLE_CLOUD_AGENT_ENGINE_ENABLE_TELEMETRY=true) and Cloud Trace export is configured on the global OTel tracer provider, the BigQuery Agent Analytics plugin causes every instrumented operation to appear as TWO spans in Cloud Trace — the framework's real span plus a duplicate plugin-owned span. Reported in GoogleCloudPlatform/BigQuery-Agent-Analytics-SDK#94 (also at haiyuan-eng-google#94) by a regular BQAA + Agent Engine user. Root cause ---------- TraceManager.push_span() called tracer.start_span(...) purely as an ID carrier, so the plugin could populate BigQuery span_id / parent_span_id columns. The author was aware of one related class of pitfall (re-parenting the framework's spans — fixed by not attaching the plugin span to the ambient context, see google#4561), but that guard does not stop the plugin span from going through the configured SpanProcessor → BatchSpanProcessor → Cloud Trace exporter. Once Agent Engine wires the global provider to Cloud Trace, every push/pop pair is exported. The plugin already tracked every parent/child relationship on its own contextvar-backed _SpanRecord stack — the OTel span object was incidental to correctness. Fix (scoped to TraceManager methods + _SpanRecord) ------------------------------------------------- * _SpanRecord no longer holds an OTel span object. It carries span_id, trace_id, owns_span, start_time_ns, first_token_time. * push_span generates a 16-hex span_id directly and inherits trace_id by precedence: top of internal stack → ambient OTel span → freshly generated 32-hex. No tracer.start_span call. * attach_current_span extracts trace_id/span_id from the ambient span (the existing path the framework already supports) and stores them as plain strings — no longer holds the OTel object. * pop_span / clear_stack drop the .end()/.start_time machinery since there is no OTel span to end. * get_trace_id / get_start_time read directly from the record. The signatures of push_span / attach_current_span / pop_span / clear_stack / get_trace_id / get_start_time are unchanged. Module-level `tracer = trace.get_tracer(...)` is retained for ABI compat (currently unused by plugin code; can be removed in a follow-up if no external consumers are identified). attach_current_span() is otherwise untouched — it only observed the ambient span; it never created one. That path was already correct and remains so. Cross-system correlation ------------------------ BigQuery rows still carry trace_id, inherited from the ambient Agent Engine / Runner span when present. Joining `agent_events` to Cloud Trace by trace_id continues to work end-to-end. Tests ----- Three existing tests that were directly asserting the bug (test_otel_integration, test_otel_integration_real_provider, test_clear_stack_ends_owned_spans) are rewritten as inverted regression guards: * test_push_pop_does_not_call_tracer_start_span * test_push_pop_does_not_export_spans_through_real_provider * test_clear_stack_does_not_export_spans Each asserts that the corresponding code path does NOT export an OTel span via an InMemorySpanExporter wired to a real provider, or does NOT invoke tracer.start_span via a mock spy. Four new tests added to lock in the lifecycle / inheritance contracts the plugin must keep: * test_push_span_inherits_ambient_trace_id — when an ambient OTel span exists (the Agent Engine pattern), the plugin's trace_id matches it. * test_llm_request_response_share_span_id_contract — the paired LLM_REQUEST / LLM_RESPONSE rows share one span_id (the documented BQAA join contract). * test_tool_starting_completed_share_span_id_contract — same invariant for the tool lifecycle pair. * test_streaming_llm_response_shares_span_id_until_final_contract — multiple partial LLM_RESPONSE callbacks reuse the same span_id and only the final fire pops the span. Prevents a future "dedupe" of streaming rows from breaking the contract. 226/229 plugin tests pass (6 skipped for unrelated optional deps); pyink + isort clean. Refs: - haiyuan-eng-google/BigQuery-Agent-Analytics-SDK#94 (reported by a customer) - google#4561 (prior fix for span-hierarchy re-parenting) - google#4645 (prior fix for trace_id fracture)
1 parent e5c0d8b commit 7d29bfa

2 files changed

Lines changed: 315 additions & 154 deletions

File tree

src/google/adk/plugins/bigquery_agent_analytics_plugin.py

Lines changed: 83 additions & 91 deletions
Original file line numberDiff line numberDiff line change
@@ -634,20 +634,35 @@ class BigQueryLoggerConfig:
634634

635635
@dataclass
636636
class _SpanRecord:
637-
"""A single record on the unified span stack.
638-
639-
Consolidates span, id, ownership, and timing into one object
640-
so all stacks stay in sync by construction.
641-
642-
Note: The plugin intentionally does NOT attach its spans to the
643-
ambient OTel context (no ``context.attach``). This prevents the
644-
plugin from corrupting the framework's span hierarchy when an
645-
external OTel exporter (e.g. ``opentelemetry-instrumentation-vertexai``)
646-
is active. See https://github.com/google/adk-python/issues/4561.
637+
"""A single record on the BQAA plugin's internal span stack.
638+
639+
Stores the IDs and timing the plugin needs to populate BigQuery
640+
``span_id`` / ``parent_span_id`` / ``trace_id`` / ``latency_ms``
641+
columns. Crucially, no OpenTelemetry ``Span`` object is held.
642+
643+
Background — prior approach and the bug it caused:
644+
The previous implementation created real OTel spans via
645+
``tracer.start_span(...)`` purely as ID carriers. When the host
646+
application has an OTel exporter configured (notably Agent Engine
647+
with ``GOOGLE_CLOUD_AGENT_ENGINE_ENABLE_TELEMETRY=true``), those
648+
plugin-owned spans were exported to Cloud Trace alongside the
649+
framework's real spans — producing a duplicate-span view for
650+
every BQAA-instrumented operation. See haiyuan-eng-google/BQAA-SDK#94.
651+
652+
The plugin already tracked all parent / child relationships on
653+
this internal stack, so the OTel span object was incidental to
654+
correctness. We now store ``trace_id`` directly on each record
655+
(inherited from the ambient OTel span when present, generated
656+
otherwise) and skip span creation entirely. Cross-system
657+
correlation with Cloud Trace still works via ``trace_id``
658+
inheritance.
659+
660+
``attach_current_span`` (which observes the ambient span without
661+
owning one) is unaffected by this change.
647662
"""
648663

649-
span: trace.Span
650664
span_id: str
665+
trace_id: str
651666
owns_span: bool
652667
start_time_ns: int
653668
first_token_time: Optional[float] = None
@@ -689,17 +704,16 @@ def init_trace(callback_context: CallbackContext) -> None:
689704

690705
@staticmethod
691706
def get_trace_id(callback_context: CallbackContext) -> Optional[str]:
692-
"""Gets the trace ID from the current span or invocation_id."""
707+
"""Gets the trace ID from the current span stack or invocation_id."""
693708
records = _span_records_ctx.get()
694709
if records:
695-
current_span = records[-1].span
696-
if current_span.get_span_context().is_valid:
697-
return format(current_span.get_span_context().trace_id, "032x")
710+
return records[-1].trace_id
698711

699-
# Fallback to OTel context
700-
current_span = trace.get_current_span()
701-
if current_span.get_span_context().is_valid:
702-
return format(current_span.get_span_context().trace_id, "032x")
712+
# Fallback to ambient OTel context (e.g. callbacks fired before
713+
# any plugin span was pushed).
714+
ambient_ctx = trace.get_current_span().get_span_context()
715+
if ambient_ctx.is_valid:
716+
return format(ambient_ctx.trace_id, "032x")
703717

704718
return callback_context.invocation_id
705719

@@ -708,78 +722,80 @@ def push_span(
708722
callback_context: CallbackContext,
709723
span_name: Optional[str] = "adk-span",
710724
) -> str:
711-
"""Starts a new span and pushes it onto the stack.
712-
713-
The span is created but NOT attached to the ambient OTel context,
714-
so it cannot corrupt the framework's own span hierarchy. The
715-
plugin tracks span_id / parent_span_id internally via its own
716-
contextvar stack.
717-
718-
If OTel is not configured (returning non-recording spans), a UUID
719-
fallback is generated to ensure span_id and parent_span_id are
720-
populated in BigQuery logs.
725+
"""Pushes a BQAA-internal span record onto the stack.
726+
727+
No OpenTelemetry span is created — see ``_SpanRecord`` for
728+
background. The record carries everything the plugin needs to
729+
populate BigQuery columns:
730+
731+
* ``span_id`` — newly generated 16-hex string.
732+
* ``trace_id`` — inherited by precedence:
733+
1. Top of the existing internal stack (keeps every push
734+
within an invocation under one trace_id).
735+
2. Ambient OTel span when valid (e.g. the framework's Runner
736+
span, or an Agent Engine root span) — keeps BigQuery rows
737+
joinable to Cloud Trace via the shared ``trace_id``.
738+
3. A fresh 32-hex value (no ambient context, e.g. unit tests
739+
or non-OTel runtimes).
740+
* ``start_time_ns`` — for the eventual ``latency_ms`` on pop.
741+
742+
``span_name`` is preserved on the signature for API stability but
743+
is no longer used (no OTel span name is set).
721744
"""
745+
del span_name # No-op: kept for API stability; no OTel span is created.
722746
TraceManager.init_trace(callback_context)
723747

724-
# Create the span without attaching it to the ambient context.
725-
# This avoids re-parenting framework spans like ``call_llm``
726-
# or ``execute_tool``. See #4561.
727-
#
728-
# If the internal stack already has a span, create the new span
729-
# as a child so it shares the same trace_id. Without this, each
730-
# ``start_span`` would be an independent root with its own
731-
# trace_id — causing trace_id fracture (see #4645).
732748
records = TraceManager._get_records()
733-
parent_ctx = None
734-
if records and records[-1].span.get_span_context().is_valid:
735-
parent_ctx = trace.set_span_in_context(records[-1].span)
736-
span = tracer.start_span(span_name, context=parent_ctx)
737-
738-
if span.get_span_context().is_valid:
739-
span_id_str = format(span.get_span_context().span_id, "016x")
749+
if records:
750+
trace_id = records[-1].trace_id
740751
else:
741-
span_id_str = uuid.uuid4().hex
752+
ambient_ctx = trace.get_current_span().get_span_context()
753+
if ambient_ctx.is_valid:
754+
trace_id = format(ambient_ctx.trace_id, "032x")
755+
else:
756+
trace_id = uuid.uuid4().hex # 32 hex chars
757+
758+
span_id_str = uuid.uuid4().hex[:16]
742759

743760
record = _SpanRecord(
744-
span=span,
745761
span_id=span_id_str,
762+
trace_id=trace_id,
746763
owns_span=True,
747764
start_time_ns=time.time_ns(),
748765
)
749-
750-
new_records = list(records) + [record]
751-
_span_records_ctx.set(new_records)
766+
_span_records_ctx.set(list(records) + [record])
752767

753768
return span_id_str
754769

755770
@staticmethod
756771
def attach_current_span(
757772
callback_context: CallbackContext,
758773
) -> str:
759-
"""Records the current OTel span on the stack without owning it.
774+
"""Records the ambient OTel span's IDs on the stack without owning it.
760775
761-
The span is NOT re-attached to the ambient context; it is only
762-
tracked internally for span_id / parent_span_id resolution.
776+
No OTel span is created or attached. This path captures the
777+
ambient span's ``trace_id`` / ``span_id`` so plugin-emitted
778+
BigQuery rows correlate with whatever Cloud Trace / external
779+
exporter the host is already running.
763780
"""
764781
TraceManager.init_trace(callback_context)
765782

766-
span = trace.get_current_span()
767-
768-
if span.get_span_context().is_valid:
769-
span_id_str = format(span.get_span_context().span_id, "016x")
783+
ambient_ctx = trace.get_current_span().get_span_context()
784+
if ambient_ctx.is_valid:
785+
span_id_str = format(ambient_ctx.span_id, "016x")
786+
trace_id = format(ambient_ctx.trace_id, "032x")
770787
else:
771-
span_id_str = uuid.uuid4().hex
788+
span_id_str = uuid.uuid4().hex[:16]
789+
trace_id = uuid.uuid4().hex
772790

773791
record = _SpanRecord(
774-
span=span,
775792
span_id=span_id_str,
793+
trace_id=trace_id,
776794
owns_span=False,
777795
start_time_ns=time.time_ns(),
778796
)
779-
780797
records = TraceManager._get_records()
781-
new_records = list(records) + [record]
782-
_span_records_ctx.set(new_records)
798+
_span_records_ctx.set(list(records) + [record])
783799

784800
return span_id_str
785801

@@ -828,10 +844,10 @@ def ensure_invocation_span(
828844

829845
@staticmethod
830846
def pop_span() -> tuple[Optional[str], Optional[int]]:
831-
"""Ends the current span and pops it from the stack.
847+
"""Pops the top span record from the internal stack.
832848
833-
No ambient OTel context is detached because we never attached
834-
one in the first place (see ``push_span``).
849+
Returns ``(span_id, duration_ms)``. No OTel span is ended
850+
because the plugin no longer creates one (see ``_SpanRecord``).
835851
"""
836852
records = _span_records_ctx.get()
837853
if not records:
@@ -841,29 +857,13 @@ def pop_span() -> tuple[Optional[str], Optional[int]]:
841857
record = new_records.pop()
842858
_span_records_ctx.set(new_records)
843859

844-
# Calculate duration
845-
duration_ms = None
846-
otel_start = getattr(record.span, "start_time", None)
847-
if isinstance(otel_start, (int, float)) and otel_start:
848-
duration_ms = int((time.time_ns() - otel_start) / 1_000_000)
849-
else:
850-
duration_ms = int((time.time_ns() - record.start_time_ns) / 1_000_000)
851-
852-
if record.owns_span:
853-
record.span.end()
854-
860+
duration_ms = int((time.time_ns() - record.start_time_ns) / 1_000_000)
855861
return record.span_id, duration_ms
856862

857863
@staticmethod
858864
def clear_stack() -> None:
859865
"""Clears all span records. Safety net for cross-invocation cleanup."""
860-
records = _span_records_ctx.get()
861-
if records:
862-
# End any owned spans to avoid OTel resource leaks.
863-
for record in reversed(records):
864-
if record.owns_span:
865-
record.span.end()
866-
_span_records_ctx.set([])
866+
_span_records_ctx.set([])
867867

868868
@staticmethod
869869
def get_current_span_and_parent() -> tuple[Optional[str], Optional[str]]:
@@ -894,19 +894,11 @@ def get_root_agent_name() -> Optional[str]:
894894

895895
@staticmethod
896896
def get_start_time(span_id: str) -> Optional[float]:
897-
"""Gets start time of a span by ID."""
897+
"""Gets start time of a span by ID (seconds since epoch)."""
898898
records = _span_records_ctx.get()
899899
if records:
900900
for record in reversed(records):
901901
if record.span_id == span_id:
902-
# Try OTel span start_time first
903-
otel_start = getattr(record.span, "start_time", None)
904-
if (
905-
record.span.get_span_context().is_valid
906-
and isinstance(otel_start, (int, float))
907-
and otel_start
908-
):
909-
return otel_start / 1_000_000_000.0
910902
return record.start_time_ns / 1_000_000_000.0
911903
return None
912904

0 commit comments

Comments
 (0)