Sherlock0203 commented on code in PR #3687:
URL: https://github.com/apache/brpc/pull/3687#discussion_r4511362342
##########
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:
Reproduced it: after padding the checkout path until a log entry reached 1183
bytes, the third batch rotated twice, the max_backups=2 cleanup pruned
first_backup, and the content assertion failed — same failure you saw. The
tests
no longer count logs. The new helpers (WriteLogsUntilRotation,
WriteLogsUntilLargerThan, WriteLogsUntilFileExists) watch the file itself — a
size drop, growth past a threshold, a path showing up — so they don't care
how
many bytes a header takes. shift_failure_keeps_the_newest_backup and
external_rename_does_not_consume_a_backup were converted, and while auditing
the
rest for the same trap I found one more instance:
huge_max_backups_shifts_only_
existing_backups relied on headers staying under 259 bytes for its ".3 must
not
exist" check, so it now writes until .2 shows up instead. The whole rotation
suite passes from a checkout path about 50 characters longer than the one I
usually build in.
--
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]
