Skip to content

Fix flaky: SymDB Logger wrapper swallows target exceptions#5943

Draft
p-datadog wants to merge 1 commit into
masterfrom
fix-symdb-scheduler-logger-boom
Draft

Fix flaky: SymDB Logger wrapper swallows target exceptions#5943
p-datadog wants to merge 1 commit into
masterfrom
fix-symdb-scheduler-logger-boom

Conversation

@p-datadog

@p-datadog p-datadog commented Jun 23, 2026

Copy link
Copy Markdown
Member

What does this PR do?

Fixes the Ruby 2.6 flake of spec/datadog/symbol_database/component_spec.rb:752 — "does not propagate exceptions when logger.debug itself raises" — observed in PR #5798 CI.

Motivation:

Flaky test Ruby 2.6 / build & test (standard) [0] on 2026-06-15.

Failure:

The test sets up allow(raw_logger).to receive(:debug).and_raise(RuntimeError.new('logger boom')) then defines a class to trigger the hot-load TracePoint(:class). The reported failure points to the hot-load hook's logger.debug call site at component.rb:567, suggesting the inner rescue at component.rb:566-571 failed to catch.

Root cause:

The hot-load hook's inner rescue is not broken — it catches every time. Diagnostic STDERR.puts confirmed:

[symdb-diag outer-rescue] caught RuntimeError: simulated hot-load enqueue failure
[symdb-diag pre-debug] logger=Datadog::SymbolDatabase::Logger target=Datadog::SymbolDatabase::Logger
[symdb-diag inner-rescue] caught RuntimeError: logger boom
[symdb-diag outer-rescue-done]

The logger boom exception that surfaces in the test is from the scheduler thread, not the hook callback. The rspec-mocks stub is process-wide, so every @logger.debug call in Datadog::SymbolDatabase::Component raises — including the four scheduler-path sites that have no inner rescue:

Causal chain on the failing run:

  1. Component.build with force_upload = true starts the scheduler thread, which enters extract_and_upload.
  2. extract_all (ObjectSpace walk) takes longer than wait_for_idle(timeout: 5) in a loaded test environment.
  3. wait_for_idle returns false; the test ignores the return value.
  4. Test sets up allow(raw_logger).to receive(:debug).and_raise(...) while the scheduler is still inside extract_and_upload.
  5. Scheduler reaches @logger.debug { "symdb: initial extracted ..." } → stub raises.
  6. Exception escapes line 500, is caught at line 510, line 511's @logger.debug raises again, escapes to scheduler_loop's rescue at line 457, line 458 raises again, escapes scheduler_loop entirely.
  7. Scheduler thread terminates. Thread.report_on_exception=true prints the trace.
  8. Test's ensure calls component.shutdown!, which invokes @scheduler_thread&.join(5). Thread#join re-raises the joined thread's unhandled exception in the caller — standard Ruby semantics, all MRI versions.
  9. The re-raised exception escapes the ensure, surfaces as the example failure with the scheduler thread's backtrace.

The flake is not Ruby-2.6-specific — every link in the chain (missing rescues, Thread#join re-raise) is identical across all supported MRI Rubies. The 2.6-only CI observation is a timing artefact: Ruby 2.6's slower ObjectSpace iteration and no-JIT bytecode dispatch make extract_all more likely to exceed the 5-second wait_for_idle budget.

Fix:

Datadog::SymbolDatabase::Logger is a thin wrapper around the customer's logger. Its job is to be a defensive facade — but the Forwardable.def_delegators it uses for debug and warn propagates target exceptions verbatim. Replace def_delegators with explicit methods that swallow exceptions:

def debug(*args, &block)
  @target.debug(*args, &block)
rescue
  nil
end

#trace already routes through #debug, so it inherits the protection. Every @logger.debug / @logger.warn / @logger.trace call site in Datadog::SymbolDatabase::* now silently tolerates a misbehaving target without further per-site rescues.

Bare rescue (StandardError) is intentional: IOError / Errno from a disk-full or broken-pipe logger are caught; SignalException / SystemExit are not.

The existing inner rescue at component.rb:566-571 (around install_hot_load_hook's logger.debug + telemetry.report) is left in place — it still protects against telemetry.report raising, which the logger fix does not cover.

Change log entry

None.

How to test the change?

  • bundle exec rspec spec/datadog/symbol_database/logger_spec.rb — 13 examples covering debug/warn/trace under both success and target-raises conditions.
  • bundle exec rspec spec/datadog/symbol_database/ — full symbol_database suite passes (374 examples) on Ruby 2.6.10, 3.0.7, 3.1.7, 3.3.10, 3.4.8.
  • The companion reproducer PR Reproduce flaky: SymDB scheduler thread logger.debug #5942 forces the race deterministically; with this fix merged in, that reproducer passes (see validation PR linked below once created).

Companion PRs:

Most @logger.debug / @logger.warn calls in SymbolDatabase::Component run
on the scheduler thread:

  - extract_and_upload success-path log (component.rb:500)
  - extract_and_upload's rescue handler (line 511)
  - scheduler_loop's rescue handler (line 458)
  - start_upload's rescue handler (line 202, called from main but
    schedules the scheduler thread)

A misbehaving customer logger (custom Logger subclass, IO error,
frozen state, rspec-mocks stub) that raises from any of these sites
escapes scheduler_loop, terminating the scheduler thread. Component
#shutdown! invokes @scheduler_thread&.join(5), and Thread#join re-
raises the unhandled exception in the caller — standard Ruby semantics
across every supported version. The customer sees a SymDB exception at
shutdown!.

Fix at the wrapper level: SymbolDatabase::Logger#debug and #warn
now swallow exceptions from the wrapped target. #trace routes through
#debug so it inherits the protection. The same defense pattern that
install_hot_load_hook applies inline at component.rb:566-571 now
applies at every SymDB log site automatically.

Implementation: replaces Forwardable.def_delegators with explicit
methods. Forwardable's generated forwarders cannot rescue; the explicit
version uses bare rescue (StandardError) — IOError / Errno from a disk-
full or broken pipe logger are caught, SignalException / SystemExit
are not.

New spec covers debug / warn / trace under both success and target-
raises conditions.

The companion reproducer at spec/datadog/symbol_database/
logger_boom_reproducer_spec.rb is on the reproduce-symdb-scheduler-
logger-boom branch and demonstrates this fix neutralizing the bug.
@p-datadog p-datadog added the AI Generated Largely based on code generated by an AI or LLM. This label is the same across all dd-trace-* repos label Jun 23, 2026
@dd-octo-sts dd-octo-sts Bot added the debugger Live Debugger (+Dynamic Instrumentation, +Symbol Database) label Jun 23, 2026
@dd-octo-sts

dd-octo-sts Bot commented Jun 23, 2026

Copy link
Copy Markdown
Contributor

Typing analysis

Note: Ignored files are excluded from the next sections.

Untyped methods

This PR introduces 4 partially typed methods, and clears 4 partially typed methods.

Partially typed methods (+4-4)Introduced:
sig/datadog/symbol_database/logger.rbs:8
└── def initialize: (untyped settings, ::Logger target) -> void
sig/datadog/symbol_database/logger.rbs:16
└── def debug: (?untyped? message) ?{ () -> untyped } -> void
sig/datadog/symbol_database/logger.rbs:17
└── def warn: (?untyped? message) ?{ () -> untyped } -> void
sig/datadog/symbol_database/logger.rbs:18
└── def trace: () { () -> untyped } -> void
Cleared:
sig/datadog/symbol_database/logger.rbs:10
└── def initialize: (untyped settings, ::Logger target) -> void
sig/datadog/symbol_database/logger.rbs:17
└── def debug: (?untyped? message) ?{ () -> untyped } -> void
sig/datadog/symbol_database/logger.rbs:18
└── def warn: (?untyped? message) ?{ () -> untyped } -> void
sig/datadog/symbol_database/logger.rbs:19
└── def trace: () { () -> untyped } -> void

Untyped other declarations

This PR introduces 2 untyped other declarations, and clears 2 untyped other declarations.

Untyped other declarations (+2-2)Introduced:
sig/datadog/symbol_database/logger.rbs:4
└── @settings: untyped
sig/datadog/symbol_database/logger.rbs:10
└── attr_reader settings: untyped
Cleared:
sig/datadog/symbol_database/logger.rbs:6
└── @settings: untyped
sig/datadog/symbol_database/logger.rbs:12
└── attr_reader settings: untyped

If you believe a method or an attribute is rightfully untyped or partially typed, you can add # untyped:accept on the line before the definition to remove it from the stats.

@datadog-datadog-prod-us1-2

datadog-datadog-prod-us1-2 Bot commented Jun 23, 2026

Copy link
Copy Markdown

Pipelines  Tests

Fix all issues with BitsAI

⚠️ Warnings

🚦 2 Pipeline jobs failed

Check Pull Request CI Status | all-jobs-are-green   View in Datadog   GitHub Actions

Static Analysis | steep/typecheck   View in Datadog   GitHub Actions

ℹ️ Info

No other issues found (see more)

🧪 All tests passed
❄️ No new flaky tests detected

🎯 Code Coverage (details)
Patch Coverage: 50.00%
Overall Coverage: 89.98% (-0.04%)

Useful? React with 👍 / 👎

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

@pr-commenter

pr-commenter Bot commented Jun 23, 2026

Copy link
Copy Markdown

Benchmarks

Benchmark execution time: 2026-06-23 18:15:13

Comparing candidate commit 6093b4e in PR branch fix-symdb-scheduler-logger-boom with baseline commit fd1e1b0 in branch master.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 48 metrics, 1 unstable metrics.

Explanation

This is an A/B test comparing a candidate commit's performance against that of a baseline commit. Performance changes are noted in the tables below as:

  • 🟩 = significantly better candidate vs. baseline
  • 🟥 = significantly worse candidate vs. baseline

We compute a confidence interval (CI) over the relative difference of means between metrics from the candidate and baseline commits, considering the baseline as the reference.

If the CI is entirely outside the configured SIGNIFICANT_IMPACT_THRESHOLD (or the deprecated UNCONFIDENCE_THRESHOLD), the change is considered significant.

Feel free to reach out to #apm-benchmarking-platform on Slack if you have any questions.

More details about the CI and significant changes

You can imagine this CI as a range of values that is likely to contain the true difference of means between the candidate and baseline commits.

CIs of the difference of means are often centered around 0%, because often changes are not that big:

---------------------------------(------|---^--------)-------------------------------->
                              -0.6%    0%  0.3%     +1.2%
                                 |          |        |
         lower bound of the CI --'          |        |
sample mean (center of the CI) -------------'        |
         upper bound of the CI ----------------------'

As described above, a change is considered significant if the CI is entirely outside the configured SIGNIFICANT_IMPACT_THRESHOLD (or the deprecated UNCONFIDENCE_THRESHOLD).

For instance, for an execution time metric, this confidence interval indicates a significantly worse performance:

----------------------------------------|---------|---(---------^---------)---------->
                                       0%        1%  1.3%      2.2%      3.1%
                                                  |   |         |         |
       significant impact threshold --------------'   |         |         |
                      lower bound of CI --------------'         |         |
       sample mean (center of the CI) --------------------------'         |
                      upper bound of CI ----------------------------------'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

AI Generated Largely based on code generated by an AI or LLM. This label is the same across all dd-trace-* repos debugger Live Debugger (+Dynamic Instrumentation, +Symbol Database)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants