Repository navigation
Make TEST_LOG async-signal-safe - #883
Conversation
TEST_LOG wrote through stdio (fprintf + fflush on stdout), which takes glibc's stdout lock. It is also called from code that signal handlers run, e.g. Profiler::populateRemoteFrame() under CTimer::signalHandler(). When the signal lands on a thread that is itself inside stdio, here LibraryPatcher::patch_libraries() logging from the dlopen hook, the handler waits forever for the lock its own thread holds, and every other thread that samples or logs then blocks on it too. Debug builds only, since TEST_LOG is a no-op otherwise; this is what hung the 8-orcl debug cell in RemoteSymbolicationTest (gdb: both threads in __lll_lock_wait_private on _IO_stdfile_1_lock). testLog() formats into a stack buffer with vsnprintf() and emits the line with one write(2) to fd 1, so no lock is taken; it preserves errno, and cuts lines longer than its 1 KiB buffer. A single write of a short line stays atomic on a pipe, which the tests reading these lines from child JVMs rely on. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Codex Review SummaryThis comment shows the latest Codex review activity on this pull request.
ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings. |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: cbd89a7121
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
![datadog-official[bot]](https://avatars.githubusercontent.com/in/1358509?s=60&v=4){kind=small}
There was a problem hiding this comment.
On macOS, concurrent debug log records longer than 512 bytes can interleave because the new buffer exceeds the platform's atomic pipe-write limit.
🤖 Bits Code Review · Commit cbd89a7
CI Test ResultsRun: #39770840665 | Commit:
Status Overview
Legend: ✅ passed | ❌ failed | ⚪ skipped | 🚫 cancelled ❔ Failing tests — flakiness not measured
These fail the build. The suite was not retried (slow suites run once), so whether they are flaky or broken was never measured — the entry below is offered on the same terms as a flake's, and the judgement is still yours. Consider quarantining these — click for ready-made entriesA quarantined test still runs and still reports; its failures just stop
CI fails once Failed Jobs
Summary: Total: 32 | Passed: 31 | Failed: 1 Updated: 2026-10-22 11:51:40 UTC |
vsnprintf() is not async-signal-safe: some conversions may allocate or read locale state (glibc's floating-point and wide-character paths, BSD's gdtoa, which also locks). testLog() now uses its own printf subset in testLog.h, covering what TEST_LOG's callers use (integers of every length, x/X/o, p, s with precision, c, f, flags and widths), with no allocation and no locks; %f is fixed-point and rounds ties up. Lines are now cut at 512 bytes, newline included: the POSIX minimum of PIPE_BUF and macOS's value, so a single write() stays atomic on a pipe everywhere, not only on Linux. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
@codex review |
|
Codex Review: Didn't find any major issues. Keep them coming! Reviewed commit: ℹ️ About Codex in GitHubCodex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback". |
kaahos
left a comment
kaahos
left a comment
There was a problem hiding this comment.
thanks for the work! Approved with a coupled of non-blocking comments. I also noticed that ddprof-lib/src/main/cpp/rcDebugLevel.h actually redefines TEST_LOG which might bypass this new writer so routing those macros through testLog() might be a follow-up.
| s = "(null)"; | ||
| } | ||
| size_t len = 0; | ||
| while (s[len] != '\0' && (spec.precision < 0 || len < (size_t)spec.precision)) { |
There was a problem hiding this comment.
I would invert the 2 conditions here. Otherwise the loop evaluates s[len] before checking the precision. For %.1s, it reads a 2nd byte even though the caller only needs to supply 1 byte which could cause a segfault.
| default: | ||
| // Unknown conversion: copy it through, so the line shows what went | ||
| // unformatted. Its argument, if any, is not consumed. | ||
| out.put(start, (size_t)(fmt - start) + (*fmt != '\0' ? 1 : 0)); | ||
| break; |
There was a problem hiding this comment.
could the fallback copy the rest of the format literally and return? Currently it skips the unsupported conversion’s argument, then continues parsing which could lead to segfault.
generate-test-summary.sh lists the run's jobs with `gh api --paginate`, which asks for 100 items per page unless the URL says otherwise. GitHub answers that request with HTTP 502 for a run with many jobs, e.g. once a job has been re-run, so summarize-tests failed on every such run (#868, #883); 50 per page works. Ask for 50 explicitly, and retry a failed listing twice, 10 s apart, since GitHub's 5xx can also be transient. A listing that keeps failing still fails the script, as before. The hermetic test's gh stub now answers a listing without an explicit page size below 100 with a 502, as GitHub does, and tests both retry outcomes. Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
What
TEST_LOG(debug builds only) no longer goes through stdio or libc formatting.testLog()in the newtestLog.h:write(2);errno;Why
The old macro was
fprintf(stdout, …); fflush(stdout), which takes glibc's stdout lock.TEST_LOGis also reached from signal handlers, e.g.Profiler::populateRemoteFrame()underCTimer::signalHandler(). When the signal lands on a thread that is itself inside stdio, the handler waits forever for a lock its own thread holds. Every other thread that samples or logs then blocks on the same lock, and the test JVM hangs.That is exactly what the gdb watchdog caught on #880, in the
test-linux-glibc-amd64 (8-orcl, debug, regular)cell duringRemoteSymbolicationTest [cstack=fp]:A second sampled thread was blocked on the same lock. Both log calls have been there for months, so this race is old and just rare. It only needs the signal to land inside a stdio call on the same thread. The intermittent IBM SDK 8 hangs in
DatadogSettingsTest(#868, #880) also stop right afterlibraries patched, so they are likely the same thing. That isn't confirmed, though: their watchdog dumps predate #880's fix.Notes
Output format: unchanged,
[TEST::INFO] <message>\non stdout. Tests that parse these lines from child JVMs keep working.Line length: capped at 512 bytes, newline included. That's the POSIX minimum of
PIPE_BUF, and macOS's value. So one line is one atomic pipe write on every platform, and concurrent lines can't interleave.Formatting: libc's formatters aren't async-signal-safe. Some conversions may allocate or read locale state (glibc's floating-point and wide-character paths; BSD's gdtoa, which also locks). The subset covers what the 130 call sites use:
hh h l ll z j t),x/X/o,p,swith precision (%.*s),c,%;-0+and widths;f, which rounds ties up, so the last digit can differ from libc's.Format checking is kept through
__attribute__((format(printf, 1, 2))).Ordering: output from other stdio writers to stdout is no longer ordered with these lines by stdio's buffer. The old
TEST_LOGflushed after every line anyway, and nothing else in the library writes to stdout through stdio while tests run.Tests
New
testLog_ut:flockfile);errno;snprintffor every conversion in use.With the old macro, the lock test fails ("TEST_LOG waited for the stdout lock", after its 2 s timeout), and the long-line test fails because the old macro didn't cut lines.
All debug gtests pass.
The full debug Java suite on macOS had the same six failures with each version of this PR. Run on their own, they behave the same with the old and the new macro:
DynamicNativeThread,NativeThreadTest,StartWithChurningThreadsTest,StopWithChurningThreadsTestandVtableReceiverFrameTestfail both ways;ThreadEntryDetectionTestpasses both ways; it failed only in the full run.These are sampling and thread-churn tests that are flaky on macOS.
🤖 Generated with Claude Code