Fix silent backup loss and test pollution in log rotation

docs/cn/streaming_log.md

@@ -270,7 +270,7 @@ CHECK(x > y);    // Check failed: x > y.
 
 切分默认关闭，升级不会改变已有的文件名和文件内容。打开后，当前文件 `foo.log` 会被重命名为 `foo.log.1`，原先的 `foo.log.1` 变为 `foo.log.2`，依此类推，超过 `log_rotate_max_backups` 的最老文件被删除，即 `.1` 永远是最近一次切出来的日志。切分发生在写入之前，所以一条日志不会被拆到两个文件里；单条日志超过 `log_rotate_size_mb` 时不会产生空文件，该条日志会完整写入当前文件。
 
-如果重命名失败（比如日志所在目录不可写），brpc会打印一条错误，然后等文件又长了一个`log_rotate_size_mb`再重试，而不是每写一条日志都去关闭、重开、重命名一次文件。期间日志继续追加到当前文件，不会丢。如果发现文件比失败时更小，说明它已经被外部替换或截断，切分立刻恢复正常。
+如果重命名失败（比如日志所在目录不可写），brpc会打印一条错误，然后等文件又长了一个`log_rotate_size_mb`再重试，而不是每写一条日志都去关闭、重开、重命名一次文件。期间日志继续追加到当前文件，不会丢。如果某个历史文件因为被其它进程占用等原因移不走，切分会整体放弃这一次操作，而不会用当前文件把它覆盖掉，因此不会悄悄丢掉一代日志。如果发现文件比失败时更小，说明它已经被外部替换或截断，切分立刻恢复正常。
 
 > 不要在同一个日志文件上同时使用logrotate等外部切分工具。外部工具把文件改名之后，brpc下一次写入会重新创建原路径的文件，两边的切分规则会互相干扰，保留下来的历史文件数也不再受`log_rotate_max_backups`控制。二选一。
 

docs/en/streaming_log.md

@@ -272,7 +272,7 @@ When logs go to a file (`LoggingSettings.logging_dest` contains `LOG_TO_FILE`),
 
 Rotation is disabled by default, so upgrading changes neither the file names nor the existing files. Once enabled, the current file `foo.log` is renamed to `foo.log.1`, the previous `foo.log.1` becomes `foo.log.2` and so on, and the files beyond `log_rotate_max_backups` are removed. In other words `.1` is always the most recent backup. The check happens before the write, so a single log is never split into two files; a log larger than `log_rotate_size_mb` does not produce empty backups either, it is written to the current file as a whole.
 
-If the rename fails, for example because the directory holding the log file is not writable, brpc prints an error and retries only once the file has grown by another `log_rotate_size_mb`, instead of closing, reopening and renaming the file for every single log. Logs keep being appended to the current file in the meantime, none of them are lost. If the file turns out to be smaller than it was when rotation failed, it has been replaced or truncated from the outside and rotation resumes immediately.
+If the rename fails, for example because the directory holding the log file is not writable, brpc prints an error and retries only once the file has grown by another `log_rotate_size_mb`, instead of closing, reopening and renaming the file for every single log. Logs keep being appended to the current file in the meantime, none of them are lost. A backup that cannot be renamed out of the way, for example because another process holds it open, stops the rotation altogether rather than being overwritten with the current file, so no generation is silently dropped. If the file turns out to be smaller than it was when rotation failed, it has been replaced or truncated from the outside and rotation resumes immediately.
 
 > Do not run an external rotator such as logrotate on the same log file. Once an external tool renames the file, the next write recreates it under the original name, the two sets of rotation rules interfere with each other and the number of files kept around is no longer bounded by `log_rotate_max_backups`. Use one or the other.
 

src/butil/logging.cc

@@ -473,13 +473,20 @@ void CloseLogFileUnlocked() {
 //
 // A log file that disappeared from under the process is not a rotation
 // failure: the handle is closed so that the next write starts a fresh file,
-// and the backups are left untouched.
+// and the backups are left untouched. The size at which it happened is
+// remembered all the same, so that a file which is still over the limit
+// once reopened (the ".\\debug.log" that Windows falls back to when the
+// requested name could not be opened at all) is not closed and reopened on
+// every single log.
 //
-// A rename that fails does not disable rotation for good. The size at which
-// it failed is remembered and rotation is retried once the file has grown by
-// another --log_rotate_size_mb, which keeps a directory that cannot be
-// written to from closing, reopening and renaming the file for every single
-// log. A file that turns out to be smaller than it was at that point has been
+// A rename that fails does not disable rotation for good, and a backup is
+// only ever replaced by a shift that succeeded: a backup that cannot be
+// moved out of the way aborts the rotation instead of being silently
+// overwritten with the current file. The size at which the rotation failed
+// is remembered and rotation is retried once the file has grown by another
+// --log_rotate_size_mb, which keeps a directory that cannot be written to
+// from closing, reopening and renaming the file for every single log. A
+// file that turns out to be smaller than it was at that point has been
 // replaced or truncated from the outside, and rotation resumes immediately.
 //
 // Sharing one log file between multiple processes is NOT supported together
@@ -519,25 +526,60 @@ bool RenameFilePath(const PathString& from, const PathString& to) {
 #endif
 }
 
+// Narrow representation of a path, for printing. Paths are wide on Windows.
+std::string PathAsString(const PathString& path) {
+#if defined(OS_WIN)
+    return butil::WideToUTF8(path);
+#else
+    return path;
+#endif
+}
+
+// Back off after a rotation that could not rename `from' to `to': the size
+// that triggered it does not change by itself, so retrying on the next log
+// would close, reopen and rename the file for every single log. The failure
+// is printed once rather than per log. The caller must hold the logging
+// lock and `err' must have been captured before anything else could
+// overwrite it.
+void BackOffAfterFailedRotation(int64_t size_before_rotation,
+                                const PathString& from,
+                                const PathString& to,
+                                SystemErrorCode err) {
+    failed_rotation_size = size_before_rotation;
+    if (rotation_failure_reported) {
+        return;
+    }
+    rotation_failure_reported = true;
+    fprintf(stderr, "Fail to rotate %s: renaming %s to %s failed: %s, "
+            "retrying after another --log_rotate_size_mb of logs\n",
+            PathAsString(*log_file_name).c_str(), PathAsString(from).c_str(),
+            PathAsString(to).c_str(),
+            SystemErrorCodeToString(err).c_str());
+}
+
 // Rename the current log file to "<log_file_name>.1" and shift the older
 // backups down by one. The caller must hold the logging lock.
 void RotateLogFileUnlocked() {
     if (!log_file_name) {
         return;
     }
+    // Remember it before closing, CloseLogFileUnlocked() resets the size.
+    const int64_t size_before_rotation = log_file_size;
     if (!PathExists(*log_file_name)) {
         // The file was renamed or removed from the outside. There is nothing
         // to rotate: closing the handle makes the next write start a fresh
         // file under the original name, which is what a rotation would have
         // done anyway. The backups are left alone, shifting them down would
-        // consume one generation for nothing.
+        // consume one generation for nothing. This is not an error, but the
+        // back off still applies: the file that the next write reopens may
+        // still be over the limit, which is the case of the Windows
+        // fallback to ".\\debug.log" when the requested name could not be
+        // opened at all. A fresh file is smaller than
+        // `size_before_rotation', which lets the next write retry at once.
         CloseLogFileUnlocked();
-        failed_rotation_size = -1;
-        rotation_failure_reported = false;
+        failed_rotation_size = size_before_rotation;
         return;
     }
-    // Remember it before closing, CloseLogFileUnlocked() resets the size.
-    const int64_t size_before_rotation = log_file_size;
     // Close before renaming: on Windows an opened file cannot be renamed, and
     // on POSIX the handle would keep pointing at the renamed inode.
     CloseLogFileUnlocked();
@@ -556,28 +598,39 @@ void RotateLogFileUnlocked() {
             break;  // could not remove it, do not spin
         }
     }
-    for (int i = max_backups - 1; i >= 1; --i) {
-        RenameFilePath(MakeBackupLogPath(*log_file_name, i),
-                       MakeBackupLogPath(*log_file_name, i + 1));
+    // Rotation numbers the backups contiguously, so the first missing index
+    // bounds the existing ones from above. Shifting from the highest
+    // existing index rather than from --log_rotate_max_backups keeps a huge
+    // value (only validated to be a positive int) from turning into as many
+    // rename() calls on every rotation, all under the logging lock.
+    int highest_backup = 0;
+    for (int i = 1; i < max_backups; ++i) {
+        if (!PathExists(MakeBackupLogPath(*log_file_name, i))) {
+            break;
+        }
+        highest_backup = i;
+    }
+    // Shift the backups down by one. A rename that fails aborts the
+    // rotation: renaming the current file over "<log_file_name>.1" anyway
+    // would destroy the newest backup, the very one that the failed shift
+    // could not move out of the way.
+    for (int i = highest_backup; i >= 1; --i) {
+        const PathString from = MakeBackupLogPath(*log_file_name, i);
+        const PathString to = MakeBackupLogPath(*log_file_name, i + 1);
+        if (!RenameFilePath(from, to)) {
+            BackOffAfterFailedRotation(size_before_rotation, from, to,
+                                       GetLastSystemErrorCode());
+            return;
+        }
     }
-    if (RenameFilePath(*log_file_name,
-                       MakeBackupLogPath(*log_file_name, 1))) {
+    const PathString first_backup = MakeBackupLogPath(*log_file_name, 1);
+    if (RenameFilePath(*log_file_name, first_backup)) {
         failed_rotation_size = -1;
         rotation_failure_reported = false;
         return;
     }
-    // Back off rather than retrying on every log. The next write reopens the
-    // file under its original name and keeps appending, which is better than
-    // dropping logs.
-    failed_rotation_size = size_before_rotation;
-    if (!rotation_failure_reported) {
-        rotation_failure_reported = true;
-#if defined(OS_POSIX)
-        fprintf(stderr, "Fail to rotate %s: %s, retrying after another "
-                "--log_rotate_size_mb of logs\n",
-                log_file_name->c_str(), berror());
-#endif
-    }
+    BackOffAfterFailedRotation(size_before_rotation, *log_file_name,
+                               first_backup, GetLastSystemErrorCode());
 }
 
 // Rotate the log file if appending `incoming_size' bytes would grow it beyond

test/logging_unittest.cc

@@ -5,10 +5,13 @@
 #include "butil/basictypes.h"
 #include "butil/logging.h"
 #include "gperftools_helper.h"
+#include "butil/file_util.h"
 #include "butil/files/temp_file.h"
 #include "butil/popen.h"
+#include "butil/time.h"
 #include <gtest/gtest.h>
 #include <gflags/gflags.h>
+#include <set>
 #include <sys/stat.h>
 #include <unistd.h>
 
@@ -568,12 +571,25 @@ class LogRotationTest : public LoggingTest {
 
     void TearDown() override {
         CloseLogFile();
-        for (int i = 1; i <= _saved_max_backups + 2; ++i) {
-            unlink(BackupPath(i).c_str());
-        }
         FLAGS_log_rotate_max_backups = _saved_max_backups;
         FLAGS_log_rotate_size_mb = _saved_rotate_size_mb;
         FLAGS_async_log = _saved_async_log;
+        // 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
+        // handle, the next log of whichever suite runs later would reopen
+        // and keep appending to a file under this path, and its stderr
+        // would go silent.
+        LoggingSettings settings;
+        settings.logging_dest = LOG_TO_SYSTEM_DEBUG_LOG;
+        ASSERT_TRUE(InitLogging(settings));
+        // A failed test may leave the obstacle directories that the
+        // rotation failure tests create behind, remove them as well.
+        for (int i = 1; i <= _saved_max_backups + 2; ++i) {
+            unlink(BackupPath(i).c_str());
+            rmdir((BackupPath(i) + "/x").c_str());
+            rmdir(BackupPath(i).c_str());
+        }
         LoggingTest::TearDown();
     }
 
@@ -878,6 +894,142 @@ TEST_F(LogRotationTest, recovers_after_the_log_file_is_replaced) {
     unlink(moved.c_str());
 }
 
+// A backup that cannot be shifted out of the way must stop the rotation
+// rather than let the final rename overwrite it with the current log file,
+// which would silently drop the newest generation on every rotation.
+TEST_F(LogRotationTest, shift_failure_keeps_the_newest_backup) {
+    FLAGS_log_rotate_size_mb = 1;
+    FLAGS_log_rotate_max_backups = 2;
+    InitLoggingToTempFile();
+
+    // Rotate once so that ".1" holds a complete generation. The size is
+    // not enough to tell the generations apart, the rotation threshold
+    // makes them equally large, the content is compared instead.
+    WriteLogs(1200, 1000);
+    std::string first_backup;
+    ASSERT_TRUE(butil::ReadFileToString(
+        butil::FilePath(BackupPath(1)), &first_backup));
+    ASSERT_GT(first_backup.size(), (size_t)(100 * 1024));
+
+    // Occupy ".2" with a non-empty directory: shifting ".1" to ".2" fails
+    // with ENOTEMPTY while renaming the current file over ".1" would work.
+    ASSERT_EQ(0, mkdir(BackupPath(2).c_str(), 0755));
+    ASSERT_EQ(0, mkdir((BackupPath(2) + "/x").c_str(), 0755));
+
+    WriteLogs(1200, 1000);  // crosses the threshold, the shift fails
+    CloseLogFile();
+
+    // ".1" still holds the very same generation, rotation did not trade it
+    // for the current file.
+    std::string backup;
+    ASSERT_TRUE(butil::ReadFileToString(
+        butil::FilePath(BackupPath(1)), &backup));
+    ASSERT_EQ(first_backup, backup);
+    // The current file kept growing instead of losing a generation.
+    off_t size = 0;
+    ASSERT_TRUE(FileSize(_log_path, &size));
+    ASSERT_GT(size, 1L * 1024 * 1024);
+
+    // Once the obstacle is gone, the backed off retry shifts the preserved
+    // backup and rotation works again.
+    ASSERT_EQ(0, rmdir((BackupPath(2) + "/x").c_str()));
+    ASSERT_EQ(0, rmdir(BackupPath(2).c_str()));
+    WriteLogs(1200, 1000);
+    CloseLogFile();
+
+    ASSERT_TRUE(butil::ReadFileToString(
+        butil::FilePath(BackupPath(2)), &backup));
+    ASSERT_EQ(first_backup, backup);  // the preserved generation, shifted
+    ASSERT_TRUE(FileSize(BackupPath(1), &size));
+    ASSERT_GT(size, 1L * 1024 * 1024);
+}
+
+// --log_rotate_max_backups is only validated to be a positive int, so a
+// huge value must not turn into one rename() per index on every rotation,
+// all of them under the logging lock.
+TEST_F(LogRotationTest, huge_max_backups_shifts_only_existing_backups) {
+    FLAGS_log_rotate_size_mb = 1;
+    FLAGS_log_rotate_max_backups = 100000000;
+    InitLoggingToTempFile();
+
+    butil::Timer timer;
+    timer.start();
+    WriteLogs(2500, 1000);  // ~2.5MB, a couple of rotations
+    CloseLogFile();
+    timer.stop();
+
+    // The rotations above renamed a handful of files rather than 1e8 of
+    // them, which would stall the logging threads for minutes.
+    ASSERT_LT(timer.m_elapsed(), 10 * 1000);
+    ASSERT_TRUE(FileSize(BackupPath(1), nullptr));
+    ASSERT_TRUE(FileSize(BackupPath(2), nullptr));
+    ASSERT_FALSE(FileSize(BackupPath(3), nullptr));
+}
+
+struct SyncLogArgs {
+    int thread_index;
+    int log_count;
+    size_t log_size;
+};
+
+void* write_sync_logs(void* void_arg) {
+    auto args = (SyncLogArgs*)void_arg;
+    for (int i = 0; i < args->log_count; ++i) {
+        LOG(INFO) << butil::string_printf("<<T:%d:%d>>",
+                                          args->thread_index, i)
+                  << std::string(args->log_size, 'x');
+    }
+    return nullptr;
+}
+
+// Threads logging synchronously rotate the file between them without
+// losing or duplicating a log.
+TEST_F(LogRotationTest, concurrent_sync_log) {
+    FLAGS_log_rotate_size_mb = 1;
+    FLAGS_log_rotate_max_backups = 10;
+    InitLoggingToTempFile();
+
+    const int thread_num = 8;
+    const int logs_per_thread = 300;
+    SyncLogArgs args[thread_num];
+    pthread_t threads[thread_num];
+    for (int i = 0; i < thread_num; ++i) {
+        args[i].thread_index = i;
+        args[i].log_count = logs_per_thread;
+        args[i].log_size = 1000;
+        ASSERT_EQ(0, pthread_create(&threads[i], nullptr,
+                                    write_sync_logs, &args[i]));
+    }
+    for (int i = 0; i < thread_num; ++i) {
+        ASSERT_EQ(0, pthread_join(threads[i], nullptr));
+    }
+    CloseLogFile();
+    ASSERT_TRUE(FileSize(BackupPath(1), nullptr));  // rotation did happen
+
+    // Every single log must show up exactly once across the current file
+    // and the backups: none lost, none written twice, none torn apart by
+    // a rotation.
+    std::set<std::string> markers;
+    size_t marker_count = 0;
+    for (int i = 0; i <= FLAGS_log_rotate_max_backups + 1; ++i) {
+        std::string content;
+        if (!butil::ReadFileToString(butil::FilePath(
+                i == 0 ? _log_path : BackupPath(i)), &content)) {
+            continue;
+        }
+        size_t pos = 0;
+        while ((pos = content.find("<<T:", pos)) != std::string::npos) {
+            const size_t end = content.find(">>", pos);
+            ASSERT_NE(std::string::npos, end);
+            markers.insert(content.substr(pos, end - pos + 2));
+            ++marker_count;
+            pos = end + 2;
+        }
+    }
+    ASSERT_EQ((size_t)(thread_num * logs_per_thread), marker_count);
+    ASSERT_EQ((size_t)(thread_num * logs_per_thread), markers.size());
+}
+
 #if defined(BRPC_ENABLE_CPU_PROFILER) || defined(BAIDU_RPC_ENABLE_CPU_PROFILER)
 struct BAIDU_CACHELINE_ALIGNMENT PerfArgs {
     const std::string* log;