chenBright commented on code in PR #3687:
URL: https://github.com/apache/brpc/pull/3687#discussion_r4479955348
##########
src/butil/logging.cc:
##########
@@ -425,6 +458,210 @@ 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. 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. 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, 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
+// 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
+}
+
+// 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. 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 = size_before_rotation;
+ return;
+ }
+ // 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
+ }
+ }
+ // 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;
+ }
+ }
+ 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;
Review Comment:
After the original file is moved here, the next `InitializeLogFileHandle()`
creates a new file with `fopen(..., "a")` using the process's `umask`, without
preserving the original log permissions. When an existing `0600` file is opened
in append mode with `umask=0022`, the current file becomes `0644` after the
first rotation, making subsequent logs that were previously private readable by
other users. I reproduced this locally; the control with rotation disabled
remained `0600`. Please preserve the original file permissions and apply them
when creating the replacement file to prevent rotation from broadening access.
##########
src/butil/logging.cc:
##########
@@ -425,6 +458,210 @@ 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. 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. 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, 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
+// 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
+}
+
+// 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. 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 = size_before_rotation;
+ return;
+ }
+ // Close before renaming: on Windows an opened file cannot be renamed, and
+ // on POSIX the handle would keep pointing at the renamed inode.
+ CloseLogFileUnlocked();
Review Comment:
On POSIX, please keep the old handle open until the replacement file has
been opened successfully. If privileges are dropped or permissions are
tightened after initialization, the old handle may still be writable even
though the path can no longer be reopened. After it is closed early here,
`Log2File()` can only discard logs when `fopen` fails, even if the rename fails
and the code enters backoff. Locally, after opening the file, I changed the
file to `0400` and the directory to `0500` and confirmed that both the
triggering record and the next record were lost. With the same control and
rotation disabled, both records were written.
##########
test/logging_unittest.cc:
##########
@@ -540,6 +547,572 @@ 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_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 {
+ CloseLogFile();
+ 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
+ // 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();
+ }
+
+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);
+ }
+
+ // 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) {
+ 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};
+ bool _saved_async_log_in_background_always{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());
+}
+
+// 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
Review Comment:
This fixed batch of `WriteLogs(1200, 1000)` triggers two successful
rotations when the source path is longer. The original backup is moved to `.2`
and then normally removed, causing the next content assertion to fail. In a
CMake build with no source changes for this run, each log entry was 1,183 bytes
including the header, and this test consistently failed at line 993 even when
run alone; a control with only the log source filename shortened passed. Please
stop writing once the first successful rotation is detected, or fix the log
header and control the test data based on the actual byte count.
##########
src/butil/logging.cc:
##########
@@ -425,6 +458,210 @@ 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. 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. 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, 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
+// 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
+}
+
+// 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. 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 = size_before_rotation;
+ return;
+ }
+ // 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;
+ }
Review Comment:
The first missing number cannot be treated as the end of all backups: an
internal rotation failure can create gaps without any external splitting tool.
For example, with a retention count of 4, if `.3→.4` and `.2→.3` succeed but
`.1→.2` fails, `.2` will be missing. After resolving the cause of the failure
and changing the limit to 1, cleanup deletes `.1` and stops early at `.2`,
leaving `.3` and `.4` permanently. Locally, three backups remained after two
consecutive successful rotations. Please clean up all backups beyond the limit
based on the files that actually exist, or restore contiguous numbering after a
failure.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
