feat(logging): Use timestamp instead of index in log files and limit …

…file size and count

src/utils/simple_logger.cpp

@@ -26,27 +26,41 @@
 
 #include "utils/simple_logger.h"
 
+#include <cstdint>
+#include <errno.h>
 // IWYU pragma: no_include <ext/alloc_traits.h>
 #include <fmt/core.h>
 #include <fmt/printf.h>
-#include <cstdint>
+#include <sys/stat.h>
+#include <algorithm>
+#include <ctime>
 #include <functional>
 #include <memory>
-#include <ostream>
+#include <type_traits>
+#include <utility>
 #include <vector>
 
 #include "absl/strings/string_view.h"
 #include "runtime/api_layer1.h"
 #include "utils/command_manager.h"
+#include "utils/errors.h"
 #include "utils/fail_point.h"
 #include "utils/filesystem.h"
 #include "utils/flags.h"
 #include "utils/fmt_logging.h"
 #include "utils/ports.h"
 #include "utils/process_utils.h"
+#include "utils/safe_strerror_posix.h"
 #include "utils/string_conv.h"
 #include "utils/time_utils.h"
 
+DSN_DEFINE_uint64(tools.simple_logger,
+                  max_log_file_bytes,
+                  64 * 1024 * 1024,
+                  "The maximum bytes of a log file. A new log file will be created if the current "
+                  "log file exceeds this size.");
+DSN_DEFINE_validator(max_log_file_bytes, [](int32_t value) -> bool { return value > 0; });
+
 DSN_DEFINE_bool(tools.simple_logger, fast_flush, false, "Whether to flush logs immediately");
 DSN_DEFINE_bool(tools.simple_logger,
                 short_header,
@@ -192,43 +206,13 @@ void screen_logger::flush() { ::fflush(stdout); }
 simple_logger::simple_logger(const char *log_dir)
     : _log_dir(std::string(log_dir)),
       _log(nullptr),
-      // we assume all valid entries are positive
-      _start_index(0),
-      _index(1),
-      _lines(0),
+      _file_bytes(0),
       _stderr_start_level(enum_from_string(FLAGS_stderr_start_level, LOG_LEVEL_INVALID))
 {
-    // check existing log files
-    std::vector<std::string> sub_list;
-    CHECK(dsn::utils::filesystem::get_subfiles(_log_dir, sub_list, false),
-          "Fail to get subfiles in {}",
-          _log_dir);
-    for (auto &fpath : sub_list) {
-        auto &&name = dsn::utils::filesystem::get_file_name(fpath);
-        if (name.length() <= 8 || name.substr(0, 4) != "log.") {
-            continue;
-        }
-
-        int index;
-        if (1 != sscanf(name.c_str(), "log.%d.txt", &index) || index <= 0) {
-            continue;
-        }
-
-        if (index > _index) {
-            _index = index;
-        }
-
-        if (_start_index == 0 || index < _start_index) {
-            _start_index = index;
-        }
-    }
-    sub_list.clear();
-
-    if (_start_index == 0) {
-        _start_index = _index;
-    } else {
-        ++_index;
-    }
+    // Use 'role_name' if it is specified, otherwise use 'base_name'.
+    const std::string symlink_name("log");
+    _file_name_prefix = fmt::format("{}.", symlink_name);
+    _symlink_path = utils::filesystem::path_combine(_log_dir, symlink_name);
 
     create_log_file();
 
@@ -273,22 +257,94 @@ void simple_logger::create_log_file()
         _log = nullptr;
     }
 
-    _lines = 0;
-
-    std::stringstream str;
-    str << _log_dir << "/log." << _index++ << ".txt";
-    _log = ::fopen(str.str().c_str(), "w+");
-
-    // TODO: move gc out of criticial path
-    while (_index - _start_index > FLAGS_max_number_of_log_files_on_disk) {
-        std::stringstream str2;
-        str2 << "log." << _start_index++ << ".txt";
-        auto dp = utils::filesystem::path_combine(_log_dir, str2.str());
-        if (utils::filesystem::file_exists(dp)) {
-            if (::remove(dp.c_str()) != 0) {
-                // if remove failed, just print log and ignore it.
-                printf("Failed to remove garbage log file %s\n", dp.c_str());
-            }
+    // Reset the file size.
+    _file_bytes = 0;
+
+    // Open the new log file.
+    uint64_t ts = dsn::utils::get_current_physical_time_ns();
+    std::string time_str;
+    ::dsn::utils::time_ms_to_sequent_string(ts / 1000000, time_str);
+    const std::string file_name(fmt::format("{}{}", _file_name_prefix, time_str));
+    const std::string path(utils::filesystem::path_combine(_log_dir, file_name));
+    _log = ::fopen(path.c_str(), "w+");
+    CHECK_NOTNULL(_log, "Failed to fopen {}: {}", path, dsn::utils::safe_strerror(errno));
+
+    // Unlink the latest log file.
+    if (::unlink(_symlink_path.c_str()) != 0) {
+        if (errno != ENOENT) {
+            fmt::print(stderr,
+                       "Failed to unlink {}: {}\n",
+                       _symlink_path,
+                       dsn::utils::safe_strerror(errno));
+        }
+    }
+
+    // Create a new symlink to the newly created log file.
+    if (::symlink(file_name.c_str(), _symlink_path.c_str()) != 0) {
+        fmt::print(stderr,
+                   "Failed to symlink {} as {}: {}\n",
+                   file_name,
+                   _symlink_path,
+                   dsn::utils::safe_strerror(errno));
+    }
+
+    // Remove redundant log files.
+    remove_redundant_files();
+}
+
+void simple_logger::remove_redundant_files()
+{
+    // Collect log files.
+    const auto file_path_pattern =
+        fmt::format("{}*", utils::filesystem::path_combine(_log_dir, _file_name_prefix));
+    std::vector<std::string> matching_files;
+    const auto es = dsn::utils::filesystem::glob(file_path_pattern, matching_files);
+    if (!es) {
+        fmt::print(
+            stderr, "{}: Failed to glob '{}', error \n", es.description(), file_path_pattern);
+        return;
+    }
+
+    // Skip if the number of log files is not exceeded.
+    auto max_matches = static_cast<size_t>(FLAGS_max_number_of_log_files_on_disk);
+    if (matching_files.size() <= max_matches) {
+        return;
+    }
+
+    // Collect mtimes of log files.
+    std::vector<std::pair<time_t, std::string>> matching_file_mtimes;
+    for (auto &matching_file_path : matching_files) {
+        struct stat s;
+        if (::stat(matching_file_path.c_str(), &s) != 0) {
+            fmt::print(stderr,
+                       "Failed to stat {}: {}\n",
+                       matching_file_path,
+                       dsn::utils::safe_strerror(errno));
+            continue;
+        }
+
+#ifdef __APPLE__
+        int64_t mtime = s.st_mtimespec.tv_sec * 1000000 + s.st_mtimespec.tv_nsec / 1000;
+#else
+        int64_t mtime = s.st_mtim.tv_sec * 1000000 + s.st_mtim.tv_nsec / 1000;
+#endif
+        matching_file_mtimes.emplace_back(mtime, std::move(matching_file_path));
+    }
+
+    // Use mtime to determine which matching files to delete. This could
+    // potentially be ambiguous, depending on the resolution of last-modified
+    // timestamp in the filesystem, but that is part of the contract.
+    std::sort(matching_file_mtimes.begin(), matching_file_mtimes.end());
+    matching_file_mtimes.resize(matching_file_mtimes.size() - max_matches);
+
+    // Remove redundant log files.
+    for (const auto & [ _, matching_file ] : matching_file_mtimes) {
+        if (::remove(matching_file.c_str()) != 0) {
+            // If remove failed, just print log and ignore it.
+            fmt::print(stderr,
+                       "Failed to remove redundant log file {}: {}\n",
+                       matching_file,
+                       dsn::utils::safe_strerror(errno));
         }
     }
 }
@@ -310,21 +366,21 @@ void simple_logger::flush()
 
 void simple_logger::print_header(log_level_t log_level)
 {
-    ::dsn::tools::print_header(_log, _stderr_start_level, log_level);
+    add_bytes_if_valid(::dsn::tools::print_header(_log, _stderr_start_level, log_level));
 }
 
 void simple_logger::print_long_header(const char *file,
                                       const char *function,
                                       const int line,
                                       log_level_t log_level)
 {
-    ::dsn::tools::print_long_header(
-        _log, file, function, line, FLAGS_short_header, _stderr_start_level, log_level);
+    add_bytes_if_valid(::dsn::tools::print_long_header(
+        _log, file, function, line, FLAGS_short_header, _stderr_start_level, log_level));
 }
 
 void simple_logger::print_body(const char *body, log_level_t log_level)
 {
-    ::dsn::tools::print_body(_log, body, _stderr_start_level, log_level);
+    add_bytes_if_valid(::dsn::tools::print_body(_log, body, _stderr_start_level, log_level));
 }
 
 void simple_logger::log(
@@ -342,7 +398,7 @@ void simple_logger::log(
 
     process_fatal_log(log_level);
 
-    if (++_lines >= 200000) {
+    if (_file_bytes >= FLAGS_max_log_file_bytes) {
         create_log_file();
     }
 }

src/utils/simple_logger.h

@@ -26,11 +26,13 @@
 
 #pragma once
 
+#include <cstdint>
 #include <cstdio>
 #include <string>
 
 #include "utils/api_utilities.h"
 #include "utils/logging_provider.h"
+#include "utils/ports.h"
 #include "utils/synchronize.h"
 
 namespace dsn {
@@ -91,17 +93,30 @@ class simple_logger : public logging_provider
                            log_level_t log_level);
     void print_body(const char *body, log_level_t log_level);
 
+    inline void add_bytes_if_valid(int bytes)
+    {
+        if (dsn_likely(bytes > 0)) {
+            _file_bytes += static_cast<uint64_t>(bytes);
+        }
+    }
+
     void create_log_file();
+    void remove_redundant_files();
 
 private:
     ::dsn::utils::ex_lock _lock; // use recursive lock to avoid dead lock when flush() is called
                                  // in signal handler if cored for bad logging format reason.
     // The directory to store log files.
     const std::string _log_dir;
+    // The path of the symlink to the latest log file.
+    std::string _symlink_path;
+    // The prefix of the log file names. The actual log files are prefixed by '_file_name_prefix'
+    // and postfixed by timestamp.
+    std::string _file_name_prefix;
+    // The current log file descriptor.
     FILE *_log;
-    int _start_index;
-    int _index;
-    int _lines;
+    // The byte size of the current log file.
+    uint64_t _file_bytes;
     const log_level_t _stderr_start_level;
 };
 } // namespace tools