fix(logger): decide colors without a static guard a fork child inherits by SizzleUnrlsd · Pull Request #48 · CoreTrace/coretrace-log

SizzleUnrlsd · 2026-10-14T22:22:58Z

A child of fork() could hang forever on its first log line: CoreTrace/coretrace-compiler#213.

The first commits fixed the color decision, the state the issue points at. After review, the PR also covers every other state a child could inherit half-taken from another thread of the parent, and two details of the color decision.

Cause

A child of fork() has only the thread that forked. Whatever another thread of the parent held at the time of the fork stays held in the child, and no thread of the child will ever release it:

The color decision. use_color() kept it in a function-local static (static const bool enabled = [](){...}();). When another thread was running that initializer, the child inherited the initialization guard marked "in progress", and its first call to color() waited in __cxa_guard_acquire forever.
pid(). It cached the pid in the same kind of function-local static. Besides, the child's lines carried the parent's pid.
The output and state locks. g_output_mutex is held for the whole write of a line, sink call included: a child forked while another thread was writing blocked on its first line.
The initialization. init_once() uses std::call_once. With libc++, a child forked while another thread runs init_from_env() waits for a flag left "pending".

In coretrace-compiler, the runtime builds the color arguments of a log line before it takes its log lock, so a fork could happen during that first initialization. Its fixture ct_fork_threads.c hung once in 1,000 runs on macOS, and once in CI. The issue gives the stack of the hung child, and the disassembly showing the guard is the one of enabled.

Change

Fork

The color decision is a std::atomic<ColorDecision> (Undecided, Off, On), with no lock and no initialization guard. Two threads may decide at once: the first decision stored holds (compare-exchange), and a thread that loses takes it. A static_assert checks that the atomic is lock-free.
pid() asks the system on each call.
pthread_atfork() handlers, through platform::at_fork() (a no-op on Windows):
- before the fork, the forking thread runs init_once(), then takes the output lock and the state lock, in the order of a sink that logs;
- after the fork, the parent and the child release them;
- other fork handlers run in between, in the forking thread, and can still call the logger: the handlers' acquisitions go through the locks' reentrance.
Both locks are reentrant: a std::mutex with a thread-local count of the guards held, taken when the count goes from 0 to 1. The output lock was a std::recursive_mutex, which the child cannot release when taken before the fork: glibc and macOS check the id of its owner, and the child's thread has another one. A sink can still log, and a sink that forks gives a child that can log.
The two mutexes are never destroyed (a union whose destructor does nothing, still constant-initialized), so fork() still works from an atexit() handler or a static destructor that runs after the logger's.

Colors

An empty NO_COLOR no longer disables the colors: no-color.org asks for "present and not an empty string".

Docs

The changelog, the README and the API comments: the lock is reentrant, not recursive, fork() waits for a line being written, when the environment defaults are read, and which NO_COLOR values disable the colors.

Behavior changes

fork() waits for a line another thread is writing. A sink that waits for the thread calling fork() would now deadlock it.
CT_LOG_LEVEL and CT_DEBUG are read at the first logging call or at the first fork(), whichever comes first. They were read only at the first logging call.
NO_COLOR= (empty) keeps the colors.

Tests

Each fix comes after a test that fails without it.

Test	Checks	Without the fix
`test_fork_color`	fork while another thread decides the colors; the first decision stored holds for every thread; no decision is made after it	on `main` (`f8bf453`), the child hangs and is killed after 5 s; before `a0c2f45`, the decider gets a color and the main thread none
`test_fork`	`fork()` finishes the initialization; the child's `pid()`; fork while another thread writes through a 300 ms sink; fork from inside a sink	the four checks fail: the environment is read after the fork, the child reports the parent's pid, and both children hang
`test_fork`	fork handlers registered before the logger's log and set the sink, in the prepare, parent and child phases	before `2e82a6d`, `fork()` never returns: the forking thread waits for the locks it holds
`test_fork`	an `atexit()` handler that runs after the logger's static destructors forks	before `73c9198`, aborts on macOS: `mutex lock failed: Invalid argument`
`test_colors_tty.empty_no_color`	`NO_COLOR` set to an empty string keeps the colors	the colors are off

test_fork_color redefines isatty() in a translation unit of its own, fork_color_isatty.cpp, with the exception specification of the C library's declaration. The logger, a static library, calls that definition while it decides. The first call says stderr is a terminal after 300 ms; later calls say it is not, at once.
Both fork tests restore the default SIGCHLD action, and test_fork_color unsets NO_COLOR. Their reap and wait helpers, in tests/fork_helpers.hpp, give up after 5 s.
test_fork registers its fork handlers and its atexit() handler during its own static initialization, which runs before the logger's: its prepare handler then runs after the logger's, its parent and child handlers before them, and its atexit() handler after the logger's destructors. Without the fixes, both checks fail on macOS and on Linux.

Verification

CI at 73c9198: the 13 checks pass, Windows, TSan, ASan+UBSan and coverage included.
macOS (Apple clang 17): 28 / 28 tests plain, with -fsanitize=thread and with -fsanitize=address,undefined. Under each sanitizer, test_fork and test_fork_color pass 30 times in a row.
Linux (Ubuntu 24.04 arm64 container, g++ 13.3), test_fork and test_fork_color 20 times in each mode:

Mode	Suite	`test_fork`, `test_fork_color` ×20
plain, `-Wall -Wextra -Werror`	28 / 28	pass
`-fsanitize=thread`	28 / 28	pass
`-fsanitize=address,undefined`	26 / 28	pass

The two failures under ASan+UBSan are test_concurrency_smoke and test_format_error_serialized, which time out after 20 s. They time out on main too, in the same container, which emulates arm64.

dlclose(): a shared library built with the logger, loaded, used, closed, then fork(). glibc removes the library's fork handlers when it unloads it; macOS does not unload it. fork() works on both.
clang-format 20: clean.

Inside coretrace-compiler

The first use_color() change (610446e), applied to the commit coretrace-compiler pins (624688a), was built into its runtime on macOS:

the deterministic probe of the issue: the child exits 5 times out of 5, where it hung 5 times out of 5 before;
ctest: 213 passed;
runtime suite: 45 passed, 5 skipped.

The later commits were not built into coretrace-compiler yet.

Moving coretrace-compiler's pin to main was blocked by another defect. With main, every instrumented program aborts at start-up:

the error is recursive_mutex lock failed: Invalid argument;
the stack is ct_init_env_once → coretrace::set_sink → std::recursive_mutex::lock;
the runtime's static constructor calls set_sink() before the global g_output_mutex, a std::recursive_mutex added by 381e27b, is constructed, since libc++ initializes it dynamically.

This PR makes g_output_mutex a std::mutex, whose constexpr constructor makes it constant-initialized, before any static constructor runs. That should remove this failure as well; it is not checked in coretrace-compiler yet.

use_color() kept its decision in a function-local static. When another thread was initializing it at the time of a fork(), the child inherited the initialization guard as taken, and its first call to color() waited for it forever: no thread of the child would ever release it. The decision is now an atomic, decided by the first caller; two threads deciding at once reach the same answer. Seen in coretrace-compiler, where a child forked while a thread logged hung: CoreTrace/coretrace-compiler#213

The test redefines isatty(), which the logger calls once to decide whether stderr takes colors, so that the decision lasts while the test forks; the child then asks for a color and must exit. Before the fix, the child hung on the decision's initialization guard every time.

Under NO_COLOR, the logger decides without calling isatty(), so the test waited forever for the decision to start: the wait now gives up after 5 s with a failed check, and the test unsets NO_COLOR, as test_colors_tty does. It also restores the default SIGCHLD action, which waitpid() needs to reap the child. The fake isatty() takes the exception specification of the C library's declaration, noexcept with glibc, instead of relying on the compiler to accept a mismatch with a system header. Threads::Threads already comes with coretrace_logger.

Two threads may decide the colors at once. The fake isatty() now tells the first caller, after a delay, that stderr is a terminal, and later callers at once that it is not: the main thread decides while the decider waits, and both must get the same color, as must later calls, which must not call isatty() again. The test fails: the decider's slower decision overwrites the one already stored.

… once Each thread that decided stored its answer, so the last one won: when NO_COLOR changed in between, or when SetConsoleMode() failed for one of them on Windows, a thread could color its lines while the decision kept for later said no. The decision is now stored only when none is, with a compare-exchange, and a thread that loses takes the one stored. The three states are named by an enum, and a static_assert checks that the atomic is lock-free: a child of fork() must not inherit a lock taken by the parent.

no-color.org asks programs to disable colors when NO_COLOR is present and not an empty string. The new test_colors_tty.empty_no_color case sets NO_COLOR to an empty string and expects the colors of the default case. It fails: the logger disables the colors whenever NO_COLOR is set.

no-color.org disables colors when NO_COLOR is present and not an empty string; the logger disabled them for an empty NO_COLOR too, as when a script sets NO_COLOR= to clear it. The README says which values disable the colors.

test_fork forks after the logger was used, and the child must be able to log: - before any initialization, fork() must finish it, so the environment defaults are those at the time of the fork; - the child's pid() must be its own; - while another thread writes a line, through a sink that takes 300 ms; - from inside a sink, where the forking thread holds the output lock itself. The reap and wait loops of test_fork_color move to fork_helpers.hpp, shared by both tests. All four checks fail: the environment is read after the fork, the child reports the parent's pid, and both children hang on the output lock they inherit.

pid() cached the process id in a function-local static, so after fork() the child's lines carried the parent's pid, and the child could also inherit the static's initialization guard taken by another thread of the parent, as with the color decision. pid() now asks the system each time: getpid() costs a fraction of a log line.

…ogger A child of fork() has only the thread that forked. It inherited the output lock, or the state lock, taken by another thread of the parent writing a line at the time of the fork, and its first line waited for them forever; with libc++, it also waited forever for an initialization another thread was running, since std::call_once does not survive fork(). pthread_atfork() handlers now make fork() wait for them: the forking thread finishes the initialization, takes the output lock then the state lock, the order of a sink that logs, and releases them in the parent and in the child. The environment defaults are thus read at the latest by the first fork(). The output lock is a std::mutex, with a thread-local count of the guards held, instead of a std::recursive_mutex: a recursive mutex checks the id of its owner, which the child's thread does not share with the forking thread, so the child could not release it. A sink can still log, and a sink that forks gives a child that can log.

The changelog lists the fork() fixes and the NO_COLOR change. The README and the API comments no longer call the output lock recursive or pid() cached, say that fork() waits for a line being written, and when the environment defaults are read.

SizzleUnrlsd

Review of 01fe73f: 14 points, one thread each, tagged [blocking], [important], [minor] or [nit]. Two of them are on lines outside the diff (pid() and the output/state mutexes in src/logger.cpp), so they are file-level comments.

CI was green on 01fe73f, and test_fork_color passes locally. The fixes follow on this branch.

SizzleUnrlsd · 2026-10-15T02:14:29Z

+
+int main() {
+  std::thread decider([] { (void)coretrace::color(coretrace::Color::Red); });
+  while (!g_deciding_colors.load()) {


[blocking] The test hangs when NO_COLOR is set in the environment.

use_color() checks NO_COLOR before stderr_supports_color(), so under NO_COLOR the fake isatty() is never called, g_deciding_colors stays false and this loop spins until ctest's 20 s timeout.

Reproduced: NO_COLOR=1 ctest -R fork_color gives (Timeout). Anyone exporting NO_COLOR in their shell profile (as no-color.org suggests) hits it.

Fix: unsetenv("NO_COLOR") at the start of main(), as test_colors_tty.cpp does.

Fixed in f339a83: main() unsets NO_COLOR first. NO_COLOR=1 ctest -R fork_color now passes.

SizzleUnrlsd · 2026-10-15T02:14:29Z

+  while (!g_deciding_colors.load()) {
+  }


[minor] Unbounded busy-wait.

The loop has no deadline and no message: whenever the decision does not go through isatty() (the NO_COLOR case above, or a later refactor that checks TERM or uses ioctl), the test burns a core for 20 s and ends as (Timeout) instead of failing fast with a readable CHECK.

Fix: bound it by the same deadline as reap().

Fixed in f339a83: the wait gives up after 5 s with a failed CHECK. Since 2c73405 it is ct_test::wait_for() in tests/fork_helpers.hpp, shared with test_fork.cpp.

SizzleUnrlsd · 2026-10-15T02:14:29Z

+    const bool enabled =
+        env_var("NO_COLOR") == nullptr && platform::stderr_supports_color();
+    decision = enabled ? 2 : 1;
+    g_color_decision.store(decision, std::memory_order_release);


[important] Last writer wins when two threads decide at once.

Each decider stores its own answer unconditionally, so the last store wins. The old static guard guaranteed a single decision. Scenario: T1 decides "colors", T2 decides "no colors" first (because NO_COLOR changed in between, or SetConsoleMode() failed once on Windows), then T1 overwrites it: T1's lines are colored, T2's are not, and the final value depends on scheduling.

Fix: compare_exchange_strong(Undecided → decision), and a thread that loses takes the stored value.

Fixed in a0c2f45 (compare_exchange_strong, a thread that loses takes the stored decision). 84d6819 adds the failing test first: the fake isatty() gives the decider a slow "yes" and the main thread a fast "no", and both must end up with the same color.

SizzleUnrlsd · 2026-10-15T02:14:29Z

+    const bool enabled =
+        env_var("NO_COLOR") == nullptr && platform::stderr_supports_color();


[minor] An empty NO_COLOR disables colors.

no-color.org says colors are disabled when NO_COLOR is "present and not an empty string"; == nullptr also disables them for NO_COLOR= (e.g. a script clearing the variable). The README advertises NO_COLOR compliance. The line is rewritten by this PR, so it is a good time to fix it.

Fixed in dce596a, with the test_colors_tty.empty_no_color case added first in 4d43094. The README now says "any non-empty value".

SizzleUnrlsd · 2026-10-15T02:14:30Z

+// initialization guard as taken when another thread of the parent was deciding
+// at the time of the fork, and wait for it forever. Two threads may decide at
+// once; they reach the same answer.
+std::atomic<int> g_color_decision{0};


[minor] The fork safety relies on std::atomic<int> being lock-free, unchecked.

On a target where it is implemented with a lock (libatomic), a child forked during a load or store would inherit that lock taken. A static_assert(std::atomic<...>::is_always_lock_free); next to the declaration makes the requirement explicit.

Fixed in a0c2f45: static_assert(std::atomic<ColorDecision>::is_always_lock_free);.

SizzleUnrlsd · 2026-10-15T02:14:30Z

+  while (!g_deciding_colors.load()) {
+  }
+
+  const pid_t child = fork();


[minor] Nothing checks that the decision stays cached.

The PR promises one decision per process, but a regression that drops the store (deciding on every color() call: getenv + isatty 10 to 14 times per line) keeps the whole suite green. Counting the fake isatty() calls and checking that later calls do not add any would cover it.

Fixed in 84d6819: the fake isatty() counts its calls, and the test checks that a color() call after the decision adds none.

SizzleUnrlsd · 2026-10-15T02:14:30Z

+bool reap(pid_t child, int &status) {
+  const auto deadline = std::chrono::steady_clock::now() + kChildTimeout;
+  while (std::chrono::steady_clock::now() < deadline) {
+    if (waitpid(child, &status, WNOHANG) == child)


[minor] reap() reports an auto-reaped child as hung.

If the test is launched with SIGCHLD ignored (the disposition is inherited across exec), the child is reaped automatically, waitpid() returns -1/ECHILD, and the loop waits 5 s then fails CHECK(exited) although the child exited fine. Restoring SIG_DFL at the start of main() removes the case.

Fixed in f339a83: main() restores SIG_DFL for SIGCHLD. test_fork.cpp does the same (2c73405).

SizzleUnrlsd · 2026-10-15T02:14:30Z

+
+std::atomic<bool> g_deciding_colors{false};
+
+extern "C" int isatty(int) {


[minor] Exception specification mismatch with glibc's declaration.

glibc declares isatty() with __THROW (noexcept(true) in C++), and the premise "kept apart from <unistd.h>" does not hold: with libstdc++ 13 in C++20, <atomic> includes <unistd.h> (checked with g++ -E on Ubuntu 24.04). The definition without noexcept only compiles because GCC tolerates the mismatch with a system-header declaration.

Fix: include <unistd.h> and copy the C library's specification, noexcept(noexcept(::isatty(0))), which is noexcept on glibc and nothing on macOS.

Fixed in f339a83: the fake includes <unistd.h> and is declared noexcept(noexcept(::isatty(0))). Builds clean with -Wall -Wextra -Werror on g++ 13 and Apple clang 17.

SizzleUnrlsd · 2026-10-15T02:14:30Z

@@ -0,0 +1,17 @@
+// isatty() for test_fork_color.cpp. The logger calls it once, to decide whether


[nit] "The logger calls it once" is not accurate.

In this test the fake is called at least twice (the parent's decider, then the child, which decides again), and two threads may now call it concurrently.

Fixed in 84d6819: the comment now describes the first slow call and the later fast ones.

SizzleUnrlsd · 2026-10-15T02:14:30Z

+  # fork() while another thread decides the colors: the test redefines isatty(), which the
+  # logger calls then, to make that decision last.
+  add_executable(coretrace_logger_test_fork_color test_fork_color.cpp fork_color_isatty.cpp)
+  target_link_libraries(coretrace_logger_test_fork_color PRIVATE coretrace_logger Threads::Threads)


[nit] Threads::Threads is redundant.

It is already a PUBLIC dependency of coretrace_logger (top-level CMakeLists.txt); the other test targets that use std::thread link only coretrace_logger.

Fixed in f339a83.

SizzleUnrlsd · 2026-10-15T02:14:34Z

[blocking] pid() (line 597) keeps the static guard this PR removes from use_color().

static const int cached = platform::process_id();

It is on the same first-line path (write_log_line(), write_prefix()), so a child forked while another thread runs that initializer waits for its guard forever, exactly like the color decision. Independently of the race, every line of a child carries the parent's pid (the PR description mentions it).

Fix: return platform::process_id();. getpid() is cheap next to a log line.

Fixed in 1be612d: pid() returns platform::process_id(). test_fork.cpp (2c73405) checks that a child's pid() equals its getpid().

SizzleUnrlsd · 2026-10-15T02:14:35Z

[important] g_output_mutex and g_state_mutex (lines 49 and 52) can be inherited locked.

g_output_mutex is held for the whole write, sink call included (write_log_line(), line 774). If thread T1 is writing to a slow sink (file, pipe) when T2 calls fork(), the child's first line blocks on OutputLockGuard forever: the same symptom as the issue, with a much wider window than the color decision.

General fix: pthread_atfork() handlers that take the locks before the fork and release them in both processes. The order must be output then state, since a sink that logs takes them in that order. Note that the child cannot release a std::recursive_mutex taken by the parent: glibc and macOS check the owner's thread id, which differs in the child.

Fixed in 9c8a615. pthread_atfork() handlers: before the fork, the forking thread runs init_once(), then takes the output lock and then the state lock; after it, both processes release them. The output lock is now a std::mutex with a thread-local depth, so a sink can still log, and a sink that forks gives a child that can log. 2c73405 adds the tests first: fork while another thread writes through a slow sink, and fork from inside a sink. Without the fix both children hang.

fork() calls the prepare handlers in the reverse order of their registration, and the parent and child handlers in that order. A handler registered before the logger's, here by the test's own initialization, thus runs while the forking thread holds the logger's locks. The new check logs and sets the sink from such handlers, in the prepare, parent and child phases, and expects the lines and the child to come through; alarm() ends the test if fork() hangs. It fails: the forking thread waits for the locks it holds, and fork() never returns.

Between the logger's prepare and parent or child handlers, fork() runs the handlers registered before the logger's, in the forking thread, which then held both locks: a log() or a set_sink() from such a handler waited for a lock its own thread held, and fork() never returned. A regression of the previous commit: without handlers, the logger never held a lock across the fork. The handlers' acquisitions now go through the reentrance of the guards: both locks keep a thread-local count, taken when it goes from 0 to 1 and released when it returns to 0, for the state lock as for the output lock. The forking thread can thus call the logger from any fork handler, while the other threads still wait.

An atexit() handler registered by the test's own initialization, before the logger's, runs after the logger's static destructors, and forks. The logger's fork handlers still run then. It fails on macOS: libc++ destroys the logger's mutexes, and the prepare handler aborts on "mutex lock failed: Invalid argument".

The fork handlers lock the logger's mutexes on every fork(), including one made by an atexit() handler or a static destructor that runs after this file's static destructors. libc++ destroys a std::mutex, and locking it then threw "mutex lock failed: Invalid argument" from the prepare handler, aborting the program. A regression of the fork handlers: without them, fork() never touched the logger. The two mutexes are now never destroyed: they live in a union whose destructor does nothing, still constant-initialized.

SizzleUnrlsd added 3 commits October 15, 2026 00:22

docs(changelog): note the fork-safe color decision

01fe73f

SizzleUnrlsd added the bug Something isn't working label Oct 14, 2026

SizzleUnrlsd self-assigned this Oct 14, 2026

SizzleUnrlsd mentioned this pull request Oct 14, 2026

Runtime: a child of fork() can hang on the logger's first color lookup CoreTrace/coretrace-compiler#213

Closed

SizzleUnrlsd added 9 commits October 15, 2026 03:25

fix(logger): keep the colors on when NO_COLOR is empty

dce596a

no-color.org disables colors when NO_COLOR is present and not an empty string; the logger disabled them for an empty NO_COLOR too, as when a script sets NO_COLOR= to clear it. The README says which values disable the colors.

SizzleUnrlsd commented Oct 15, 2026

View reviewed changes

SizzleUnrlsd added 4 commits October 15, 2026 04:37

SizzleUnrlsd merged commit 284dc42 into main Oct 15, 2026
13 checks passed

SizzleUnrlsd deleted the fix/fork-safe-color-decision branch October 15, 2026 03:23

		const bool enabled =
		env_var("NO_COLOR") == nullptr && platform::stderr_supports_color();


		std::atomic<bool> g_deciding_colors{false};

		extern "C" int isatty(int) {

		@@ -0,0 +1,17 @@
		// isatty() for test_fork_color.cpp. The logger calls it once, to decide whether

Conversation

SizzleUnrlsd commented Oct 14, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Cause

Change

Behavior changes

Tests

Verification

Inside coretrace-compiler

Uh oh!

SizzleUnrlsd left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

SizzleUnrlsd commented Oct 14, 2026 •

edited

Loading