diff --git a/common/alog.cpp b/common/alog.cpp index 0d8b4998..9e48a68b 100644 --- a/common/alog.cpp +++ b/common/alog.cpp @@ -24,6 +24,7 @@ limitations under the License. #include #include #include +#include #include #include #include @@ -220,6 +221,21 @@ void LogFormatter::put_integer_dec(ALogBuffer& buf, ALogInteger x) } } +// Protects log file rotation. It used to be a function-local static in +// write(), but if fork() happened while a thread was rotating, the child +// would inherit the mutex in locked state forever. So it is hoisted here +// and serialized against fork() with pthread_atfork(): prepare acquires +// the lock (waiting for any in-flight rotation), and both parent and +// child release it after fork(). +static mutex log_file_lock; + +__attribute__((constructor)) +static void __register_log_file_lock_atfork() { + pthread_atfork([] { log_file_lock.lock(); }, + [] { log_file_lock.unlock(); }, + [] { log_file_lock.unlock(); }); +} + class LogOutputFile final : public BaseLogOutput { public: uint64_t log_file_size_limit = 0; @@ -250,7 +266,6 @@ class LogOutputFile final : public BaseLogOutput { if (log_file_name && log_file_size_limit) { log_file_size += length; if (log_file_size > log_file_size_limit) { - static mutex log_file_lock; lock_guard guard(log_file_lock); if (log_file_size > log_file_size_limit) { log_file_rotate(); diff --git a/common/test/test_alog.cpp b/common/test/test_alog.cpp index c2797c62..1ba43456 100644 --- a/common/test/test_alog.cpp +++ b/common/test/test_alog.cpp @@ -24,9 +24,13 @@ limitations under the License. #include #include #include +#include +#include #include #include #include +#include +#include #include "../../test/ci-tools.h" #include "../../test/gtest.h" @@ -177,6 +181,45 @@ TEST(ALog, log_to_file) { ::close(fd); } +static bool wait_child_exited(pid_t pid, int timeout_sec) { + for (int i = 0; i < timeout_sec * 100; ++i) { + int st; + if (::waitpid(pid, &st, WNOHANG) == pid) + return WIFEXITED(st) && WEXITSTATUS(st) == 0; + ::usleep(10 * 1000); + } + ::kill(pid, SIGKILL); + ::waitpid(pid, nullptr, 0); + return false; +} + +TEST(ALog, fork_during_rotation) { + const char* fn = "/tmp/test_alog_fork.log"; + // minimum rotate limit is 1MB + ASSERT_EQ(0, log_output_file(fn, 1024 * 1024, 3)); + DEFER(log_output_file_close()); + // keep triggering rotation in background, so that fork() below + // is likely to happen while the rotation lock is held + std::atomic stop{false}; + std::thread writer([&] { + while (!stop) + LOG_INFO("background writer keeps rotating the log file, padding padding padding padding"); + }); + DEFER({ stop = true; writer.join(); }); + for (int i = 0; i < 8; ++i) { + pid_t pid = fork(); + ASSERT_GE(pid, 0); + if (pid == 0) { + // child: write enough to trigger a rotation of its own; + // it deadlocks here if the rotation lock was inherited locked + for (int j = 0; j < 16 * 1024; ++j) + LOG_INFO("child writer must not deadlock on the rotation lock, padding padding padding"); + ::_exit(0); + } + EXPECT_TRUE(wait_child_exited(pid, 10)) << "child " << pid << " deadlocked"; + } +} + TEST(ALog, float_point) { log_output = &log_output_test;