Skip to content

Commit 2d9eaed

Browse files
observability: phase 6.1 PR-B logs SDK migration + filter bug fix
The OTel SDK's ``opentelemetry.sdk._logs.LoggingHandler`` is deprecated and slated for removal in SDK 2.x. Migrate ``install_log_bridge`` to use the handler from ``opentelemetry-instrumentation-logging`` (the package the SDK's deprecation message points at) so the deprecation goes away and the bridge keeps working past SDK 2.x. Constructor shape is unchanged (``LoggingHandler(level=..., logger_provider=...)``); the contrib package's main public class is ``LoggingInstrumentor`` but it's too opinionated for our use (reads ``get_logger_provider()`` globally and overrides the logging format) — direct handler import is the documented escape hatch for callers like us with a caller-supplied LoggerProvider. Dependency changes: - Add ``opentelemetry-instrumentation-logging>=0.62.0b1`` to the ``[otel]`` extras. No upper bound — the contrib repo cycles fast on minor releases below 1.0; revisit when 1.0 lands. - Drop ``<2`` upper bound on ``opentelemetry-sdk``; replace with ``<3`` as a coarse safety cap. We no longer reach into the deprecated path that prompted the original cap. Same shape on ``opentelemetry-api`` for parity. - Remove the Phase 6.0 pending-migration comment block from ``pyproject.toml``. The migration's new export-path test surfaced a real spec §7 violation in the existing bridge: ``_CorrelationIdFilter`` was attached to the root logger, but Python's logging propagation walks ancestor handlers and SKIPS ancestor filters, so child- logger records (the normal ``logging.getLogger("module")`` pattern) shipped to the OTel exporter without the §7-mandated ``openarmature.correlation_id`` attribute. The existing ``test_log_bridge_filter_injects_correlation_id`` only called ``flt.filter()`` directly, never integration-tested through ``install_log_bridge`` + a child-logger emit + an export, which is why the bug went unobserved through Phase 6.0 review, round-7 followups, PR-A merge, and the fixture-031 span tests. Fix: replace ``_CorrelationIdFilter`` with a process-global ``logging.setLogRecordFactory`` hook. The factory chains over any prior factory (preserving user-installed factories), reads ``current_correlation_id()`` at record construction, and sets ``openarmature.correlation_id`` on every newly constructed record — but only when a correlation_id is in scope per §7's "within an invocation" qualifier. ``_FACTORY_MARKER`` attribute on the wrapper function turns re-calls into no-ops; no stacked-wrapper pathology. Tests: - ``test_log_bridge_filter_injects_correlation_id`` → ``test_log_record_factory_injects_correlation_id`` (calls the installed factory directly, asserts null-cid + live-cid paths). - ``test_install_log_bridge_is_idempotent`` extended to assert factory identity is preserved across re-calls. Wrapped in ``warnings.catch_warnings("error")`` so the migrated path's "no DeprecationWarning" guarantee is locked in. - New ``test_log_bridge_exports_records_with_correlation_id`` emits on a CHILD logger (the load-bearing case) and asserts the exported OTel ``LogRecord.attributes`` carry ``openarmature.correlation_id``. Wrapped in ``warnings.catch_warnings("error")``. 388 tests pass (was 387; net +1 from the new export-path test). Pyright clean. The DeprecationWarning emitted by the prior implementation is gone (warnings count: 4 → 3, the 3 remaining are pre-existing intentional ``UserWarning``s from fixture 015-observer-error-isolation).
1 parent c2c1eda commit 2d9eaed

4 files changed

Lines changed: 313 additions & 88 deletions

File tree

pyproject.toml

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -22,13 +22,13 @@ dependencies = [
2222
# dependencies. Plan to lift into a sibling ``openarmature-otel``
2323
# package at v1.0 launch alongside ``openarmature-eval``.
2424
otel = [
25-
# Upper bound guards against the SDK 2.x release that removes
26-
# ``opentelemetry.sdk._logs.LoggingHandler`` (currently emits a
27-
# DeprecationWarning). Migration to
28-
# ``opentelemetry-instrumentation-logging`` lands in Phase 6.1
29-
# before bumping the upper bound.
30-
"opentelemetry-api>=1.27,<2",
31-
"opentelemetry-sdk>=1.27,<2",
25+
"opentelemetry-api>=1.27,<3",
26+
"opentelemetry-sdk>=1.27,<3",
27+
# Provides ``LoggingHandler`` after the SDK's deprecation
28+
# of ``opentelemetry.sdk._logs.LoggingHandler``. No upper
29+
# bound — the contrib repo cycles fast on minor releases
30+
# below 1.0; revisit when 1.0 lands.
31+
"opentelemetry-instrumentation-logging>=0.62.0b1",
3232
]
3333

3434
[project.urls]

src/openarmature/observability/otel/logs.py

Lines changed: 63 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -8,36 +8,67 @@
88
Opt-in by design: users may have their own logging configuration we
99
shouldn't override silently. Calling ``install_log_bridge(provider)``
1010
explicitly attaches an OTel ``LoggingHandler`` to the root logger
11-
and registers a filter that injects the correlation_id from the
12-
ContextVar.
11+
and installs a process-global ``LogRecord`` factory that injects
12+
the correlation_id from the ContextVar.
1313
"""
1414

1515
from __future__ import annotations
1616

1717
import logging
18-
from typing import TYPE_CHECKING
18+
from typing import TYPE_CHECKING, Any
1919

2020
if TYPE_CHECKING:
2121
from opentelemetry.sdk._logs import LoggerProvider
2222

2323

24-
class _CorrelationIdFilter(logging.Filter):
25-
"""Logging filter that reads the openarmature correlation_id
26-
ContextVar and attaches it to every log record as the
27-
``openarmature.correlation_id`` attribute. Per spec §7 the
28-
attribute MUST appear on every log record emitted during an
29-
invocation."""
24+
# Marker attribute used to detect "this is the OA-installed
25+
# LogRecord factory" so re-calling ``install_log_bridge`` doesn't
26+
# stack a second wrapper on top of the already-installed one.
27+
_FACTORY_MARKER = "_openarmature_correlation_factory"
28+
29+
30+
def _install_correlation_id_factory() -> None:
31+
"""Install a process-global :class:`logging.LogRecord` factory
32+
that reads the openarmature correlation_id ContextVar and
33+
attaches it to every constructed record as the
34+
``openarmature.correlation_id`` attribute.
35+
36+
Why a factory instead of a logger filter: filters added to the
37+
ROOT logger only fire for records originating directly on the
38+
root logger — Python's logging propagation walks ancestors'
39+
HANDLERS but not their filters. A filter on root therefore
40+
misses every record from a child logger (the normal case;
41+
every reasonable user does ``logger = logging.getLogger("module")``).
42+
Spec §7 mandates the attribute appear on records emitted from
43+
"anywhere within an invocation" — the factory hooks at record
44+
construction, fires uniformly for every emit regardless of
45+
which logger originated the record, and chains over any
46+
user-installed factory rather than replacing it.
47+
48+
Idempotent: re-calling skips installation if the current
49+
factory is already the OA-installed one.
50+
"""
51+
from openarmature.observability.correlation import current_correlation_id
52+
53+
current_factory = logging.getLogRecordFactory()
54+
if getattr(current_factory, _FACTORY_MARKER, False):
55+
# Already installed — re-calling is a no-op.
56+
return
3057

31-
def filter(self, record: logging.LogRecord) -> bool:
32-
from openarmature.observability.correlation import current_correlation_id
58+
prior_factory = current_factory
3359

60+
def _correlation_id_factory(*args: Any, **kwargs: Any) -> logging.LogRecord:
61+
record = prior_factory(*args, **kwargs)
3462
cid = current_correlation_id()
3563
if cid is not None:
3664
# Stored on the log record so any formatter/handler that
3765
# reads ``record.__dict__`` (including the OTel
3866
# LoggingHandler) sees it.
3967
setattr(record, "openarmature.correlation_id", cid)
40-
return True
68+
return record
69+
70+
setattr(_correlation_id_factory, _FACTORY_MARKER, True)
71+
logging.setLogRecordFactory(_correlation_id_factory)
4172

4273

4374
def install_log_bridge(
@@ -47,32 +78,31 @@ def install_log_bridge(
4778
) -> None:
4879
"""Wire the stdlib root logger to the supplied OTel
4980
:class:`LoggerProvider`. Adds a
50-
:class:`opentelemetry.sdk._logs.LoggingHandler` for OTel-native
51-
``trace_id`` / ``span_id`` bridging, AND attaches an
52-
:class:`_CorrelationIdFilter` directly to the ROOT LOGGER (not
53-
the handler) so the ``openarmature.correlation_id`` attribute
54-
lands on every log record emitted during an invocation —
55-
including records consumed by pre-existing stdout / file /
56-
third-party handlers the user already had configured.
57-
58-
Filter-on-the-root-logger placement matters per spec §7:
59-
"log records emitted from anywhere within an invocation MUST
60-
carry ``openarmature.correlation_id``." A handler-level filter
61-
would only modify records flowing through THAT handler, so a
62-
user's existing stdout handler would see records without the
63-
attribute. The root-logger filter applies to every record,
64-
regardless of which handler eventually processes it.
81+
:class:`opentelemetry.instrumentation.logging.handler.LoggingHandler`
82+
for OTel-native ``trace_id`` / ``span_id`` bridging, AND
83+
installs a process-global :class:`logging.LogRecord` factory
84+
that injects ``openarmature.correlation_id`` on every record.
85+
86+
The factory placement matters per spec §7: "log records
87+
emitted from anywhere within an invocation MUST carry
88+
``openarmature.correlation_id``." Filters added to the root
89+
logger fire only for records originating on root — Python's
90+
propagation walks ancestor handlers but not ancestor filters
91+
— so a root-logger filter misses every child-logger record.
92+
The factory hook fires at record construction time, before any
93+
logger or handler dispatch, so every record gets the
94+
attribute regardless of which logger originated it.
6595
6696
Idempotent: re-calling is a no-op (we check for the existing
67-
OA-tagged handler AND for an existing filter instance on the
68-
root logger).
97+
OA-tagged handler on the root logger AND for the OA-installed
98+
factory marker on the current global factory).
6999
70100
The user retains responsibility for providing the
71101
:class:`LoggerProvider` (typically built with their preferred
72-
exporter — :class:`InMemoryLogExporter` for tests,
102+
exporter — :class:`InMemoryLogRecordExporter` for tests,
73103
:class:`OTLPLogExporter` for production).
74104
"""
75-
from opentelemetry.sdk._logs import LoggingHandler # type: ignore[attr-defined]
105+
from opentelemetry.instrumentation.logging.handler import LoggingHandler
76106

77107
root = logging.getLogger()
78108
# Idempotency #1: don't double-add the OTel LoggingHandler.
@@ -87,11 +117,8 @@ def install_log_bridge(
87117
# marker behavior.
88118
object.__setattr__(handler, "_openarmature_installed", True)
89119
root.addHandler(handler)
90-
# Idempotency #2: don't double-add the correlation_id filter to
91-
# the root logger.
92-
filter_already_installed = any(isinstance(f, _CorrelationIdFilter) for f in root.filters)
93-
if not filter_already_installed:
94-
root.addFilter(_CorrelationIdFilter())
120+
# Idempotency #2: don't stack the LogRecord factory.
121+
_install_correlation_id_factory()
95122

96123

97124
__all__ = [

tests/unit/test_observability_otel.py

Lines changed: 147 additions & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -303,70 +303,174 @@ async def test_disable_llm_spans_skips_llm_provider_span() -> None:
303303
# ---------------------------------------------------------------------------
304304

305305

306-
def test_log_bridge_filter_injects_correlation_id() -> None:
306+
def test_log_record_factory_injects_correlation_id() -> None:
307307
"""Spec §7: every log record emitted during an invocation MUST
308-
carry ``openarmature.correlation_id``. The bridge's filter reads
309-
the ContextVar and attaches it to the LogRecord."""
308+
carry ``openarmature.correlation_id``. The bridge installs a
309+
process-global :class:`logging.LogRecord` factory (rather than
310+
a logger-level filter) so the attribute lands on every record
311+
regardless of which logger originated it — Python's logging
312+
propagates records up the logger tree's HANDLERS but skips
313+
ancestor FILTERS, so a filter on root would miss any
314+
child-logger emit.
315+
316+
Tests both null-cid (outside invocation) and live-cid paths."""
310317
from openarmature.observability.correlation import (
311318
_reset_correlation_id,
312319
_set_correlation_id,
313320
)
314-
from openarmature.observability.otel.logs import _CorrelationIdFilter
315-
316-
flt = _CorrelationIdFilter()
317-
record = logging.LogRecord(
318-
name="test",
319-
level=logging.INFO,
320-
pathname="",
321-
lineno=0,
322-
msg="hello",
323-
args=None,
324-
exc_info=None,
321+
from openarmature.observability.otel.logs import (
322+
_install_correlation_id_factory,
325323
)
326-
# Outside an invocation: no correlation_id attribute set.
327-
assert flt.filter(record) is True
328-
assert not hasattr(record, "openarmature.correlation_id")
329-
330-
# Inside an invocation: filter attaches the ContextVar value.
331-
record2 = logging.LogRecord(
332-
name="test",
333-
level=logging.INFO,
334-
pathname="",
335-
lineno=0,
336-
msg="hello",
337-
args=None,
338-
exc_info=None,
339-
)
340-
token = _set_correlation_id("my-cid-42")
324+
325+
prior_factory = logging.getLogRecordFactory()
341326
try:
342-
flt.filter(record2)
327+
_install_correlation_id_factory()
328+
factory = logging.getLogRecordFactory()
329+
330+
# Outside an invocation: no correlation_id attribute set.
331+
record = factory(
332+
"any.child.logger",
333+
logging.INFO,
334+
"",
335+
0,
336+
"hello",
337+
None,
338+
None,
339+
)
340+
assert not hasattr(record, "openarmature.correlation_id")
341+
342+
# Inside an invocation: factory attaches the ContextVar
343+
# value to every newly constructed record.
344+
token = _set_correlation_id("my-cid-42")
345+
try:
346+
record2 = factory(
347+
"any.child.logger",
348+
logging.INFO,
349+
"",
350+
0,
351+
"hello",
352+
None,
353+
None,
354+
)
355+
finally:
356+
_reset_correlation_id(token)
357+
assert getattr(record2, "openarmature.correlation_id") == "my-cid-42"
343358
finally:
344-
_reset_correlation_id(token)
345-
assert getattr(record2, "openarmature.correlation_id") == "my-cid-42"
359+
# Restore the prior factory — process-global state.
360+
logging.setLogRecordFactory(prior_factory)
346361

347362

348363
def test_install_log_bridge_is_idempotent() -> None:
349364
"""Re-calling :func:`install_log_bridge` MUST NOT register a
350-
duplicate handler — the bridge owns the only OA-flagged
351-
LoggingHandler on the root logger."""
365+
duplicate handler on the root logger AND MUST NOT stack a
366+
second LogRecord factory wrapper on top of the
367+
already-installed one.
368+
369+
Wrapped in ``warnings.catch_warnings("error")`` to lock in the
370+
Phase 6.1 PR-B migration: this is the canonical surface where
371+
the deprecated ``opentelemetry.sdk._logs.LoggingHandler`` used
372+
to emit a ``DeprecationWarning``. Any future regression that
373+
re-introduces the deprecated path fires here immediately."""
374+
import warnings
375+
376+
from opentelemetry.sdk._logs import LoggerProvider
377+
378+
root = logging.getLogger()
379+
prior_handlers = list(root.handlers)
380+
prior_filters = list(root.filters)
381+
prior_factory = logging.getLogRecordFactory()
382+
try:
383+
with warnings.catch_warnings():
384+
warnings.simplefilter("error")
385+
provider = LoggerProvider()
386+
install_log_bridge(provider)
387+
handler_count_before = len(root.handlers)
388+
factory_after_first = logging.getLogRecordFactory()
389+
install_log_bridge(provider)
390+
handler_count_after = len(root.handlers)
391+
factory_after_second = logging.getLogRecordFactory()
392+
assert handler_count_before == handler_count_after
393+
# Factory identity is preserved across re-calls — no
394+
# second wrapper stacked on top of the first.
395+
assert factory_after_first is factory_after_second
396+
finally:
397+
# install_log_bridge mutates process-wide state; restore so
398+
# this test does not leak into others.
399+
root.handlers[:] = prior_handlers
400+
root.filters[:] = prior_filters
401+
logging.setLogRecordFactory(prior_factory)
402+
403+
404+
def test_log_bridge_exports_records_with_correlation_id() -> None:
405+
"""Spec §7 end-to-end: a log record emitted on a CHILD logger
406+
under ``current_correlation_id`` flows through the bridge to
407+
the OTel ``LoggerProvider``'s exporter with
408+
``openarmature.correlation_id`` populated. Child-logger emit
409+
is the load-bearing case — Python's logging propagates child
410+
records up to root's handlers but skips root's filters, so a
411+
filter-on-root placement (the prior implementation) misses
412+
every reasonable user's logger.
413+
414+
Wrapped in ``warnings.catch_warnings("error")`` so the PR-B
415+
migration's "no more deprecation warning" guarantee is
416+
asserted on the affirmative export path too."""
417+
import warnings
418+
352419
from opentelemetry.sdk._logs import LoggerProvider
420+
from opentelemetry.sdk._logs.export import (
421+
InMemoryLogRecordExporter,
422+
SimpleLogRecordProcessor,
423+
)
424+
425+
from openarmature.observability.correlation import (
426+
_reset_correlation_id,
427+
_set_correlation_id,
428+
)
353429

354430
root = logging.getLogger()
355431
prior_handlers = list(root.handlers)
356432
prior_filters = list(root.filters)
433+
prior_factory = logging.getLogRecordFactory()
357434
try:
358-
provider = LoggerProvider()
359-
install_log_bridge(provider)
360-
handler_count_before = len(root.handlers)
361-
install_log_bridge(provider)
362-
handler_count_after = len(root.handlers)
363-
assert handler_count_before == handler_count_after
435+
with warnings.catch_warnings():
436+
warnings.simplefilter("error")
437+
exporter = InMemoryLogRecordExporter()
438+
provider = LoggerProvider()
439+
provider.add_log_record_processor(SimpleLogRecordProcessor(exporter))
440+
install_log_bridge(provider)
441+
442+
# Emit on a CHILD logger to verify the factory
443+
# placement (which fires uniformly at record
444+
# construction) actually delivers — a filter-on-root
445+
# placement would not.
446+
child_logger = logging.getLogger("openarmature.test_log_bridge.child")
447+
token = _set_correlation_id("test-cid-export-1")
448+
try:
449+
child_logger.warning("hello from %s", "test")
450+
finally:
451+
_reset_correlation_id(token)
452+
453+
# SimpleLogRecordProcessor flushes synchronously, but
454+
# force-flush as a belt-and-suspenders guard so any
455+
# buffered emit lands in the exporter before assertions.
456+
provider.force_flush()
457+
records = exporter.get_finished_logs()
458+
# Filter to the record(s) emitted on our test logger — the
459+
# root may receive other records from concurrent test setup.
460+
ours = [r for r in records if r.log_record.body == "hello from test"]
461+
assert len(ours) == 1, (
462+
f"expected exactly one exported record for our test logger; "
463+
f"got {len(ours)} (full set: {[r.log_record.body for r in records]})"
464+
)
465+
attrs = dict(ours[0].log_record.attributes or {})
466+
assert attrs.get("openarmature.correlation_id") == "test-cid-export-1", (
467+
f"correlation_id MUST appear on the exported OTel LogRecord attributes; "
468+
f"got {attrs.get('openarmature.correlation_id')!r}"
469+
)
364470
finally:
365-
# install_log_bridge mutates the process-wide root logger;
366-
# restore the prior handler + filter set so this test does
367-
# not leak state into others.
368471
root.handlers[:] = prior_handlers
369472
root.filters[:] = prior_filters
473+
logging.setLogRecordFactory(prior_factory)
370474

371475

372476
# ---------------------------------------------------------------------------

0 commit comments

Comments
 (0)