Skip to content

feat(pytest): add _DD_CIVISIBILITY_LOG_INJECTION log prefix injection#18187

Draft
gnufede wants to merge 5 commits into
mainfrom
gnufede/civisibility-log-injection
Draft

feat(pytest): add _DD_CIVISIBILITY_LOG_INJECTION log prefix injection#18187
gnufede wants to merge 5 commits into
mainfrom
gnufede/civisibility-log-injection

Conversation

@gnufede
Copy link
Copy Markdown
Member

@gnufede gnufede commented May 20, 2026

Description

Adds a new opt-in feature to the `ddtrace.testing` pytest plugin: when `_DD_CIVISIBILITY_LOG_INJECTION=true` is set, every log line emitted during a test session is prefixed with `[dd:trace_id,span_id]` at the very start of the line. This lets users visually correlate log output with the test span it came from without needing full agentless log submission.

Supersession: this feature is a no-op when either `DD_LOGS_INJECTION=true` or `DD_AGENTLESS_LOG_SUBMISSION_ENABLED=true` is set — both already provide richer log correlation and would conflict with a plain-text prefix.

Implementation: why `Formatter.format` and not `record.msg` or a root-logger `Filter`

Root-logger `Filter` doesn't work. The natural first attempt was `logging.getLogger().addFilter(filter)`. Python's `Logger.callHandlers()` propagates records to parent-logger handlers directly, bypassing parent-logger filters entirely. A filter on `logging.root` is only invoked for records that originate from the root logger itself (`logging.info(...)`), not from named child loggers like `logging.getLogger(name)`, which covers virtually all real test code.

Modifying `record.msg` in `makeRecord` puts the prefix in the wrong place. Injecting the prefix into `record.msg` embeds it inside `%(message)s`, which appears after any timestamp or level fields in the user's format string — e.g. `15:10:34 INFO mymodule - [dd:...] actual message`. That defeats the goal of having it at the very beginning of the line.

The fix: wrap `logging.Formatter.format`. `Formatter.format` returns the fully-assembled output string, so prepending there guarantees the prefix is always the first thing on the line regardless of the user's format string. Crucially, `Formatter.format` is called synchronously within the same call stack as the original `logger.info(...)` call, so the test span is still active when we read `get_log_correlation_context()` — no need to snapshot IDs earlier in `makeRecord`.

Why `LogInjectionPatch` lives in `ddtrace/testing/` and not in the logging integration

The existing `ddtrace/contrib/internal/logging/patch.py` was considered as a home for this logic, but it was kept separate for three reasons:

  1. Different operation on the record. The logging patch injects attributes (`dd.trace_id`, `dd.span_id`, …) so users can reference them in format strings. `LogInjectionPatch` prepends to the formatted output string. These are distinct concerns.
  2. Different audience and lifecycle. The logging patch is a production integration that stays applied globally. `LogInjectionPatch` is a test-session artifact: installed at `pytest_sessionstart`, removed at `pytest_sessionfinish`. Coupling that lifecycle to the logging integration would bleed pytest-plugin concerns into production code.
  3. Private, test-scoped env var. `_DD_CIVISIBILITY_LOG_INJECTION` is underscore-prefixed intentionally — it is an internal testing-plugin variable. Gating logic on it inside a general-purpose ddtrace integration would leak test-infrastructure details into the wrong layer.

Because `_patch_logging()` is not called when only `_DD_CIVISIBILITY_LOG_INJECTION` is active, `LogInjectionPatch` reads the trace context directly via `ddtrace.tracer.get_log_correlation_context()` rather than relying on attributes injected by the logging patch.

Testing

Manual end-to-end test suite added at `customer_repros/ci_log_injection/` (not part of this PR). Covers:

  • Prefix appears at the very start of every formatted log line with non-zero IDs on all log levels and from nested function calls.
  • IDs are consistent within a single test and differ across tests.
  • Feature is correctly suppressed when `DD_LOGS_INJECTION=true` or `DD_AGENTLESS_LOG_SUBMISSION_ENABLED=true`.

Risks

  • Wrapping `logging.Formatter.format` is a global monkey-patch active only during the test session (`pytest_sessionstart` → `pytest_sessionfinish`). A bare `except Exception` guards the body so a failure in the patch can never break logging.
  • The prefix is prepended to the formatted string returned by `Formatter.format`, not to `record.msg`. This means `caplog.text` in pytest will contain the prefixed lines, but `caplog.records[i].getMessage()` will not — test code asserting on raw log messages is unaffected.

Additional Notes

No release note — this is an internal/private env var, not a user-facing public API.

When _DD_CIVISIBILITY_LOG_INJECTION is set, prepend [dd:trace_id,span_id]
to every log message emitted during a test session so logs can be visually
correlated with test spans without requiring full agentless log submission.

Superseded (no-op) when DD_LOGS_INJECTION=true or
DD_AGENTLESS_LOG_SUBMISSION_ENABLED=true, both of which already provide
richer log correlation.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
@cit-pr-commenter-54b7da
Copy link
Copy Markdown

cit-pr-commenter-54b7da Bot commented May 20, 2026

Codeowners resolved as

tests/testing/internal/pytest/test_pytest_log_correlation.py            @DataDog/ci-app-libraries

@datadog-prod-us1-6
Copy link
Copy Markdown

datadog-prod-us1-6 Bot commented May 20, 2026

Pipelines  Tests

Fix all issues with BitsAI

⚠️ Warnings

🚦 1 Pipeline job failed

Changelog | Validate changelog   View in Datadog   GitHub Actions

🛟 This job is unlikely to succeed on retry. Please review your pipeline configuration. Release note not found during changelog validation

ℹ️ Info

No other issues found (see more)

🧪 All tests passed
❄️ No new flaky tests detected

Useful? React with 👍 / 👎

This comment will be updated automatically if new data arrives.
🔗 Commit SHA: bc322ae | Docs | Datadog PR Page | Give us feedback!

gnufede and others added 4 commits May 20, 2026 15:52
The makeRecord wrapper was prepending [dd:...] to record.msg, which places
it inside %(message)s — after any timestamp/level fields in the format
string. Instead, stamp trace/span IDs as record attributes in makeRecord
(where the test span is still active) and prepend to the fully-assembled
output string in a Formatter.format wrapper, so the prefix is always the
very first thing on each log line regardless of the user's format string.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
…rmat wrapper

The makeRecord wrapper was added to snapshot trace/span IDs before the
span could close, but Formatter.format is called synchronously in the same
stack frame as the original logger.info() call so the span is always still
active. Remove makeRecord and call get_log_correlation_context() directly
inside the Formatter.format wrapper instead.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
get_log_correlation_context() returns the full 128-bit trace_id as a
32-char hex string for high-bit IDs, but the backend stores the test
span's 64-bit integer (matching DDTraceTestContext's truncation).

Switch to reading the active span directly and applying % (1 << 64)
so the prefixed trace_id always matches the value in the test event
payload.  Also assign trace_id_raw/span_id_raw to local variables so
mypy can narrow int|None → int for the modulo operation.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
Add TestCILogInjection to test_pytest_log_correlation.py covering the
six key behaviours of LogInjectionPatch:

- [dd:trace_id,span_id] prefix appears at the start of every formatted
  log line when _DD_CIVISIBILITY_LOG_INJECTION=true
- trace_id in the prefix equals span.trace_id % (1 << 64), matching the
  64-bit integer the backend stores for the test event payload
- All log lines within one test share the same trace_id/span_id
- No prefix when the flag is not set
- Patch is not installed (superseded) when DD_LOGS_INJECTION=true
- Patch is not installed (superseded) when DD_AGENTLESS_LOG_SUBMISSION_ENABLED=true

Each test runs a pytester subprocess so the env var is present during
ddtrace plugin initialisation and the Formatter.format wrapper is
confined to the subprocess process, with no risk of leaking into the
outer test runner's logging.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant