-
Notifications
You must be signed in to change notification settings - Fork 3
HYBIM-906, HYBIM-909 - Feat/otel context bookkeeping hardening #208
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
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -136,6 +136,7 @@ class ActiveOtelContext: | |
| logger_id: int | ||
| step_id: uuid.UUID | ||
| span_context: SpanContext | ||
| previous_context: otel_context.Context | ||
| token: Token | ||
|
|
||
|
|
||
|
|
@@ -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__( | ||
|
|
@@ -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 | ||
|
|
@@ -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
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 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:
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() | ||
|
|
@@ -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
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 ( 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 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 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] = [] | ||
|
|
@@ -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), | ||
| ) | ||
| ) | ||
|
|
||
|
|
@@ -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
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟡 minor (design): This method (and the
Suggest collapsing to the straightforward version and dropping 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 🤖 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.""" | ||
|
|
@@ -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.""" | ||
|
|
@@ -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 = [] | ||
|
|
||
|
|
||
There was a problem hiding this comment.
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_treeis 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. Butreset_parent_trackingcalls_discard_otel_subtreebare, and the method carries no@warn_catch_exceptiondecorator.SplunkAODecorator.init()callsreset_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.🤖 Generated by the Astra agent