diff --git a/docs/cn/streaming_log.md b/docs/cn/streaming_log.md index cfda269f4d..50c1e0df6b 100644 --- a/docs/cn/streaming_log.md +++ b/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实现： diff --git a/docs/en/streaming_log.md b/docs/en/streaming_log.md index 0412118df7..a35eac75b7 100644 --- a/docs/en/streaming_log.md +++ b/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: diff --git a/src/butil/logging.cc b/src/butil/logging.cc index b389b18f13..b62558e42e 100644 --- a/src/butil/logging.cc +++ b/src/butil/logging.cc @@ -52,6 +52,7 @@ typedef HANDLE MutexHandle; #include #include #include +#include #include #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. " + "Files beyond the limit are removed by the next rotation."); +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(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(st.st_size) : 0; #endif } @@ -425,6 +458,157 @@ 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 +// ".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. Every rotation also removes the backups 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. +// +// 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. +// +// 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 +// replaced or truncated from the outside, and rotation resumes immediately. +// +// 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 ".". +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 ".1" and shift the older +// backups down by one. The caller must hold the logging lock. +void RotateLogFileUnlocked() { + if (!log_file_name) { + return; + } + 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. + CloseLogFileUnlocked(); + failed_rotation_size = -1; + rotation_failure_reported = false; + 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 +621,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(log.data()), static_cast(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 +1001,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(); } diff --git a/test/logging_unittest.cc b/test/logging_unittest.cc index c1fea6ef19..20e1ce6762 100644 --- a/test/logging_unittest.cc +++ b/test/logging_unittest.cc @@ -9,6 +9,8 @@ #include "butil/popen.h" #include #include +#include +#include #if !BRPC_WITH_GLOG @@ -19,6 +21,8 @@ DECLARE_bool(log_func_name); DECLARE_bool(async_log); DECLARE_bool(async_log_in_background_always); DECLARE_int32(max_async_log_queue_size); +DECLARE_int32(log_rotate_size_mb); +DECLARE_int32(log_rotate_max_backups); namespace { @@ -540,6 +544,340 @@ TEST_F(LoggingTest, async_log) { FLAGS_async_log = saved_async_log; } +static bool FileSize(const std::string& path, off_t* size) { + struct stat st; + if (stat(path.c_str(), &st) != 0) { + return false; + } + if (size) { + *size = st.st_size; + } + return true; +} + +class LogRotationTest : public LoggingTest { +public: + void SetUp() override { + LoggingTest::SetUp(); + _saved_async_log = FLAGS_async_log; + _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(); + } + + 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; + LoggingTest::TearDown(); + } + +protected: + // Point the logging framework at `_log_path' and start from an empty file. + void InitLoggingToTempFile() { + LoggingSettings settings; + settings.logging_dest = LOG_TO_FILE; + settings.log_file = _log_path.c_str(); + settings.delete_old = DELETE_OLD_LOG_FILE; + ASSERT_TRUE(InitLogging(settings)); + } + + std::string BackupPath(int index) const { + return _log_path + butil::string_printf(".%d", index); + } + + // 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) { + const std::string content(size, 'x'); + for (int i = 0; i < count; ++i) { + LOG(INFO) << content; + } + } + + std::string _log_path; + +private: + butil::TempFile _temp_file; + bool _saved_async_log{false}; + int _saved_rotate_size_mb{0}; + int _saved_max_backups{0}; +}; + +TEST_F(LogRotationTest, disabled_by_default) { + FLAGS_log_rotate_size_mb = 0; + InitLoggingToTempFile(); + + WriteLogs(2000, 1000); // ~2MB + CloseLogFile(); + + off_t size = 0; + ASSERT_TRUE(FileSize(_log_path, &size)); + ASSERT_GT(size, 1L * 1024 * 1024); + ASSERT_FALSE(FileSize(BackupPath(1), nullptr)); +} + +TEST_F(LogRotationTest, rotate_and_prune) { + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 2; + InitLoggingToTempFile(); + + WriteLogs(3000, 1000); // ~3MB, rotates 3 times + CloseLogFile(); + + const off_t rotate_size = 1L * 1024 * 1024; + off_t size = 0; + // The current file was restarted by the last rotation. + ASSERT_TRUE(FileSize(_log_path, &size)); + ASSERT_LE(size, rotate_size); + // ".1" is the most recent backup, older ones are pruned. + ASSERT_TRUE(FileSize(BackupPath(1), &size)); + ASSERT_GT(size, 0); + ASSERT_LE(size, rotate_size); + ASSERT_TRUE(FileSize(BackupPath(2), &size)); + ASSERT_GT(size, 0); + ASSERT_LE(size, rotate_size); + ASSERT_FALSE(FileSize(BackupPath(3), nullptr)); +} + +TEST_F(LogRotationTest, keep_one_backup) { + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 1; + InitLoggingToTempFile(); + + WriteLogs(3000, 1000); + CloseLogFile(); + + ASSERT_TRUE(FileSize(BackupPath(1), nullptr)); + ASSERT_FALSE(FileSize(BackupPath(2), nullptr)); +} + +// A log bigger than the threshold is written as a whole rather than being +// split or triggering a rotation on every single write. Only the number of +// files holding a whole oversized log is checked, so that logs written by the +// rest of the process cannot make the test flaky. +TEST_F(LogRotationTest, log_larger_than_rotate_size) { + FLAGS_log_rotate_size_mb = 1; + // High enough that none of the files below can be pruned. + FLAGS_log_rotate_max_backups = 10; + InitLoggingToTempFile(); + + const size_t log_size = 2 * 1024 * 1024; + WriteLogs(3, log_size); + CloseLogFile(); + + int whole_logs = 0; + off_t size = 0; + if (FileSize(_log_path, &size) && size >= (off_t)log_size) { + ++whole_logs; + } + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + if (!FileSize(BackupPath(i), &size)) { + continue; + } + // A rotation never leaves an empty file behind. + ASSERT_GT(size, 0) << BackupPath(i); + if (size >= (off_t)log_size) { + ++whole_logs; + } + } + ASSERT_EQ(3, whole_logs); +} + +// The log file is opened with "a", so the size a restarted process starts +// from must come from the file itself instead of being counted from zero. +TEST_F(LogRotationTest, size_of_existing_file_is_taken_into_account) { + // Grow the file beyond the future threshold while rotation is still off. + FLAGS_log_rotate_size_mb = 0; + FLAGS_log_rotate_max_backups = 2; + InitLoggingToTempFile(); + WriteLogs(1500, 1000); + CloseLogFile(); // as if the process exited here + + off_t before = 0; + ASSERT_TRUE(FileSize(_log_path, &before)); + ASSERT_GT(before, 1L * 1024 * 1024); + ASSERT_FALSE(FileSize(BackupPath(1), nullptr)); + + // Turn rotation on and write a single log. The file is reopened in append + // mode, so this can only rotate if the size was read from the file rather + // than counted from zero. + FLAGS_log_rotate_size_mb = 1; + WriteLogs(1, 10); + CloseLogFile(); + + off_t rotated = 0; + ASSERT_TRUE(FileSize(BackupPath(1), &rotated)); + ASSERT_GE(rotated, before); + off_t current = 0; + ASSERT_TRUE(FileSize(_log_path, ¤t)); + ASSERT_LT(current, before); +} + +TEST_F(LogRotationTest, async_log) { + FLAGS_async_log = true; + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 2; + InitLoggingToTempFile(); + + WriteLogs(3000, 1000); + // The background thread writes the logs, wait for the rotations to show up + // instead of sleeping for a fixed amount of time. + for (int i = 0; i < 600 && !FileSize(BackupPath(2), nullptr); ++i) { + usleep(100 * 1000); + } + // Drain the rest of the queue so that no leftover log is written into the + // file of whichever test runs next. + off_t last_size = -1; + off_t current_size = 0; + for (int i = 0; i < 100 && last_size != current_size; ++i) { + last_size = current_size; + usleep(100 * 1000); + FileSize(_log_path, ¤t_size); + } + FLAGS_async_log = false; + CloseLogFile(); + + off_t size = 0; + ASSERT_TRUE(FileSize(BackupPath(1), &size)); + ASSERT_GT(size, 0); + ASSERT_LE(size, 1L * 1024 * 1024); + ASSERT_TRUE(FileSize(BackupPath(2), nullptr)); + ASSERT_FALSE(FileSize(BackupPath(3), nullptr)); +} + +// Lowering --log_rotate_max_backups at run time must also remove the files +// left over from the previous, larger value. +TEST_F(LogRotationTest, lowering_max_backups_removes_leftovers) { + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 5; + InitLoggingToTempFile(); + + WriteLogs(6000, 1000); // fills every backup slot + ASSERT_TRUE(FileSize(BackupPath(5), nullptr)); + + FLAGS_log_rotate_max_backups = 2; + WriteLogs(2000, 1000); // rotates at least once with the new value + CloseLogFile(); + + ASSERT_TRUE(FileSize(BackupPath(1), nullptr)); + ASSERT_TRUE(FileSize(BackupPath(2), nullptr)); + ASSERT_FALSE(FileSize(BackupPath(3), nullptr)); + ASSERT_FALSE(FileSize(BackupPath(4), nullptr)); + ASSERT_FALSE(FileSize(BackupPath(5), nullptr)); +} + +// An external tool taking the log file away is not a rotation failure. The +// next write starts a fresh file and the existing backups must be left alone +// rather than shifted down for nothing. +TEST_F(LogRotationTest, external_rename_does_not_consume_a_backup) { + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 5; + InitLoggingToTempFile(); + + WriteLogs(2500, 1000); // rotates a couple of times + off_t first_backup = 0; + ASSERT_TRUE(FileSize(BackupPath(1), &first_backup)); + int backups_before = 0; + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + if (FileSize(BackupPath(i), nullptr)) { + ++backups_before; + } + } + + // Take the file away the way an external log rotator would, then log + // enough that a rotation would otherwise have been due. + const std::string moved = _log_path + ".moved"; + ASSERT_EQ(0, rename(_log_path.c_str(), moved.c_str())); + WriteLogs(800, 1000); + CloseLogFile(); + + off_t size = 0; + ASSERT_TRUE(FileSize(BackupPath(1), &size)); + ASSERT_EQ(first_backup, size); // ".1" was not shifted away + int backups_after = 0; + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + if (FileSize(BackupPath(i), nullptr)) { + ++backups_after; + } + } + ASSERT_EQ(backups_before, backups_after); + // Logging went on under the original name. + ASSERT_TRUE(FileSize(_log_path, nullptr)); + unlink(moved.c_str()); +} + +// When the rename can not succeed, rotation must back off instead of closing +// and reopening the file on every single log. +TEST_F(LogRotationTest, backs_off_when_rotation_keeps_failing) { + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 2; + InitLoggingToTempFile(); + + // Occupy every backup slot with a non-empty directory, which makes both + // the shift and the final rename fail with EISDIR/ENOTEMPTY. + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + ASSERT_EQ(0, mkdir(BackupPath(i).c_str(), 0755)); + ASSERT_EQ(0, mkdir((BackupPath(i) + "/x").c_str(), 0755)); + } + + WriteLogs(1500, 1000); // ~1.5MB, crosses the threshold + CloseLogFile(); + + // Nothing was dropped, the logs kept being appended to the current file. + off_t size = 0; + ASSERT_TRUE(FileSize(_log_path, &size)); + ASSERT_GT(size, 1L * 1024 * 1024); + + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + ASSERT_EQ(0, rmdir((BackupPath(i) + "/x").c_str())); + ASSERT_EQ(0, rmdir(BackupPath(i).c_str())); + } + // InitLogging() clears the back off for the tests that follow. + InitLoggingToTempFile(); +} + +// An external tool renaming the log file away must not disable rotation for +// good: the file it is reopened on starts empty, which is the signal that +// rotation can be attempted again. +TEST_F(LogRotationTest, recovers_after_the_log_file_is_replaced) { + FLAGS_log_rotate_size_mb = 1; + FLAGS_log_rotate_max_backups = 2; + InitLoggingToTempFile(); + + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + ASSERT_EQ(0, mkdir(BackupPath(i).c_str(), 0755)); + ASSERT_EQ(0, mkdir((BackupPath(i) + "/x").c_str(), 0755)); + } + WriteLogs(1500, 1000); // rotation fails and backs off + off_t size = 0; + ASSERT_TRUE(FileSize(_log_path, &size)); + ASSERT_GT(size, 1L * 1024 * 1024); + + for (int i = 1; i <= FLAGS_log_rotate_max_backups; ++i) { + ASSERT_EQ(0, rmdir((BackupPath(i) + "/x").c_str())); + ASSERT_EQ(0, rmdir(BackupPath(i).c_str())); + } + // Take the file away the way an external log rotator would. + CloseLogFile(); + const std::string moved = _log_path + ".moved"; + ASSERT_EQ(0, rename(_log_path.c_str(), moved.c_str())); + + WriteLogs(1500, 1000); + CloseLogFile(); + + // Rotation works again without InitLogging() having been called. + ASSERT_TRUE(FileSize(BackupPath(1), &size)); + ASSERT_GT(size, 0); + ASSERT_LE(size, 1L * 1024 * 1024); + unlink(moved.c_str()); +} + #if defined(BRPC_ENABLE_CPU_PROFILER) || defined(BAIDU_RPC_ENABLE_CPU_PROFILER) struct BAIDU_CACHELINE_ALIGNMENT PerfArgs { const std::string* log;