diff --git a/CHANGELOG.md b/CHANGELOG.md index bd27995..10ab34f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,11 @@ Notable changes are grouped by release. See [all releases](https://github.com/Co ## Unreleased - Added repository contribution, conduct and security documentation. +- A child of `fork()` no longer hangs on its first line when another thread of the parent was + deciding whether stderr takes colors, writing a line or initializing the logger at the time of + the fork: `fork()` waits for the line and the initialization. +- A child of `fork()` logs its own pid instead of the parent's. +- An empty `NO_COLOR` no longer disables colors, as no-color.org specifies. ## v1.1.0 diff --git a/README.md b/README.md index 555c909..eb36bed 100644 --- a/README.md +++ b/README.md @@ -218,7 +218,9 @@ coretrace::set_thread_safe(true); // Default: mutex-protected output coretrace::set_thread_safe(false); // Disable for single-threaded hot paths ``` -In thread-safe mode, each line reaches the sink in a single call and never concurrently with another line. The mutex is recursive, so a sink may itself call `log()`, for example to report a write error. With `set_thread_safe(false)`, the sink can be called from several threads at once, and `set_sink()` no longer waits. +In thread-safe mode, each line reaches the sink in a single call and never concurrently with another line. The lock is reentrant, so a sink may itself call `log()`, for example to report a write error. With `set_thread_safe(false)`, the sink can be called from several threads at once, and `set_sink()` no longer waits. + +On POSIX, `fork()` waits for a line another thread is writing, so the child can log, even when the parent's threads were logging at the time of the fork. ### Colors @@ -230,7 +232,7 @@ coretrace::log(Level::Info, "{}bold{} and {}red{}\n", coretrace::color(Color::Reset)); ``` -Colors are automatically disabled when stderr is not a terminal or when `NO_COLOR` is set. +Colors are automatically disabled when stderr is not a terminal or when `NO_COLOR` is set to a non-empty value. ### Low-level API @@ -240,7 +242,7 @@ coretrace::write_str("hello"); // Write string coretrace::write_dec(42); // Write decimal (no heap) coretrace::write_hex(0xDEAD); // Write hex with 0x prefix coretrace::write_raw(buf, len); // Write raw bytes -coretrace::pid(); // Cached PID +coretrace::pid(); // Process ID coretrace::thread_id(); // Platform-specific TID ``` @@ -252,7 +254,9 @@ These functions write straight to the sink: unlike `log()`, they are not seriali |----------|--------|-------------| | `CT_LOG_LEVEL` | `debug`, `info`, `warn`, `error` (case-insensitive) | Set startup default minimum log level. Other values mean `info` | | `CT_DEBUG` | comma-separated names | Set startup default enabled modules. Spaces around names are ignored | -| `NO_COLOR` | any value | Disable ANSI color output | +| `NO_COLOR` | any non-empty value | Disable ANSI color output | + +`CT_LOG_LEVEL` and `CT_DEBUG` are read once, at the first logging call or, on POSIX, at the first `fork()`, whichever comes first. ## Output format diff --git a/include/coretrace/logger.hpp b/include/coretrace/logger.hpp index 6a59247..2adf188 100644 --- a/include/coretrace/logger.hpp +++ b/include/coretrace/logger.hpp @@ -164,7 +164,7 @@ void enable_all_modules(); /// Enable or disable mutex-based serialization of log output. /// Default: true (thread-safe). Each line then reaches the sink in one call, -/// never concurrently with another line. The mutex is recursive, so a sink may +/// never concurrently with another line. The lock is reentrant, so a sink may /// itself call log(). Set to false for single-threaded hot paths: the sink can /// then be called concurrently, and set_sink() does not wait. void set_thread_safe(bool enabled); @@ -241,7 +241,7 @@ void write_hex(uintptr_t value); // System info // ####################################### -/// Return the cached process ID. +/// Return the process ID. [[nodiscard]] int pid(); /// Return the current thread ID (platform-specific). diff --git a/src/logger.cpp b/src/logger.cpp index cfa0870..f70ede5 100644 --- a/src/logger.cpp +++ b/src/logger.cpp @@ -45,11 +45,29 @@ std::atomic g_modules_set_explicitly{0}; // ── Synchronization ────────────────────── +// Both locks are reentrant: a thread takes a lock only when its count for that +// lock goes from 0 to 1, so that a sink, or a fork handler, can call the logger +// while the thread holds them. Not std::recursive_mutex, which a child of +// fork() cannot release: it checks the id of its owner, and the child's thread +// has another one. + +// Never destroyed: fork() takes the locks even while the program exits, from an +// atexit() handler or a static destructor that runs after this file's. +template union Immortal { + T value; + constexpr Immortal() : value() {} + ~Immortal() {} +}; + // Protects mutable logger state (prefix + modules table). -std::mutex g_state_mutex; +Immortal g_state_lock; +std::mutex &g_state_mutex = g_state_lock.value; +thread_local int t_state_depth = 0; // Protects atomicity of one log line output when thread-safe mode is on. -std::recursive_mutex g_output_mutex; +Immortal g_output_lock; +std::mutex &g_output_mutex = g_output_lock.value; +thread_local int t_output_depth = 0; std::atomic g_thread_safe{1}; // enabled by default // ── Sink ───────────────────────────────── @@ -70,9 +88,20 @@ std::once_flag g_init_once; // ── Small lock guards ──────────────────── +void lock_reentrant(std::mutex &mutex, int &depth) { + if (depth == 0) + mutex.lock(); + ++depth; +} + +void unlock_reentrant(std::mutex &mutex, int &depth) { + if (--depth == 0) + mutex.unlock(); +} + struct StateLockGuard { - StateLockGuard() { g_state_mutex.lock(); } - ~StateLockGuard() { g_state_mutex.unlock(); } + StateLockGuard() { lock_reentrant(g_state_mutex, t_state_depth); } + ~StateLockGuard() { unlock_reentrant(g_state_mutex, t_state_depth); } StateLockGuard(const StateLockGuard &) = delete; StateLockGuard &operator=(const StateLockGuard &) = delete; @@ -82,12 +111,12 @@ struct OutputLockGuard { OutputLockGuard() : locked(g_thread_safe.load(std::memory_order_acquire) != 0) { if (locked) - g_output_mutex.lock(); + lock_reentrant(g_output_mutex, t_output_depth); } ~OutputLockGuard() { if (locked) - g_output_mutex.unlock(); + unlock_reentrant(g_output_mutex, t_output_depth); } OutputLockGuard(const OutputLockGuard &) = delete; @@ -96,6 +125,28 @@ struct OutputLockGuard { bool locked; }; +// ── Fork ───────────────────────────────── + +// A child of fork() has only the thread that forked. So that it inherits +// neither a lock nor the initialization taken by another thread of the parent, +// fork() waits for them: the forking thread finishes the initialization, then +// takes the locks, in the order of a sink that logs, and releases them in both +// processes. Other fork handlers run in between, in the forking thread: since +// the locks count as held by it, they can call the logger. +void before_fork() { + init_once(); + lock_reentrant(g_output_mutex, t_output_depth); + lock_reentrant(g_state_mutex, t_state_depth); +} + +void after_fork() { + unlock_reentrant(g_state_mutex, t_state_depth); + unlock_reentrant(g_output_mutex, t_output_depth); +} + +[[maybe_unused]] const bool g_fork_handlers_registered = + (platform::at_fork(before_fork, after_fork), true); + struct PrefixSnapshot { char value[sizeof(g_prefix_buf)]; size_t len = 0; @@ -130,15 +181,30 @@ struct PrefixSnapshot { // ── Color detection ────────────────────── -[[nodiscard]] bool use_color() { - static const bool enabled = []() { - if (env_var("NO_COLOR") != nullptr) - return false; +enum class ColorDecision { Undecided, Off, On }; - return platform::stderr_supports_color(); - }(); +// Whether stderr takes colors, decided once per process. Not a function-local +// static: a child of fork() would inherit its initialization guard as taken +// when another thread of the parent was deciding at the time of the fork, and +// wait for it forever. Lock-free for the same reason. Two threads may decide at +// once: the first decision stored holds for both. +std::atomic g_color_decision{ColorDecision::Undecided}; +static_assert(std::atomic::is_always_lock_free); - return enabled; +[[nodiscard]] bool use_color() { + ColorDecision decision = g_color_decision.load(std::memory_order_acquire); + if (decision == ColorDecision::Undecided) { + // NO_COLOR disables the colors when it is not empty (no-color.org). + const char *no_color = env_var("NO_COLOR"); + const bool enabled = (no_color == nullptr || no_color[0] == '\0') && + platform::stderr_supports_color(); + ColorDecision expected = ColorDecision::Undecided; + decision = enabled ? ColorDecision::On : ColorDecision::Off; + if (!g_color_decision.compare_exchange_strong(expected, decision, + std::memory_order_acq_rel)) + decision = expected; + } + return decision == ColorDecision::On; } // ── String helpers ─────────────────────── @@ -587,10 +653,8 @@ void set_source_location(bool enabled) { // System info // #################################### -[[nodiscard]] int pid() { - static const int cached = platform::process_id(); - return cached; -} +// Not cached: a child of fork() has its own pid. +[[nodiscard]] int pid() { return platform::process_id(); } [[nodiscard]] unsigned long long thread_id() { return platform::current_thread_id(); diff --git a/src/logger_platform.hpp b/src/logger_platform.hpp index 3e9e7c4..cf8b578 100644 --- a/src/logger_platform.hpp +++ b/src/logger_platform.hpp @@ -20,6 +20,9 @@ void write_stderr(const char *data, size_t size); [[nodiscard]] int process_id(); [[nodiscard]] unsigned long long current_thread_id(); [[nodiscard]] bool utc_timestamp(UtcTimestamp &out); +// Makes fork() call `before` first, in the thread that forks, and `after` then, +// in that thread of the parent and of the child. Does nothing without fork(). +void at_fork(void (*before)(), void (*after)()); } // namespace coretrace::platform diff --git a/src/logger_posix.cpp b/src/logger_posix.cpp index 8955eeb..1bc689d 100644 --- a/src/logger_posix.cpp +++ b/src/logger_posix.cpp @@ -62,4 +62,8 @@ void write_stderr(const char *data, size_t size) { return true; } +void at_fork(void (*before)(), void (*after)()) { + (void)pthread_atfork(before, after, after); +} + } // namespace coretrace::platform diff --git a/src/logger_windows.cpp b/src/logger_windows.cpp index 5204809..ff032b5 100644 --- a/src/logger_windows.cpp +++ b/src/logger_windows.cpp @@ -86,4 +86,6 @@ void write_stderr(const char *data, size_t size) { return true; } +void at_fork(void (*)(), void (*)()) {} + } // namespace coretrace::platform diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index ff35d97..8cdb819 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -59,6 +59,22 @@ if(UNIX) COMMAND coretrace_logger_test_colors_tty no_color) set_tests_properties(coretrace_logger.test_colors_tty.no_color PROPERTIES ENVIRONMENT "NO_COLOR=1") + add_test(NAME coretrace_logger.test_colors_tty.empty_no_color + COMMAND coretrace_logger_test_colors_tty empty_no_color) +endif() + +if(UNIX) + # 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) + add_test(NAME coretrace_logger.test_fork_color COMMAND coretrace_logger_test_fork_color) + set_tests_properties(coretrace_logger.test_fork_color PROPERTIES TIMEOUT 20) + + add_executable(coretrace_logger_test_fork test_fork.cpp) + target_link_libraries(coretrace_logger_test_fork PRIVATE coretrace_logger) + add_test(NAME coretrace_logger.test_fork COMMAND coretrace_logger_test_fork) + set_tests_properties(coretrace_logger.test_fork PROPERTIES TIMEOUT 30) endif() add_executable(coretrace_logger_test_sink_reentrancy test_sink_reentrancy.cpp) diff --git a/tests/fork_color_isatty.cpp b/tests/fork_color_isatty.cpp new file mode 100644 index 0000000..7c89750 --- /dev/null +++ b/tests/fork_color_isatty.cpp @@ -0,0 +1,23 @@ +// isatty() for test_fork_color.cpp, linked into the test program ahead of the +// C library. The logger calls it to decide whether stderr takes colors. The +// first call says stderr is a terminal, after long enough for the test to fork +// and to decide in another thread during it; later calls say it is not, at +// once. + +#include +#include +#include + +std::atomic g_deciding_colors{false}; +std::atomic g_isatty_calls{0}; + +// Same exception specification as the C library's declaration, which glibc +// marks noexcept. +extern "C" int isatty(int) noexcept(noexcept(::isatty(0))) { + if (g_isatty_calls.fetch_add(1) != 0) + return 0; + g_deciding_colors.store(true); + const timespec delay{0, 300 * 1000 * 1000}; + nanosleep(&delay, nullptr); + return 1; +} diff --git a/tests/fork_helpers.hpp b/tests/fork_helpers.hpp new file mode 100644 index 0000000..e3fa7e8 --- /dev/null +++ b/tests/fork_helpers.hpp @@ -0,0 +1,53 @@ +#ifndef CORETRACE_LOGGER_TESTS_FORK_HELPERS_HPP +#define CORETRACE_LOGGER_TESTS_FORK_HELPERS_HPP + +// Helpers shared by the POSIX tests that fork. They need the default SIGCHLD +// action, which each test sets: when SIGCHLD is ignored, waitpid() cannot reap +// a child. + +#include +#include +#include +#include +#include +#include +#include + +namespace ct_test { + +inline constexpr std::chrono::seconds kForkTimeout{5}; + +/// True when `child` exits with status 0. A child still running after +/// kForkTimeout is killed, and reported as hung. +[[nodiscard]] inline bool child_succeeded(pid_t child) { + if (child <= 0) + return false; + int status = 0; + const auto deadline = std::chrono::steady_clock::now() + kForkTimeout; + while (std::chrono::steady_clock::now() < deadline) { + if (waitpid(child, &status, WNOHANG) == child) + return WIFEXITED(status) && WEXITSTATUS(status) == 0; + usleep(1000); + } + kill(child, SIGKILL); + waitpid(child, &status, 0); + std::fprintf(stderr, "child %d hung: killed after %lld s\n", + static_cast(child), + static_cast(kForkTimeout.count())); + return false; +} + +/// True once `flag` is set, false after kForkTimeout. +[[nodiscard]] inline bool wait_for(const std::atomic &flag) { + const auto deadline = std::chrono::steady_clock::now() + kForkTimeout; + while (!flag.load()) { + if (std::chrono::steady_clock::now() >= deadline) + return false; + std::this_thread::yield(); + } + return true; +} + +} // namespace ct_test + +#endif // CORETRACE_LOGGER_TESTS_FORK_HELPERS_HPP diff --git a/tests/test_colors_tty.cpp b/tests/test_colors_tty.cpp index 998f48b..3287b61 100644 --- a/tests/test_colors_tty.cpp +++ b/tests/test_colors_tty.cpp @@ -40,12 +40,16 @@ int attach_pty_to_stderr() { } // namespace // The logger decides once per process whether stderr gets colors, so ctest -// runs one process with NO_COLOR=1 ("no_color") and one without it. +// runs one process with NO_COLOR=1 ("no_color"), one with NO_COLOR empty +// ("empty_no_color"), which leaves the colors on, and one without it. int main(int argc, char **argv) { using namespace coretrace; - const bool no_color = argc > 1 && std::string_view(argv[1]) == "no_color"; - if (!no_color) + const std::string_view mode = argc > 1 ? argv[1] : ""; + const bool no_color = mode == "no_color"; + if (mode == "empty_no_color") + CHECK(ct_test::set_env("NO_COLOR", "")); + else if (!no_color) unsetenv("NO_COLOR"); set_sink(ct_test::capture_sink); diff --git a/tests/test_fork.cpp b/tests/test_fork.cpp new file mode 100644 index 0000000..be70aac --- /dev/null +++ b/tests/test_fork.cpp @@ -0,0 +1,165 @@ +// fork() while threads of the parent use the logger: the child can log. fork() +// waits for the logger's initialization and for a line another thread is +// writing, so the child inherits neither half done; a sink can fork and its +// child still log; other fork handlers can still log; fork() still works while +// the program exits; and the child's lines carry the child's pid. + +#include "check.hpp" +#include "fork_helpers.hpp" + +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace { + +using coretrace::Level; + +// fork() finishes the logger's initialization when no thread has: the +// environment defaults are those at the time of the fork. Runs first, before +// any call initializes the logger. +void check_fork_initializes() { + CHECK(ct_test::set_env("CT_LOG_LEVEL", "debug")); + const pid_t child = fork(); + if (child == 0) + _exit(coretrace::min_level() == Level::Debug ? 0 : 1); + CHECK(ct_test::set_env("CT_LOG_LEVEL", "error")); + CHECK(coretrace::min_level() == Level::Debug); + CHECK(ct_test::child_succeeded(child)); +} + +void check_child_pid() { + CHECK(coretrace::pid() == getpid()); + const pid_t child = fork(); + if (child == 0) + _exit(coretrace::pid() == getpid() ? 0 : 1); + CHECK(ct_test::child_succeeded(child)); +} + +std::atomic g_writing{false}; + +// Writes the first line in 300 ms, long enough for the test to fork meanwhile. +void slow_sink(const char *, size_t) { + if (!g_writing.exchange(true)) + std::this_thread::sleep_for(std::chrono::milliseconds(300)); +} + +void check_fork_while_writing() { + coretrace::set_sink(slow_sink); + // The writer outlives the fork: ThreadSanitizer reports a thread that a + // child inherits finished and not joined. + std::atomic forked{false}; + std::thread writer([&] { + coretrace::log(Level::Info, "parent\n"); + (void)ct_test::wait_for(forked); + }); + const bool writing = ct_test::wait_for(g_writing); + CHECK(writing); + const pid_t child = writing ? fork() : -1; + if (child == 0) { + coretrace::log(Level::Info, "child\n"); + _exit(0); + } + forked = true; + writer.join(); + CHECK(ct_test::child_succeeded(child)); + coretrace::reset_sink(); +} + +pid_t g_sink_child = -1; + +// Forks on the line "fork": the child logs, from the sink and after it. +void forking_sink(const char *data, size_t size) { + if (std::string_view(data, size).find("fork") == std::string_view::npos) + return; + g_sink_child = fork(); + if (g_sink_child == 0) + coretrace::log(Level::Info, "child, in the sink\n"); +} + +void check_fork_from_sink() { + coretrace::set_sink(forking_sink); + coretrace::log(Level::Info, "fork\n"); + if (g_sink_child == 0) { + coretrace::log(Level::Info, "child, after the sink\n"); + _exit(0); + } + coretrace::reset_sink(); + CHECK(ct_test::child_succeeded(g_sink_child)); +} + +std::atomic g_log_from_fork_handlers{false}; + +void log_from_fork_handler() { + if (!g_log_from_fork_handlers.load()) + return; + coretrace::log(Level::Info, "from a fork handler\n"); + coretrace::set_sink(ct_test::capture_sink); +} + +// Registered by this translation unit's initialization, which runs before the +// logger's: fork() calls the prepare handler after the logger's, and the +// parent and child handlers before the logger's, while the forking thread holds +// the logger's locks. +const bool g_fork_handlers_registered = + pthread_atfork(log_from_fork_handler, log_from_fork_handler, + log_from_fork_handler) == 0; + +void check_logging_from_fork_handlers() { + CHECK(g_fork_handlers_registered); + coretrace::set_sink(ct_test::capture_sink); + const size_t from = ct_test::captured.size(); + g_log_from_fork_handlers = true; + alarm(5); // A fork() that hangs in a handler kills the test. + const pid_t child = fork(); + if (child == 0) + _exit(0); + alarm(0); + g_log_from_fork_handlers = false; + CHECK(ct_test::child_succeeded(child)); + + // One line from the prepare handler, one from the parent handler. + constexpr std::string_view line = "from a fork handler"; + const size_t first = ct_test::captured.find(line, from); + CHECK(first != std::string::npos && ct_test::logged(line, first + 1)); + coretrace::reset_sink(); +} + +void fork_at_exit() { + const pid_t child = fork(); + if (child == 0) + _exit(0); + if (!ct_test::child_succeeded(child)) { + std::fputs("fork() at exit failed\n", stderr); + _exit(1); + } +} + +// Registered by this translation unit's initialization, which runs before the +// logger's: fork_at_exit() runs after the logger's static destructors. +const bool g_fork_at_exit_registered = std::atexit(fork_at_exit) == 0; + +} // namespace + +int main() { + std::signal(SIGCHLD, SIG_DFL); + CHECK(g_fork_at_exit_registered); + check_fork_initializes(); + check_child_pid(); + coretrace::set_min_level(Level::Info); + coretrace::enable_logging(); + check_fork_while_writing(); + check_fork_from_sink(); + check_logging_from_fork_handlers(); + return ct_test::result(); +} diff --git a/tests/test_fork_color.cpp b/tests/test_fork_color.cpp new file mode 100644 index 0000000..1e3f5a4 --- /dev/null +++ b/tests/test_fork_color.cpp @@ -0,0 +1,56 @@ +// A child of fork() can use the colors although another thread of the parent +// was deciding them at the time of the fork: the child decides them again, +// instead of waiting for a decision that no thread of the child will ever +// finish. In the parent, the first decision stored holds for every thread, and +// later calls do not decide again. + +#include "check.hpp" +#include "fork_helpers.hpp" + +#include + +#include +#include +#include +#include +#include +#include + +extern std::atomic g_deciding_colors; +extern std::atomic g_isatty_calls; + +int main() { + // The logger decides without isatty() under NO_COLOR, which may come from + // the environment. + unsetenv("NO_COLOR"); + std::signal(SIGCHLD, SIG_DFL); + + using coretrace::Color; + + // The decider is told stderr is a terminal, after the main thread is told it + // is not: the main thread's decision is stored first. + std::string_view decider_red; + std::thread decider([&] { decider_red = coretrace::color(Color::Red); }); + const bool deciding = ct_test::wait_for(g_deciding_colors); + CHECK(deciding); + if (!deciding) { + decider.join(); + return ct_test::result(); + } + + const pid_t child = fork(); + if (child == 0) { + (void)coretrace::color(Color::Red); + _exit(0); + } + const std::string_view main_red = coretrace::color(Color::Red); + decider.join(); + CHECK(decider_red == main_red); + + const int calls = g_isatty_calls.load(); + CHECK(coretrace::color(Color::Red) == main_red); + CHECK(g_isatty_calls.load() == calls); + + CHECK(ct_test::child_succeeded(child)); + return ct_test::result(); +}