HYBIM-906, HYBIM-909 - Feat/otel context bookkeeping hardening

[pradystar]

Summary

Harden proprietary logger OpenTelemetry context bookkeeping before W3C propagation work builds on it. This replaces private token access with verified public context detachment and makes identity-subtree cleanup linear.

What changed

• Store the exact OTel context present before each managed context attachment.
• Detach managed contexts exclusively through the public opentelemetry.context.detach() API.
• Verify that detachment restores the expected context object and rebuild from the recorded base context after silent or copied-context detach failures.
• Track proprietary parent/child relationships using explicit step UUID indexes.
• Centralize identity insertion, rollback, release, and clearing.
• Replace recursive identity-map scans with iterative O(V + E) subtree cleanup.
• Preserve interleaved logger and concurrent-request isolation.
• Add deep, wide, partial-subtree, no-scan, failure-rollback, lifecycle, and leaf-release regression coverage.
• Update test cleanup to avoid private ContextVar token access.

For DTB, this preserves stable trace/span identities, explicit parentage, request isolation, and context release at the existing completion seams while completed spans continue to enqueue independently.

[fercor-cisco]

🤖 This review was generated by the Astra agent (claude-opus-5). It may contain mistakes.

Verdict: request_changes — Two reachable regressions: reset_parent_tracking() now propagates OTel bookkeeping exceptions into user code, and the copied-async-context path that the PR claims to preserve now emits ERROR-level tracebacks from the OTel SDK on every occurrence.

General Comments

• 🟠 major (bug): The switch to public detach() turns a silently-handled condition into user-visible ERROR logs on the copied-async-context path.

HYBIM-906 acceptance criteria says "Copied async/execution contexts still rebuild from the recorded base context." The rebuild still works, but the cost of detecting failure has changed in a way the PR doesn't account for.

The old code called active.token.var.reset(active.token) and caught (RuntimeError, ValueError) itself — completely silent. opentelemetry.context.detach() instead wraps the same reset() in except Exception: logger.exception("Failed to detach context"), which emits an ERROR record with a full traceback on the opentelemetry.context logger.

This is reachable on a normal path, not a pathological one. _sync_otel_context_impl detaches every entry in active_contexts, not just those attached in the current execution context. In test_copied_async_context_can_add_and_conclude_child, the root's token is attached in the parent task; logger.conclude() inside the child task detaches it, and ContextVar.reset() raises ValueError: Token was created in a different Context. So every async-task-scoped child span conclusion now produces an ERROR + stack trace that SDK users see and cannot suppress without silencing the OTel context logger wholesale. For an observability SDK whose stated design goal is "without disrupting proprietary logging," emitting spurious ERROR tracebacks during correct, expected operation is a meaningful regression.

Options:

1. Detect the copied-context case before calling detach() — e.g. only detach tokens whose previous_context matches otel_context.get_current(), and go straight to the base-context rebuild otherwise. This uses the public API and avoids provoking the logged exception at all.
2. Temporarily raise the level of / filter the opentelemetry.context logger around the detach loop. Works, but is fragile and couples you to the SDK's logger name.

Option 1 seems clearly better and stays within the ticket's constraint. Whichever you pick, please add a caplog assertion to test_copied_async_context_can_add_and_conclude_child that no ERROR records are emitted on that path — the current tests assert recovery but say nothing about log cleanliness, which is exactly why this slipped through.

Follow-ups

Suggested follow-up work that could be tracked as Jira tickets:

• src/splunk_ao/logger/logger.py:574-575: otel_context.attach(base_context) discards the returned token, so the recovery path leaks one attach level on the OTel context stack every time detach_failed is set. Pre-existing (the same line existed before this PR), but the new verification logic makes detach_failed reachable in strictly more situations, so the leak will trigger more often. Consider recording this token in OtelContextState so it can be detached during the next reconciliation, or documenting why the leak is acceptable.
• tests/conftest.py:141-155: _clear_otel_test_context now duplicates the detach/verify/rebuild algorithm from _sync_otel_context_impl verbatim. The two copies will drift as the production logic evolves (and the fix for the ERROR-log regression will need applying twice). Consider extracting a module-level helper in logger.py — e.g. _detach_all_managed_contexts(state) -> bool — that both the production reconciler and the test fixture call.
• tests/test_logger_otel_context.py:339-360: HYBIM-909's acceptance criteria asks for "a benchmark or targeted performance test [that] demonstrates linear cleanup behavior." The deep/wide tests at 1500/1000 nodes assert correctness but never assert anything about complexity — they'd pass just as well against the old O(n^2) recursive implementation (modulo the recursion limit on the deep case). test_partial_identity_cleanup_preserves_siblings_and_never_scans_unrelated_ids is a good structural proxy via ItemsForbiddenIdentityMap, but it only proves "no full scan" for one small fixed tree. Consider adding a scaling assertion (e.g. cleanup work at 2N is within a small constant factor of N) or an explicit operation counter to close the criterion.

[fercor-cisco]

🟡 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

[fercor-cisco]

🟡 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

[fercor-cisco]

🟡 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

[fercor-cisco]

🟡 minor (testing): Asserting on inspect.getsource(...) string content tests the implementation's text rather than its behavior, and it's brittle in both directions:

• False pass: the private access could be reintroduced as token . var, getattr(token, "var"), or simply moved into a helper called by _sync_otel_context_impl — all of which the substring check misses while the guarded property is genuinely violated.
• False fail: a pure refactor that renames the otel_context import alias breaks the test with no behavior change.

It also silently stops protecting anything if the method is ever split, since only _sync_otel_context_impl's own source is inspected.

The two tests above it (..._detaches_in_lifo_order_and_verifies_previous_context and ..._recovers_when_public_detach_is_a_silent_noop) already give real coverage: by monkeypatching context.detach and asserting call_count == 2, they prove the production code routes through the public API — if it used token.var.reset directly, the patched detach would never be invoked and those assertions would fail. That's behavioral proof of the same property.

Suggest deleting this test as redundant, or if you want an explicit guard against private-API reintroduction, make it a lint rule (a ruff/semgrep pattern for \.token\.var) rather than a runtime assertion, so it covers the whole module instead of one method.

🤖 Generated by the Astra agent

[fercor-cisco]

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