Suppress logging from post_fork_child/post_fork_parent - #989
Conversation
logging.Logger.debug() is not safe to call from an os.register_at_fork() callback: it can block acquiring a StreamHandler's own lock, and that lock is left permanently locked in the child if some other thread held it at the exact instant of fork (no thread survives fork to release it there). _start_flush_thread and _start_sender_thread both log on every branch they can take, and both run from post_fork_child/post_fork_parent, so every invocation from that path was exposed regardless of config. Confirmed live: a process using this client hung permanently inside post_fork_child -> _start_flush_thread -> log.debug, even with buffering, aggregation, and the background sender all disabled -- the "everything is disabled" branch still logs unconditionally today, so there was no combination of settings that avoided this path entirely. Related to DataDog#834, a similar report against a different call site (close_socket) reachable from the same post_fork hooks. Signed-off-by: Stephen Wakely <stephen.wakely@datadoghq.com>
There was a problem hiding this comment.
Copilot review overview
🟡 Changes recommended
The post-fork socket-close path can still log and deadlock; related fork-hook documentation also needs correction.
Get a fresh assessment by requesting another Copilot review.
Review effort: Lite
Findings: 1
What changed in this PR
This PR suppresses debug logging during DogStatsD fork callbacks to help prevent post-fork deadlocks.
Changes:
- Adds quiet startup controls for flush and sender threads.
- Uses quiet mode during fork restoration.
- Adds parametrized fork logging tests.
| File | Summary |
|---|---|
tests/integration/dogstatsd/test_statsd_fork.py |
Verifies fork callbacks suppress debug logging. |
datadog/dogstatsd/base.py |
Implements quiet thread startup during fork handling. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
StephenWakely
left a comment
StephenWakely
left a comment
There was a problem hiding this comment.
Can you fix the copilot suggestion as well. We'll need to pass quiet to close_socket as well..
close_socket() still logged at error level on a socket.close() OSError even when called from post_fork_child()'s os.register_at_fork(after_in_child=...) handler, the same fork-unsafe logging path already fixed for _start_flush_thread/_start_sender_thread. Add a quiet flag, gate the two log.error calls behind it, and pass quiet=True only from post_fork_child. Signed-off-by: Stephen Wakely <stephen.wakely@datadoghq.com>
|
@StephenWakely done, also had my claude agent do another pass at the |
dc16851 to
f8cad08
Compare
StephenWakely
added
the
changelog/Fixed
|
@StephenWakely not sure what the merge/release workflow looks like for DD, is there anything else you need from me on this PR? |
@seanmuth We should be good from here, thanks. Just a little dance with CI to get it merged and then I'll kick off a new release. |
gh-worker-dd-devflow-36fce6
Bot
added
mergequeue-status: rejected
and removed
mergequeue-status: in_progress
labels
❌ ErrorsYour PR has failed checks. Please review the issues below and take necessary action before merging. 🚦 1 Pipeline job failed
Useful? React with 👍 / 👎 This comment will be updated automatically if new data arrives.🔗 Commit SHA: 3332069 | Docs | View more details | Give us feedback! |
StephenWakely
removed
ci/integrations
What does this PR do?
Related to #834, a different specific manifestation of the same underlying class — a thread that hangs somewhere reachable from
post_fork_child/post_fork_parent, the callbacks registered viaos.register_at_fork()._start_flush_threadand_start_sender_threadboth calllog.debug(...)on every branch they can take, and both run frompost_fork_child/post_fork_parent.logging.Logger.debug()is not safe to call there: it can block acquiring aStreamHandler's own lock, and if some other thread held that lock at the exact instant offork(), it's left permanently locked in the child — no thread survives fork to release it. Confirmed live: a process using this client hung permanently insidepost_fork_child→_start_flush_thread→log.debug, even with buffering, aggregation, and the background sender all disabled — the "everything is disabled" branch still logs unconditionally today, so there was no config that avoided this path entirely.Description of the Change
Add a
quiet=Falseparameter to both_start_flush_threadand_start_sender_thread, gating everylog.debug(...)call inside each behindif not quiet:.post_fork_child/post_fork_parentnow call both withquiet=True. Every other caller is unaffected — same logging as before.Alternate Designs
Could have just deleted the log lines outright — #817 removed a different post-fork log call for being "misleading" for a similar reason. Went with
quietinstead so normal (non-fork) construction/config-change logging is untouched; only the specific atfork-reachable path goes quiet.Possible Drawbacks
Anyone relying on these specific debug-level log lines firing after a fork loses that signal. These aren't documented as a stable interface and are debug-level only, so this seems low-risk.
Verification Process
test_post_fork_does_not_log(parametrized across the same buffering/sender config combinations as the existing fork tests) assertinglog.debugis never called duringpost_fork_child/post_fork_parent. Confirmed it fails against the pre-fix code with the exact two log calls this PR removes from that path, and passes with the fix.tests/unit/dogstatsd/test_statsd.py(134 passed, 1 skipped, unrelated),tests/integration/dogstatsd/test_statsd_fork.py(16 passed, including the new test),tests/integration/dogstatsd/test_statsd_sender.py(79 passed) — all green, no regressions.mypy datadog/dogstatsd/base.pyclean.Additional Notes
Generated with AI assistance (Claude Sonnet 5); I reviewed and tested the change before opening this PR.