Add size based log rotation to butil/logging

docs/cn/streaming_log.md

@@ -259,6 +259,27 @@ CHECK(x > y);    // Check failed: x > y.
 
 和DLOG类似，你不应该在DCHECK的日志流中包含重要的副作用。
 
+## 日志切分
+
+当日志打向文件时（`LoggingSettings.logging_dest` 含 `LOG_TO_FILE`），可以用下面两个 gflag 打开按大小切分：
+
+| 名称 | 默认值 | 说明 |
+| ---- | ---- | ---- |
+| log_rotate_size_mb | 0 | 当前日志文件即将超过该大小（单位MB）时切分一次，0表示不切分。|
+| log_rotate_max_backups | 10 | 除当前文件外最多保留的历史文件个数，超出的旧文件在下一次切分时删除。|
+
+切分默认关闭，升级不会改变已有的文件名和文件内容。打开后，当前文件 `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`再重试，而不是每写一条日志都去关闭、重开、重命名一次文件。期间日志继续追加到当前文件，不会丢。如果发现文件比失败时更小，说明它已经被外部替换或截断，切分立刻恢复正常。
+
+> 不要在同一个日志文件上同时使用logrotate等外部切分工具。外部工具把文件改名之后，brpc下一次写入会重新创建原路径的文件，两边的切分规则会互相干扰，保留下来的历史文件数也不再受`log_rotate_max_backups`控制。二选一。
+
+两个flag都可以在运行时通过`/flags`修改。
+
+同步日志和异步日志（`--async_log`）都走同一个文件写入入口，所以对两者都生效。
+
+> **多进程共享同一个日志文件时不要打开切分**。POSIX下`LoggingLock`用的是进程内的mutex，并不能在进程之间互斥；而且切分是靠rename实现的，一个进程rename之后，其它进程的文件句柄仍然指向被改名的那个inode，日志会继续写到旧文件里。
+
 ## LogSink
 
 streaming log通过logging::SetLogSink修改日志刷入的目标，默认是屏幕。用户可以继承LogSink，实现自己的日志打印逻辑。我们默认提供了个LogSink实现：

docs/en/streaming_log.md

@@ -261,6 +261,27 @@ CHECK(x > y);    // Check failed: x > y.
 
 Like DLOG, you should NOT include important side effects inside DCHECK.
 
+## Log rotation
+
+When logs go to a file (`LoggingSettings.logging_dest` contains `LOG_TO_FILE`), size based rotation can be turned on with the following gflags:
+
+| Name | Default | Description |
+| ---- | ---- | ---- |
+| log_rotate_size_mb | 0 | Rotate the log file once it is about to grow beyond this size in megabytes. 0 means never rotate. |
+| log_rotate_max_backups | 10 | Max number of rotated files kept besides the current one. Files beyond the limit are removed by the next rotation. |
+
+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.
+
+> 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.
+
+Both flags are modifiable at run time via `/flags`.
+
+Synchronous and asynchronous logging (`--async_log`) share the same file writing path, so rotation works for both.
+
+> **Do not enable rotation when several processes share one log file.** On POSIX `LoggingLock` uses a process-local mutex which does not serialize different processes, and rotation is implemented with rename: after one process renames the file, the file handles of the other processes still refer to the renamed inode and their logs keep going to the old file.
+
 ## LogSink
 
 The default destination of streaming log is the screen. You can change it through `logging::SetLogSink`. Users can inherit LogSink and implement their own output logic. We provide an internal LogSink as an example:

src/butil/logging.cc

@@ -52,6 +52,7 @@ typedef HANDLE MutexHandle;
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
+#include <sys/stat.h>
 #include <unistd.h>
 #define MAX_PATH PATH_MAX
 typedef FILE* FileHandle;
@@ -169,6 +170,17 @@ DEFINE_int32(max_async_log_queue_size, 100000, "Max async log size. "
 DEFINE_int32(sleep_to_flush_async_log_s, 0,
              "If the value > 0, sleep before atexit to flush async log");
 
+DEFINE_int32(log_rotate_size_mb, 0,
+             "Rotate the log file once it is about to grow beyond this size "
+             "in megabytes. 0 means never rotate. Only takes effect when "
+             "logging to a file.");
+BUTIL_VALIDATE_GFLAG(log_rotate_size_mb, butil::NonNegativeInteger);
+
+DEFINE_int32(log_rotate_max_backups, 10,
+             "Max number of rotated log files kept besides the current one. "
+             "The oldest one is removed once the limit is reached.");
+BUTIL_VALIDATE_GFLAG(log_rotate_max_backups, butil::PositiveInteger);
+
 namespace {
 
 LoggingDestination logging_destination = LOG_DEFAULT;
@@ -189,6 +201,21 @@ PathString* log_file_name = nullptr;
 // this file is lazily opened and the handle may be nullptr
 FileHandle log_file = nullptr;
 
+// Number of bytes in the file referenced by `log_file'. Guarded by
+// LoggingLock just like `log_file' itself.
+int64_t log_file_size = 0;
+
+// Size of the log file when rotation last failed, -1 when the last attempt
+// succeeded. The size that triggered a failed rotation does not change by
+// itself, so an unconditional retry would close, reopen and rename the file
+// for every single log. Rotation is retried once per --log_rotate_size_mb of
+// new data instead. Guarded by LoggingLock.
+int64_t failed_rotation_size = -1;
+
+// Whether the failure above was already printed, so that a directory that
+// can not be written to does not flood stderr. Guarded by LoggingLock.
+bool rotation_failure_reported = false;
+
 // Should we pop up fatal debug messages in a dialog?
 bool show_error_dialogs = false;
 
@@ -399,12 +426,18 @@ bool InitializeLogFileHandle() {
             }
         }
         SetFilePointer(log_file, 0, 0, FILE_END);
+        LARGE_INTEGER file_size;
+        log_file_size = GetFileSizeEx(log_file, &file_size) ?
+            static_cast<int64_t>(file_size.QuadPart) : 0;
 #elif defined(OS_POSIX)
         log_file = fopen(log_file_name->c_str(), "a");
         if (log_file == nullptr) {
             fprintf(stderr, "Fail to fopen %s: %s", log_file_name->c_str(), berror());
             return false;
         }
+        struct stat st;
+        log_file_size = (0 == fstat(fileno(log_file), &st)) ?
+            static_cast<int64_t>(st.st_size) : 0;
 #endif
     }
 
@@ -425,6 +458,133 @@ void CloseLogFileUnlocked() {
 
     CloseFile(log_file);
     log_file = nullptr;
+    log_file_size = 0;
+}
+
+// ---------------------------- Log rotation ----------------------------
+// Rotation is size based and disabled by default. Once the current log file
+// is about to grow beyond --log_rotate_size_mb, it is renamed to
+// "<log_file_name>.1" and a fresh file is opened under the original name.
+// Existing backups are shifted down (".1" -> ".2" -> ...) beforehand and the
+// ones beyond --log_rotate_max_backups are removed, so that ".1" is always
+// the most recent backup.
+//
+// Sharing one log file between multiple processes is NOT supported together
+// with rotation: on POSIX LoggingLock only serializes the threads of a single
+// process, and after the rename the other processes would keep writing to the
+// renamed inode.
+
+// Return "<path>.<index>".
+PathString MakeBackupLogPath(const PathString& path, int index) {
+#if defined(OS_WIN)
+    wchar_t suffix[16];
+    swprintf(suffix, 16, L".%d", index);
+#else
+    char suffix[16];
+    snprintf(suffix, sizeof(suffix), ".%d", index);
+#endif
+    return path + suffix;
+}
+
+bool PathExists(const PathString& path) {
+#if defined(OS_WIN)
+    return GetFileAttributes(path.c_str()) != INVALID_FILE_ATTRIBUTES;
+#else
+    return ::access(path.c_str(), F_OK) == 0;
+#endif
+}
+
+bool RenameFilePath(const PathString& from, const PathString& to) {
+#if defined(OS_WIN)
+    return ::MoveFileEx(from.c_str(), to.c_str(),
+                        MOVEFILE_REPLACE_EXISTING) != 0;
+#elif defined(OS_NACL)
+    // Do nothing; rename() isn't supported on NaCl.
+    return false;
+#else
+    return ::rename(from.c_str(), to.c_str()) == 0;
+#endif
+}
+
+// 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;
+    // Close before renaming: on Windows an opened file cannot be renamed, and
+    // on POSIX the handle would keep pointing at the renamed inode.
+    CloseLogFileUnlocked();
+
+    const int max_backups = std::max(1, FLAGS_log_rotate_max_backups);
+    // Remove the oldest backup, and any left over from a previously larger
+    // --log_rotate_max_backups, so that lowering the flag at run time really
+    // lowers the number of files kept.
+    for (int i = max_backups; ; ++i) {
+        const PathString path = MakeBackupLogPath(*log_file_name, i);
+        if (!PathExists(path)) {
+            break;
+        }
+        DeleteFilePath(path);
+        if (PathExists(path)) {
+            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));
+    }
+    if (RenameFilePath(*log_file_name,
+                       MakeBackupLogPath(*log_file_name, 1))) {
+        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
+    }
+}
+
+// Rotate the log file if appending `incoming_size' bytes would grow it beyond
+// --log_rotate_size_mb. The caller must hold the logging lock.
+void MaybeRotateLogFileUnlocked(size_t incoming_size) {
+    const int64_t rotate_size =
+        (int64_t)FLAGS_log_rotate_size_mb * 1024 * 1024;
+    if (rotate_size <= 0) {  // rotation is disabled
+        return;
+    }
+    // Opening the file is what tells us how large it already is.
+    if (!InitializeLogFileHandle() || !log_file) {
+        return;
+    }
+    if (failed_rotation_size >= 0 && log_file_size < failed_rotation_size) {
+        // The file is smaller than it was when rotation failed, so it was
+        // replaced or truncated from the outside. Rotation may work again.
+        failed_rotation_size = -1;
+        rotation_failure_reported = false;
+    }
+    // Never rotate an empty file, otherwise a single log larger than
+    // `rotate_size' would rotate on every write and produce empty backups.
+    if (log_file_size == 0 ||
+        log_file_size + (int64_t)incoming_size <= rotate_size) {
+        return;
+    }
+    if (failed_rotation_size >= 0 &&
+        log_file_size < failed_rotation_size + rotate_size) {
+        return;  // backing off after a failed rotation
+    }
+    RotateLogFileUnlocked();
 }
 
 void Log2File(const std::string& log) {
@@ -437,14 +597,19 @@ void Log2File(const std::string& log) {
     // thread at the beginning of execution.
     LoggingLock::Init(LOCK_LOG_FILE, nullptr);
     LoggingLock logging_lock;
+    // Rotate before writing so that a single log is never split into two files.
+    MaybeRotateLogFileUnlocked(log.size());
     if (InitializeLogFileHandle()) {
 #if defined(OS_WIN)
         SetFilePointer(log_file, 0, 0, SEEK_END);
-        DWORD num_written;
+        DWORD num_written = 0;
         WriteFile(log_file, static_cast<const void*>(log.data()),
                   static_cast<DWORD>(log.size()), &num_written, nullptr);
+        log_file_size += num_written;
 #else
-        fwrite(log.data(), log.size(), 1, log_file);
+        if (fwrite(log.data(), log.size(), 1, log_file) == 1) {
+            log_file_size += (int64_t)log.size();
+        }
         fflush(log_file);
 #endif
     }
@@ -812,6 +977,9 @@ bool BaseInitLoggingImpl(const LoggingSettings& settings) {
     }
     if (settings.delete_old == DELETE_OLD_LOG_FILE)
         DeleteFilePath(*log_file_name);
+    // Give rotation another chance, the destination may have changed.
+    failed_rotation_size = -1;
+    rotation_failure_reported = false;
 
     return InitializeLogFileHandle();
 }