Skip to content
Draft
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
162 changes: 139 additions & 23 deletions src/splunk_ao/logger/logger.py

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

src/splunk_ao/logger/logger.py:429-430 (line not in diff)

🟠 major (bug): _discard_otel_identity_tree is now designed to re-raise (first_error), and this is the one call site that isn't guarded.

Every other caller of the raising path wraps it: _release_otel_context (line 683) catches and warns, and _emit_and_release (line 730) catches and warns. But reset_parent_tracking calls _discard_otel_subtree bare, and the method carries no @warn_catch_exception decorator. SplunkAODecorator.init() calls reset_parent_tracking() directly (decorator.py:1433), so an OTel bookkeeping failure here propagates straight into user application code.

This contradicts HYBIM-909's acceptance criterion "Partial OTel bookkeeping failures do not affect proprietary logging" — and note the proprietary reset (_set_current_parent(None)) has already completed by this point, so the only thing that can fail is the OTel side that is explicitly supposed to be non-fatal.

Before this PR the recursive implementation only did dict.pop, so raising was near-impossible in practice; now the accumulate-and-raise contract makes it a real path.

Suggested change
self._set_current_parent(None)
if root is not None:
self._release_otel_context(root)

🤖 Generated by the Astra agent

Original file line number Diff line number Diff line change
Expand Up @@ -136,6 +136,7 @@ class ActiveOtelContext:
logger_id: int
step_id: uuid.UUID
span_context: SpanContext
previous_context: otel_context.Context
token: Token


Expand Down Expand Up @@ -229,6 +230,8 @@ class SplunkAOLogger(TracesLogger):
_task_handler: ThreadPoolTaskHandler
_trace_completion_submitted: bool
_otel_ids: dict[uuid.UUID, OtelIds] = PrivateAttr(default_factory=dict)
_otel_children_by_parent: dict[uuid.UUID, set[uuid.UUID]] = PrivateAttr(default_factory=dict)
_otel_parent_by_child: dict[uuid.UUID, uuid.UUID] = PrivateAttr(default_factory=dict)
_pending_otel_steps: set[uuid.UUID] = PrivateAttr(default_factory=set)

def __init__(
Expand Down Expand Up @@ -368,7 +371,9 @@ def __init__(
"User must provide project_name or project_id to SplunkAOLogger, or set it as an environment variable."
)
if self.experiment_id is None and self.agent_stream_name is None and self.agent_stream_id is None:
raise SplunkAOLoggerException("agent_stream or agent_stream_id is required to initialize SplunkAOLogger.")
raise SplunkAOLoggerException(
"agent_stream or agent_stream_id is required to initialize SplunkAOLogger."
)

if local_metrics:
self.local_metrics = local_metrics
Expand Down Expand Up @@ -438,11 +443,16 @@ def _record_otel_ids(
self, step: BaseStep, parent_step: BaseStep | None = None, parent_span_context: SpanContext | None = None
) -> OtelIds | None:
"""Assign stable OTel identity without disrupting proprietary logging."""
existing_ids = self._otel_ids.get(step.id)
if existing_ids is not None:
return existing_ids
Comment on lines +446 to +448

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 minor (question): This early return is a behavior change that isn't mentioned in the PR description or either ticket.

Previously a second _record_otel_ids(step, parent_step=X) call for an already-recorded step would overwrite the entry with a fresh span_context and the new parent. Now the first identity wins and the requested parent_step is silently discarded — no warning, and the caller gets back an OtelIds whose parent_span_context may not match what it asked for.

I think making insertion idempotent is the right call (it's what keeps the new edge index from accumulating duplicate/conflicting parents), but the silent divergence is the part worth tightening. Two suggestions:

  1. Document the idempotence in the docstring — it's now load-bearing for index consistency, not just an optimization.
  2. If parent_step_id differs from the recorded _otel_parent_by_child.get(step.id), emit a warning. A re-parent attempt indicates a caller bug, and silently ignoring it will be painful to debug once W3C propagation builds on this bookkeeping.

Is there a known call path that re-records a step, or is this purely defensive?

🤖 Generated by the Astra agent


parent_step_id = parent_step.id if parent_step is not None else None
try:
if parent_step is not None:
parent_ids = self._otel_ids.get(parent_step.id)
if parent_ids is None:
raise RuntimeError(f"Missing OTel context for parent step {parent_step.id}.")
raise RuntimeError(f"Missing OTel context for parent step {parent_step_id}.")
parent_span_context = parent_ids.span_context
elif parent_span_context is None:
active_context = otel_trace.get_current_span().get_span_context()
Expand All @@ -459,14 +469,43 @@ def _record_otel_ids(
span_context=self._assign_otel_context(otel_trace_id, trace_state),
parent_span_context=parent_span_context,
)
self._otel_ids[step.id] = ids
self._insert_otel_identity(step.id, ids, parent_step_id)
return ids
except Exception:
self._rollback_otel_identity_insert(step.id, parent_step_id)
self._logger.warning(
"Failed to assign OTel identity for step %s; continuing proprietary logging.", step.id, exc_info=True
)
return None

def _insert_otel_identity(self, step_id: uuid.UUID, ids: OtelIds, parent_step_id: uuid.UUID | None) -> None:
"""Record one identity and its explicit proprietary parent edge."""
self._otel_ids[step_id] = ids
if parent_step_id is None:
return

self._otel_parent_by_child[step_id] = parent_step_id
self._otel_children_by_parent.setdefault(parent_step_id, set()).add(step_id)
Comment on lines +481 to +488

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 minor (design): This PR promotes a single dict into a three-dict invariant (_otel_ids, _otel_parent_by_child, _otel_children_by_parent must agree), but the updates are not atomic and these are instance attributes shared across concurrent requests on the same logger — a configuration the test suite explicitly supports (test_concurrent_traces_on_same_logger_are_isolated, test_concurrent_flush_preserves_other_request_otel_ids).

The GIL makes each individual dict operation safe, so there's no corruption, but the cross-dict invariant can be permanently broken by interleaving. Concretely: thread A inserts child C under parent P and gets as far as _otel_parent_by_child[C] = P; thread B concurrently runs _discard_otel_identity_tree(P), reads _otel_children_by_parent[P] (not yet containing C), and pops P; thread A then executes setdefault(P, set()).add(C), resurrecting a key for an identity that no longer exists. _otel_children_by_parent[P] and _otel_ids[C] are now unreachable by any future cleanup and leak for the lifetime of the logger.

The underlying "child inserted during parent teardown leaks" hazard predates this PR, but the resurrected index key is new and makes the leak strictly worse. Given _otel_children_by_parent grows without bound in a long-lived process, this is worth addressing — a single threading.Lock around _insert_otel_identity / _remove_otel_identity / _discard_otel_identity_tree / _clear_otel_identities would close it cheaply, since these are all short non-blocking critical sections.

HYBIM-909 lists "Concurrent requests sharing a logger cannot remove each other's identities" as acceptance criteria. That holds (UUID keys never collide), but the criteria doesn't cover concurrent insert vs remove, which is where the index diverges. Worth confirming whether that's in scope for this ticket or should be split out.

🤖 Generated by the Astra agent


def _rollback_otel_identity_insert(self, step_id: uuid.UUID, parent_step_id: uuid.UUID | None) -> None:
"""Best-effort rollback for a partially inserted OTel identity."""
with contextlib.suppress(Exception):
self._otel_ids.pop(step_id, None)

recorded_parent_id = parent_step_id
with contextlib.suppress(Exception):
recorded_parent_id = self._otel_parent_by_child.pop(step_id, parent_step_id)

if recorded_parent_id is None:
return

with contextlib.suppress(Exception):
children = self._otel_children_by_parent.get(recorded_parent_id)
if children is not None:
children.discard(step_id)
if not children:
self._otel_children_by_parent.pop(recorded_parent_id, None)

def _open_otel_step_ids(self, current_parent: StepWithChildSpans | None) -> tuple[uuid.UUID, ...]:
"""Return the root-to-current proprietary chain that has OTel identities."""
path: list[uuid.UUID] = []
Expand Down Expand Up @@ -525,22 +564,27 @@ def _sync_otel_context_impl(self, current_parent: StepWithChildSpans | None) ->

detach_failed = False
for active in reversed(active_contexts):
try:
active.token.var.reset(active.token)
except (RuntimeError, ValueError):
# ContextVar tokens cannot be reset from a copied execution
# context. Restore the recorded base before rebuilding below.
otel_context.detach(active.token)
if otel_context.get_current() is not active.previous_context:
# Public detach catches its own errors. Verify the exact
# previously active Context so copied-context failures and
# swallowed no-ops can still trigger deterministic recovery.
detach_failed = True

if detach_failed:
otel_context.attach(base_context)

rebuilt_contexts: list[ActiveOtelContext] = []
for owner_id, step_id, span_context in contexts_to_restore:
ctx = otel_trace.set_span_in_context(NonRecordingSpan(span_context))
previous_context = otel_context.get_current()
ctx = otel_trace.set_span_in_context(NonRecordingSpan(span_context), previous_context)
rebuilt_contexts.append(
ActiveOtelContext(
logger_id=owner_id, step_id=step_id, span_context=span_context, token=otel_context.attach(ctx)
logger_id=owner_id,
step_id=step_id,
span_context=span_context,
previous_context=previous_context,
token=otel_context.attach(ctx),
)
)

Expand All @@ -556,18 +600,83 @@ def _discard_otel_subtree(self, step: BaseStep) -> None:
self._discard_otel_identity_tree(step.id)

def _discard_otel_identity_tree(self, step_id: uuid.UUID) -> None:
"""Remove one identity and all identities parented to it."""
ids = self._otel_ids.pop(step_id, None)
if ids is None:
return
"""Iteratively remove one identity and its indexed descendants."""
worklist = [step_id]
visited: set[uuid.UUID] = set()
first_error: Exception | None = None

while worklist:
current_step_id = worklist.pop()
if current_step_id in visited:
continue
visited.add(current_step_id)

child_ids: tuple[uuid.UUID, ...] = ()
try:
child_ids = tuple(self._otel_children_by_parent.get(current_step_id, ()))
self._otel_children_by_parent.pop(current_step_id, None)
except Exception as exc:
first_error = first_error or exc
worklist.extend(child_ids)

child_ids = tuple(
child_id
for child_id, child_ids in self._otel_ids.items()
if child_ids.parent_span_context == ids.span_context
)
for child_id in child_ids:
self._discard_otel_identity_tree(child_id)
for child_id in child_ids:
try:
self._otel_parent_by_child.pop(child_id, None)
except Exception as exc:
first_error = first_error or exc

try:
self._remove_otel_identity(current_step_id)
except Exception as exc:
first_error = first_error or exc

if first_error is not None:
raise first_error

def _remove_otel_identity(self, step_id: uuid.UUID) -> None:
"""Remove one identity and unlink it from its proprietary parent."""
first_error: Exception | None = None
parent_step_id: uuid.UUID | None = None

try:
parent_step_id = self._otel_parent_by_child.get(step_id)
self._otel_parent_by_child.pop(step_id, None)
except Exception as exc:
first_error = exc

if parent_step_id is not None:
try:
siblings = self._otel_children_by_parent.get(parent_step_id)
if siblings is not None:
try:
siblings.discard(step_id)
except Exception as exc:
first_error = first_error or exc
remaining_siblings = set(siblings)
remaining_siblings.discard(step_id)
if remaining_siblings:
self._otel_children_by_parent[parent_step_id] = remaining_siblings
else:
self._otel_children_by_parent.pop(parent_step_id, None)
else:
if not siblings:
self._otel_children_by_parent.pop(parent_step_id, None)
except Exception as exc:
first_error = first_error or exc

try:
self._otel_ids.pop(step_id, None)
except Exception as exc:
first_error = first_error or exc

if first_error is not None:
raise first_error
Comment on lines +636 to +673

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 minor (design): This method (and the first_error accumulation in _discard_otel_identity_tree) guards against failures that cannot occur, and the cost is ~40 lines of hard-to-follow control flow on a hot cleanup path.

self._otel_parent_by_child.get(...), .pop(...), and self._otel_ids.pop(...) are plain-dict operations keyed by uuid.UUID. UUID.__hash__/__eq__ cannot raise, and these dicts are only ever populated by _insert_otel_identity with plain dict/set values. The nested try/except/else around siblings.discard(step_id) — including the rebuild-the-set-from-scratch fallback at lines 655-660 — is only reachable because test_partial_identity_removal_rebuilds_forward_index_and_does_not_interrupt_logging injects a FailingDiscardSet. The test constructs an impossible state and then the production code carries permanent complexity to satisfy it.

Suggest collapsing to the straightforward version and dropping FailingChildSet/FailingDiscardSet along with _rollback_otel_identity_insert's contextlib.suppress layers:

def _remove_otel_identity(self, step_id: uuid.UUID) -> None:
    """Remove one identity and unlink it from its proprietary parent."""
    parent_step_id = self._otel_parent_by_child.pop(step_id, None)
    if parent_step_id is not None:
        siblings = self._otel_children_by_parent.get(parent_step_id)
        if siblings is not None:
            siblings.discard(step_id)
            if not siblings:
                self._otel_children_by_parent.pop(parent_step_id, None)
    self._otel_ids.pop(step_id, None)

The genuine failure-isolation requirement from HYBIM-909 is already satisfied one level up, where _release_otel_context and _emit_and_release catch and warn. If you'd rather keep the belt-and-braces handling, please at least add a comment explaining which concrete failure it defends against, so the next reader doesn't have to reverse-engineer it from the tests.

🤖 Generated by the Astra agent


def _clear_otel_identities(self) -> None:
"""Clear stable identities and both structural indexes."""
self._otel_ids.clear()
self._otel_children_by_parent.clear()
self._otel_parent_by_child.clear()

def _release_otel_context(self, finished_step: BaseStep) -> None:
"""Release OTel bookkeeping without disrupting proprietary completion."""
Expand Down Expand Up @@ -618,7 +727,14 @@ def _emit_and_release(self, finished_step: BaseStep) -> None:
self._logger.warning("Failed to emit completed step %s.", finished_step.id, exc_info=True)
finally:
self._pending_otel_steps.discard(finished_step.id)
self._otel_ids.pop(finished_step.id, None)
try:
self._remove_otel_identity(finished_step.id)
except Exception:
self._logger.warning(
"Failed to release OTel identity for completed step %s; continuing proprietary logging.",
finished_step.id,
exc_info=True,
)

def _emit_pending_descendants(self, finished_step: BaseStep) -> None:
"""Emit pending descendants in post-order before their enclosing parent."""
Expand Down Expand Up @@ -2457,7 +2573,7 @@ def terminate(self) -> None:
self._logger.warning("SplunkAOLogger.terminate: sink shutdown failed: %s", exc)
finally:
self._set_current_parent(None)
self._otel_ids.clear()
self._clear_otel_identities()
self._pending_otel_steps.clear()
self.traces = []

Expand Down
5 changes: 2 additions & 3 deletions tests/conftest.py
Original file line number Diff line number Diff line change
Expand Up @@ -146,9 +146,8 @@ def _clear_otel_test_context() -> None:

detach_failed = False
for active in reversed(state.active_contexts):
try:
active.token.var.reset(active.token)
except (RuntimeError, ValueError):
otel_context.detach(active.token)
if otel_context.get_current() is not active.previous_context:
detach_failed = True

if detach_failed:
Expand Down
Loading
Loading