From 5cb860917d80152e180e24d755fa1cb494dcf3bf Mon Sep 17 00:00:00 2001 From: Sergiu Deitsch Date: Fri, 5 Jan 2024 19:24:09 +0100 Subject: [PATCH] feat(logger): use chrono --- src/glog/logging.h | 32 ++++++---- src/logging.cc | 129 +++++++++++++++++++++++----------------- src/logging_unittest.cc | 15 +++-- 3 files changed, 106 insertions(+), 70 deletions(-) diff --git a/src/glog/logging.h b/src/glog/logging.h index 214af70c2..5d5e832b4 100644 --- a/src/glog/logging.h +++ b/src/glog/logging.h @@ -83,9 +83,11 @@ struct GLOG_EXPORT LogMessageTime { LogMessageTime(); explicit LogMessageTime(std::chrono::system_clock::time_point now); - const time_t& timestamp() const { return timestamp_; } + const std::chrono::system_clock::time_point& timestamp() const noexcept { + return timestamp_; + } const int& sec() const { return time_struct_.tm_sec; } - const int32_t& usec() const { return usecs_; } + long usec() const { return usecs_.count(); } const int&(min)() const { return time_struct_.tm_min; } const int& hour() const { return time_struct_.tm_hour; } const int& day() const { return time_struct_.tm_mday; } @@ -94,18 +96,19 @@ struct GLOG_EXPORT LogMessageTime { const int& dayOfWeek() const { return time_struct_.tm_wday; } const int& dayInYear() const { return time_struct_.tm_yday; } const int& dst() const { return time_struct_.tm_isdst; } - const long int& gmtoff() const { return gmtoffset_; } + const std::chrono::hours& gmtoff() const { return gmtoffset_; } const std::tm& tm() const { return time_struct_; } private: void init(const std::tm& t, std::time_t timestamp, std::chrono::system_clock::time_point now); - std::tm time_struct_; // Time of creation of LogMessage - time_t timestamp_; // Time of creation of LogMessage in seconds - int32_t usecs_; // Time of creation of LogMessage - microseconds part - long int gmtoffset_; + std::tm time_struct_{}; // Time of creation of LogMessage + std::chrono::system_clock::time_point + timestamp_; // Time of creation of LogMessage in seconds + std::chrono::microseconds usecs_; + std::chrono::hours gmtoffset_; - void CalcGmtOffset(); + void CalcGmtOffset(std::time_t t); }; struct LogMessageInfo { @@ -347,7 +350,7 @@ typedef void (*CustomPrefixCallback)(std::ostream& s, const LogMessageInfo& l, // timestamps from different machines. // Log messages below the GOOGLE_STRIP_LOG level will be compiled away for -// security reasons. See LOG(severtiy) below. +// security reasons. See LOG(severity) below. // A few definitions of macros that don't generate much code. Since // LOG(INFO) and its ilk are used all over our code, it's @@ -1567,8 +1570,15 @@ class GLOG_EXPORT Logger { // appropriate by the higher level logging facility. For example, // textual log messages already contain timestamps, and the // file:linenumber header. - virtual void Write(bool force_flush, time_t timestamp, const char* message, - size_t message_len) = 0; + [[deprecated( + "Logger::Write accepting a std::time_t timestamp is provided for " + "compatibility purposes only. New code should implement the " + "std::chrono::system_clock::time_point overload.")]] virtual void + Write(bool force_flush, time_t timestamp, const char* message, + size_t message_len); + virtual void Write(bool force_flush, + const std::chrono::system_clock::time_point& timestamp, + const char* message, size_t message_len); // Flush any buffered messages virtual void Flush() = 0; diff --git a/src/logging.cc b/src/logging.cc index 0ce8478f9..849504f2f 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -342,6 +342,28 @@ static bool SendEmailInternal(const char* dest, const char* subject, base::Logger::~Logger() = default; +void base::Logger::Write(bool /*force_flush*/, time_t /*timestamp*/, + const char* /*message*/, size_t /*message_len*/) {} + +void base::Logger::Write(bool force_flush, + const std::chrono::system_clock::time_point& timestamp, + const char* message, size_t message_len) { +#if defined(__GNUG__) +# pragma GCC diagnostic push +# pragma GCC diagnostic ignored "-Wdeprecated-declarations" +#elif defined(_MSC_VER) +# pragma warning(push) +# pragma warning(disable : 4996) +#endif // __GNUG__ + return Write(force_flush, std::chrono::system_clock::to_time_t(timestamp), + message, message_len); +#if defined(__GNUG__) +# pragma GCC diagnostic pop +#elif defined(_MSC_VER) +# pragma warning(pop) +#endif // __GNUG__ +} + namespace { constexpr std::intmax_t kSecondsInDay = 60 * 60 * 24; @@ -359,7 +381,8 @@ class LogFileObject : public base::Logger { ~LogFileObject() override; void Write(bool force_flush, // Should we force a flush here? - time_t timestamp, // Timestamp for this entry + const std::chrono::system_clock::time_point& + timestamp, // Timestamp for this entry const char* message, size_t message_len) override; // Configuration options @@ -506,13 +529,17 @@ class LogDestination { size_t len); // Take a log message of a particular severity and log it to a file // iff the base filename is not "" (which means "don't log to me") - static void MaybeLogToLogfile(LogSeverity severity, time_t timestamp, - const char* message, size_t len); + static void MaybeLogToLogfile( + LogSeverity severity, + const std::chrono::system_clock::time_point& timestamp, + const char* message, size_t len); // Take a log message of a particular severity and log it to the file // for that severity and also for all files with severity less than // this severity. - static void LogToAllLogfiles(LogSeverity severity, time_t timestamp, - const char* message, size_t len); + static void LogToAllLogfiles( + LogSeverity severity, + const std::chrono::system_clock::time_point& timestamp, + const char* message, size_t len); // Send logging info to all registered sinks. static void LogToSinks(LogSeverity severity, const char* full_filename, @@ -804,17 +831,19 @@ inline void LogDestination::MaybeLogToEmail(LogSeverity severity, } } -inline void LogDestination::MaybeLogToLogfile(LogSeverity severity, - time_t timestamp, - const char* message, size_t len) { +inline void LogDestination::MaybeLogToLogfile( + LogSeverity severity, + const std::chrono::system_clock::time_point& timestamp, const char* message, + size_t len) { const bool should_flush = severity > FLAGS_logbuflevel; LogDestination* destination = log_destination(severity); destination->logger_->Write(should_flush, timestamp, message, len); } -inline void LogDestination::LogToAllLogfiles(LogSeverity severity, - time_t timestamp, - const char* message, size_t len) { +inline void LogDestination::LogToAllLogfiles( + LogSeverity severity, + const std::chrono::system_clock::time_point& timestamp, const char* message, + size_t len) { if (FLAGS_logtostdout) { // global flag: never log to file ColoredWriteToStdout(severity, message, len); } else if (FLAGS_logtostderr) { // global flag: never log to file @@ -1077,8 +1106,9 @@ bool LogFileObject::CreateLogfile(const string& time_pid_string) { return true; // Everything worked } -void LogFileObject::Write(bool force_flush, time_t timestamp, - const char* message, size_t message_len) { +void LogFileObject::Write( + bool force_flush, const std::chrono::system_clock::time_point& timestamp, + const char* message, size_t message_len) { std::lock_guard l{mutex_}; // We don't log if the base_name_ is "" (which means "don't write") @@ -1086,9 +1116,7 @@ void LogFileObject::Write(bool force_flush, time_t timestamp, return; } - const auto now = std::chrono::system_clock::now(); - - auto cleanupLogs = [this, current_time = now] { + auto cleanupLogs = [this, current_time = timestamp] { if (log_cleaner.enabled()) { log_cleaner.Run(current_time, base_filename_selected_, base_filename_, filename_extension_); @@ -1114,10 +1142,12 @@ void LogFileObject::Write(bool force_flush, time_t timestamp, rollover_attempt_ = 0; struct ::tm tm_time; + std::time_t t = std::chrono::system_clock::to_time_t(timestamp); + if (FLAGS_log_utc_time) { - gmtime_r(×tamp, &tm_time); + gmtime_r(&t, &tm_time); } else { - localtime_r(×tamp, &tm_time); + localtime_r(&t, &tm_time); } // The logfile's filename will have the date/time & pid in it @@ -1208,7 +1238,7 @@ void LogFileObject::Write(bool force_flush, time_t timestamp, << "Running duration (h:mm:ss): " << PrettyDuration( std::chrono::duration_cast>( - now - start_time_)) + timestamp - start_time_)) << '\n' << "Log line format: [IWEF]" << date_time_format << " " << "threadid file:line] msg" << '\n'; @@ -1239,7 +1269,7 @@ void LogFileObject::Write(bool force_flush, time_t timestamp, bytes_since_flush_ += message_len; } } else { - if (now >= next_flush_time_) { + if (timestamp >= next_flush_time_) { stop_writing = false; // check to see if disk has free space. } return; // no need to flush @@ -1248,8 +1278,8 @@ void LogFileObject::Write(bool force_flush, time_t timestamp, // See important msgs *now*. Also, flush logs at least every 10^6 chars, // or every "FLAGS_logbufsecs" seconds. if (force_flush || (bytes_since_flush_ >= 1000000) || - (now >= next_flush_time_)) { - FlushUnlocked(now); + (timestamp >= next_flush_time_)) { + FlushUnlocked(timestamp); #ifdef GLOG_OS_LINUX // Only consider files >= 3MiB if (FLAGS_drop_log_memory && file_length_ >= (3U << 20U)) { @@ -1587,7 +1617,7 @@ void LogMessage::Init(const char* file, int line, LogSeverity severity, data_->sink_ = nullptr; data_->outvec_ = nullptr; - auto now = std::chrono::system_clock::now(); + const auto now = std::chrono::system_clock::now(); logmsgtime_ = LogMessageTime(now); data_->num_chars_to_log_ = 0; @@ -1722,7 +1752,7 @@ void LogMessage::Flush() { // Copy of first FATAL log message so that we can print it out again // after all the stack traces. To preserve legacy behavior, we don't // use fatal_msg_data_exclusive. -static time_t fatal_time; +static std::chrono::system_clock::time_point fatal_time; static char fatal_message[256]; void ReprintFatalMessage() { @@ -1810,7 +1840,8 @@ void LogMessage::SendToLog() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) { if (!FLAGS_logtostderr && !FLAGS_logtostdout) { for (auto& log_destination : LogDestination::log_destinations_) { if (log_destination) { - log_destination->logger_->Write(true, 0, "", 0); + log_destination->logger_->Write( + true, std::chrono::system_clock::time_point{}, "", 0); } } } @@ -2005,20 +2036,20 @@ void LogSink::send(LogSeverity severity, const char* full_filename, const char* base_filename, int line, const LogMessageTime& time, const char* message, size_t message_len) { -#if defined(__GNUC__) +#if defined(__GNUG__) # pragma GCC diagnostic push # pragma GCC diagnostic ignored "-Wdeprecated-declarations" #elif defined(_MSC_VER) # pragma warning(push) # pragma warning(disable : 4996) -#endif // __GNUC__ +#endif // __GNUG__ send(severity, full_filename, base_filename, line, &time.tm(), message, message_len); -#if defined(__GNUC__) +#if defined(__GNUG__) # pragma GCC diagnostic pop #elif defined(_MSC_VER) # pragma warning(pop) -#endif // __GNUC__ +#endif // __GNUG__ } void LogSink::send(LogSeverity severity, const char* full_filename, @@ -2649,49 +2680,41 @@ void EnableLogCleaner(const std::chrono::minutes& overdue) { void DisableLogCleaner() { log_cleaner.Disable(); } -LogMessageTime::LogMessageTime() - : time_struct_(), timestamp_(0), usecs_(0), gmtoffset_(0) {} +LogMessageTime::LogMessageTime() = default; -LogMessageTime::LogMessageTime(std::chrono::system_clock::time_point now) { +LogMessageTime::LogMessageTime(std::chrono::system_clock::time_point now) + : timestamp_{now} { std::time_t timestamp = std::chrono::system_clock::to_time_t(now); - std::tm t; if (FLAGS_log_utc_time) { - gmtime_r(×tamp, &t); + gmtime_r(×tamp, &time_struct_); } else { - localtime_r(×tamp, &t); + localtime_r(×tamp, &time_struct_); } - init(t, timestamp, now); + usecs_ = std::chrono::duration_cast( + now - std::chrono::system_clock::from_time_t(timestamp)); + CalcGmtOffset(timestamp); } -void LogMessageTime::init(const std::tm& t, std::time_t timestamp, - std::chrono::system_clock::time_point now) { - time_struct_ = t; - timestamp_ = timestamp; - usecs_ = std::chrono::duration_cast>( - now - std::chrono::system_clock::from_time_t(timestamp)) - .count(); - - CalcGmtOffset(); -} - -void LogMessageTime::CalcGmtOffset() { +void LogMessageTime::CalcGmtOffset(std::time_t t) { std::tm gmt_struct; int isDst = 0; if (FLAGS_log_utc_time) { - localtime_r(×tamp_, &gmt_struct); + localtime_r(&t, &gmt_struct); isDst = gmt_struct.tm_isdst; gmt_struct = time_struct_; } else { isDst = time_struct_.tm_isdst; - gmtime_r(×tamp_, &gmt_struct); + gmtime_r(&t, &gmt_struct); } time_t gmt_sec = mktime(&gmt_struct); - const long hour_secs = 3600; + // If the Daylight Saving Time(isDst) is active subtract an hour from the // current timestamp. - gmtoffset_ = - static_cast(timestamp_ - gmt_sec + (isDst ? hour_secs : 0)); + using namespace std::chrono_literals; + gmtoffset_ = std::chrono::duration_cast( + timestamp_ - std::chrono::system_clock::from_time_t(gmt_sec) + + (isDst ? 1h : 0h)); } } // namespace google diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index 868716cf3..db2d8085e 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -937,7 +937,8 @@ struct MyLogger : public base::Logger { ~MyLogger() override { *set_on_destruction_ = true; } - void Write(bool /* should_flush */, time_t /* timestamp */, + void Write(bool /* should_flush */, + const std::chrono::system_clock::time_point& /* timestamp */, const char* message, size_t length) override { data.append(message, length); } @@ -1070,8 +1071,9 @@ struct RecordDeletionLogger : public base::Logger { *set_on_destruction_ = false; } ~RecordDeletionLogger() override { *set_on_destruction_ = true; } - void Write(bool force_flush, time_t timestamp, const char* message, - size_t length) override { + void Write(bool force_flush, + const std::chrono::system_clock::time_point& timestamp, + const char* message, size_t length) override { wrapped_logger_->Write(force_flush, timestamp, message, length); } void Flush() override { wrapped_logger_->Flush(); } @@ -1535,10 +1537,11 @@ TEST(LogMsgTime, gmtoff) { * */ google::LogMessage log_obj(__FILE__, __LINE__); - long int nGmtOff = log_obj.getLogMessageTime().gmtoff(); + std::chrono::hours nGmtOff = log_obj.getLogMessageTime().gmtoff(); // GMT offset ranges from UTC-12:00 to UTC+14:00 - const long utc_min_offset = -43200; - const long utc_max_offset = 50400; + using namespace std::chrono_literals; + const std::chrono::hours utc_min_offset = -12h; + const std::chrono::hours utc_max_offset = 14h; EXPECT_TRUE((nGmtOff >= utc_min_offset) && (nGmtOff <= utc_max_offset)); }