From b3c27e1c315f27f7d4d985fad541de3487d65791 Mon Sep 17 00:00:00 2001 From: Sherlock0203 <1297399478@qq.com> Date: Wed, 28 Oct 2026 18:58:21 +0800 Subject: [PATCH] Fix crash on async logs flushed after the destination changed InitializeLogFileHandle() also succeeds without opening anything when the destination no longer logs to a file, and Log2File() only looked at the return value: an async log that was still in the queue when a later InitLogging() moved the destination away from the file was written through a null FILE* and took the whole process down. The clang-unittest CI hit it through LogRotationTest::TearDown(), which restores the default destination: on builds with the cpu profiler enabled, LoggingTest.performance leaves millions of logs in the queue and the background thread keeps flushing them long after the test is over. The write is skipped when there is no handle to write through, the way MaybeRotateLogFileUnlocked() already checks. The queue draining behind the tests has a second effect: those logs go to whichever file is current, rotating it from under the assertions of the rotation tests that follow. LogRotationTest::SetUp() now drains the queue into the temp file first, with rotation on to bound the disk usage, and waits until the file stops growing, which costs a single stat() poll when the queue is already idle. A regression test reproduces the crash sequence (async backlog, CloseLogFile(), destination change) and the fixture now also saves and restores --async_log_in_background_always. --- src/butil/logging.cc | 8 +++- test/logging_unittest.cc | 83 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 90 insertions(+), 1 deletion(-) diff --git a/src/butil/logging.cc b/src/butil/logging.cc index 4d41a3b299..e39e5efeaf 100644 --- a/src/butil/logging.cc +++ b/src/butil/logging.cc @@ -676,7 +676,13 @@ void Log2File(const std::string& log) { LoggingLock logging_lock; // Rotate before writing so that a single log is never split into two files. MaybeRotateLogFileUnlocked(log.size()); - if (InitializeLogFileHandle()) { + // InitializeLogFileHandle() also succeeds without opening anything when + // the destination no longer logs to a file. That is the case of an async + // log that was queued before a later InitLogging() moved the destination + // away from the file: there is no handle to write through, so the log is + // dropped instead of being written through a null handle, which used to + // crash the process. MaybeRotateLogFileUnlocked() above checks the same. + if (InitializeLogFileHandle() && log_file) { #if defined(OS_WIN) SetFilePointer(log_file, 0, 0, SEEK_END); DWORD num_written = 0; diff --git a/test/logging_unittest.cc b/test/logging_unittest.cc index 719e81047e..8374140f90 100644 --- a/test/logging_unittest.cc +++ b/test/logging_unittest.cc @@ -563,10 +563,30 @@ class LogRotationTest : public LoggingTest { void SetUp() override { LoggingTest::SetUp(); _saved_async_log = FLAGS_async_log; + _saved_async_log_in_background_always = + FLAGS_async_log_in_background_always; _saved_rotate_size_mb = FLAGS_log_rotate_size_mb; _saved_max_backups = FLAGS_log_rotate_max_backups; FLAGS_async_log = false; _log_path = _temp_file.fname(); + // A suite that ran before may have left the async log queue full: + // on builds with the cpu profiler enabled, LoggingTest.performance + // queues millions of logs that take the background thread tens of + // seconds to flush. Those logs go to whichever file is current and + // would rotate it from under the assertions below, so drain them + // into the temp file first, with rotation on to bound the disk + // usage. Costs one stat() when the queue is already idle. + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 2; + InitLoggingToTempFile(); + WaitForAsyncLogToFlush(); + CloseLogFile(); + FLAGS_log_rotate_size_mb = _saved_rotate_size_mb; + FLAGS_log_rotate_max_backups = _saved_max_backups; + unlink(_log_path.c_str()); + for (int i = 1; i <= 3; ++i) { + unlink(BackupPath(i).c_str()); + } } void TearDown() override { @@ -574,6 +594,8 @@ class LogRotationTest : public LoggingTest { FLAGS_log_rotate_max_backups = _saved_max_backups; FLAGS_log_rotate_size_mb = _saved_rotate_size_mb; FLAGS_async_log = _saved_async_log; + FLAGS_async_log_in_background_always = + _saved_async_log_in_background_always; // InitLoggingToTempFile() points the global logging destination at // the temp file. Restore the default destination (stderr on POSIX) // before anything else: once CloseLogFile() above has closed the @@ -607,6 +629,34 @@ class LogRotationTest : public LoggingTest { return _log_path + butil::string_printf(".%d", index); } + // Wait until the async log queue is idle: the background thread + // flushes the backlog into `_log_path', so a size that stops changing + // means that it caught up. Rotation makes the size drop and jump, but + // it never stays the same while logs are still flowing. Bounded so + // that a stuck queue cannot hang the whole test binary. + void WaitForAsyncLogToFlush() { + const int64_t max_wait_us = 600 * 1000 * 1000; + const int stable_samples = 6; + off_t last_size = -1; + int stable = 0; + for (int64_t waited_us = 0; waited_us < max_wait_us; + waited_us += 50 * 1000) { + off_t size = 0; + FileSize(_log_path, &size); // 0 when the file is gone + if (size == last_size) { + if (++stable >= stable_samples) { + return; + } + } else { + stable = 0; + last_size = size; + } + usleep(50 * 1000); + } + fprintf(stderr, "LogRotationTest: async log queue still not idle " + "after %dms\n", (int)(max_wait_us / 1000)); + } + // Each log adds a header on top of `size', which only makes the file grow // faster than the caller expects, never slower. void WriteLogs(int count, size_t size) { @@ -621,6 +671,7 @@ class LogRotationTest : public LoggingTest { private: butil::TempFile _temp_file; bool _saved_async_log{false}; + bool _saved_async_log_in_background_always{false}; int _saved_rotate_size_mb{0}; int _saved_max_backups{0}; }; @@ -1030,6 +1081,38 @@ TEST_F(LogRotationTest, concurrent_sync_log) { ASSERT_EQ((size_t)(thread_num * logs_per_thread), markers.size()); } +// An async log that is still in the queue when a later InitLogging() moves +// the destination away from the file is flushed by the background thread +// without looking at the destination it was queued under, which is what +// TearDown() above does while the queue of LoggingTest.performance is +// still draining. It used to be written through a null FILE* and crashed +// the whole process. +TEST_F(LogRotationTest, async_log_flushed_after_destination_change) { + // Queue everything on the background thread instead of letting the + // enqueueing thread write inline, so that logs are still in flight + // when the destination changes below. + FLAGS_async_log = true; + FLAGS_async_log_in_background_always = true; + InitLoggingToTempFile(); + + const std::string content(100, 'a'); + for (int i = 0; i < 10000; ++i) { + LOG(INFO) << content; + } + // The very sequence of TearDown(): close the handle, then stop logging + // to a file. + CloseLogFile(); + LoggingSettings settings; + settings.logging_dest = LOG_TO_SYSTEM_DEBUG_LOG; + ASSERT_TRUE(InitLogging(settings)); + + // Let the background thread flush the backlog under the new + // destination, then make sure the framework is still usable. + sleep(1); + FLAGS_async_log = false; + LOG(INFO) << "still alive"; +} + #if defined(BRPC_ENABLE_CPU_PROFILER) || defined(BAIDU_RPC_ENABLE_CPU_PROFILER) struct BAIDU_CACHELINE_ALIGNMENT PerfArgs { const std::string* log;