diff --git a/CMakeLists.txt b/CMakeLists.txt index 4ba3362..981d316 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -167,7 +167,9 @@ set(TILE_SRCS "tile/base/internal/thread_pool.cc" "tile/base/internal/time_keeper.cc" "tile/base/internal/time_keeper.h" + # logging "tile/base/logging/splitter_sink.cc" + "tile/base/logging/console_sink.cc" "tile/base/net/endpoint.cc" "tile/base/object_pool/disabled.cc" "tile/base/object_pool/global.cc" diff --git a/tile/base/internal/logging.cc b/tile/base/internal/logging.cc index 8a97f1b..21c00d2 100644 --- a/tile/base/internal/logging.cc +++ b/tile/base/internal/logging.cc @@ -40,7 +40,8 @@ void WritePrefixTo(std::string *to) { namespace tile { static std::mutex g_sink_mutex; -static std::set g_sinks; +static std::set g_sinks; +static std::atomic g_sink_count{0}; static uint64_t g_num_messages[TILE_MAX_LOG_SEVERITY + 1]; std::mutex g_log_mutex; @@ -146,7 +147,9 @@ private: } } void SendToLog() { - ColoredWriteToStdout(severity_, message_text_, num_chars_to_log_); + if (g_sink_count.load(std::memory_order_relaxed) == 0) { + ColoredWriteToStdout(severity_, message_text_, num_chars_to_log_); + } LogToSinks(severity_, fullname(), basename(), line(), time(), message_text_ + num_prefix_chars_, num_chars_to_log_ - num_prefix_chars_ - 1); @@ -208,34 +211,48 @@ std::ostream &LogMessageFatal::stream() { return LogMessage::stream(); } LogMessageTime::LogMessageTime() : time_struct_(), timestamp_(0), usecs_(0), gmtoffset_(0) {} -LogMessageTime::LogMessageTime(std::tm t) { +LogMessageTime::LogMessageTime(std::tm t) : use_localtime_(true) { std::time_t timestamp = std::mktime(&t); init(t, timestamp, 0); } -LogMessageTime::LogMessageTime(std::time_t timestamp, WallTime now) { +LogMessageTime::LogMessageTime(std::time_t timestamp, WallTime now) + : use_localtime_(false) { std::tm t; - if (true) - gmtime_r(×tamp, &t); - else + if (use_localtime_) { localtime_r(×tamp, &t); + } else { + gmtime_r(×tamp, &t); + } + init(t, timestamp, now); } -LogMessageTime::LogMessageTime(std::chrono::system_clock::time_point tp) { +LogMessageTime::LogMessageTime(std::chrono::system_clock::time_point tp) + : use_localtime_(false) { std::time_t timestamp = std::chrono::system_clock::to_time_t(tp); std::tm t; - if (true) - gmtime_r(×tamp, &t); - else + if (use_localtime_) { localtime_r(×tamp, &t); + } else { + gmtime_r(×tamp, &t); + } + init(t, timestamp, 0); + usecs_ = std::chrono::duration_cast( + tp.time_since_epoch()) + .count() % + 1000000; } void LogMessageTime::init(const std::tm &t, std::time_t timestamp, WallTime now) { time_struct_ = t; timestamp_ = timestamp; - usecs_ = static_cast((now - timestamp) * 1000000); + if (now < timestamp) { + usecs_ = 0; + } else { + usecs_ = static_cast((now - timestamp) * 1000000) % 1000000; + } CalcGmtOffset(); } @@ -270,13 +287,33 @@ void LogSink::send(LogSeverity severity, const char *full_filename, } void LogSink::WaitTillSent() {} -std::string LogSink::ToString(LogSeverity severity, const char *file, int line, +std::string LogSink::ToString(LogSeverity severity, const char *file, + const char *base_filename, int line, const LogMessageTime &logmsgtime, const char *message, size_t message_len) { + std::stringstream ss; + char date_time[64]; + sprintf(date_time, "%4d-%02d-%02dT%02d:%02d:%02d.%06d", + logmsgtime.year() + 1900, logmsgtime.month(), logmsgtime.day(), + logmsgtime.hour(), logmsgtime.min(), logmsgtime.sec(), + logmsgtime.usec()); + + ss << date_time; + + if (logmsgtime.gmtoff() != 0) { + auto hour = logmsgtime.gmtoff() / 3600; + auto min = std::abs(logmsgtime.gmtoff() % 3600) / 60; + sprintf(date_time, "%+03ld:%02ld", hour, min); + ss << date_time; + } else if (!logmsgtime.use_localtime()) { + ss << "Z"; + } + ss << " " << GetLogSeverityName(severity)[0] << " "; + ss << base_filename << ":" << line << " "; + // return google::LogSink::ToString(severity, file, line, logmsgtime.tm(), // message, message_len); - std::stringstream ss; ss.write(message, message_len); return ss.str(); } @@ -300,14 +337,16 @@ void ColoredWriteToStderr(LogSeverity severity, const char *message, ColoredWriteToStderrOrStdout(stderr, severity, message, len); } -void AddLogSink(LogSink *dest) { +void AddLogSink(LogSink::Ptr dest) { std::lock_guard _(g_sink_mutex); g_sinks.insert(dest); + g_sink_count.fetch_add(1); } -void RemoveLogSink(LogSink *dest) { +void RemoveLogSink(LogSink::Ptr dest) { std::lock_guard _(g_sink_mutex); g_sinks.erase(dest); + g_sink_count.fetch_sub(1); } void SetStderrLogging(LogSeverity min_severity) {} diff --git a/tile/base/internal/logging.h b/tile/base/internal/logging.h index 78253b9..92900f2 100644 --- a/tile/base/internal/logging.h +++ b/tile/base/internal/logging.h @@ -682,6 +682,7 @@ struct LogMessageTime { const int &dst() const { return time_struct_.tm_isdst; } const long int &gmtoff() const { return gmtoffset_; } const std::tm &tm() const { return time_struct_; } + const bool use_localtime() const { return use_localtime_; } private: void init(const std::tm &t, std::time_t timestamp, WallTime now); @@ -689,29 +690,34 @@ private: time_t timestamp_; // Time of creation of LogMessage in seconds int32_t usecs_; // Time of creation of LogMessage - microseconds part long int gmtoffset_; + bool use_localtime_; void CalcGmtOffset(); }; class LogSink { public: + using Ptr = std::shared_ptr; + virtual ~LogSink(); virtual void send(LogSeverity severity, const char *full_filename, const char *base_filename, int line, const LogMessageTime &logmsgtime, const char *message, size_t message_len); virtual void WaitTillSent(); - std::string ToString(LogSeverity severity, const char *file, int line, - const LogMessageTime &logmsgtime, const char *message, - size_t message_len); + + virtual std::string ToString(LogSeverity severity, const char *file, + const char *base_filename, int line, + const LogMessageTime &logmsgtime, + const char *message, size_t message_len); }; void ColoredWriteToStdout(LogSeverity severity, const char *message, size_t len); void ColoredWriteToStderr(LogSeverity severity, const char *message, size_t len); -void AddLogSink(LogSink *dest); -void RemoveLogSink(LogSink *dest); +void AddLogSink(LogSink::Ptr dest); +void RemoveLogSink(LogSink::Ptr dest); void SetStderrLogging(LogSeverity min_severity); void LogToStderr(); void LogToSinks(LogSeverity severity, const char *full_filename, diff --git a/tile/base/internal/logging_test.cc b/tile/base/internal/logging_test.cc index 6f0d585..6d94cf9 100644 --- a/tile/base/internal/logging_test.cc +++ b/tile/base/internal/logging_test.cc @@ -39,9 +39,9 @@ TEST(Logging, CHECK) { } TEST(Logging, Prefix) { - AwesomeLogSink sink; - tile::AddLogSink(&sink); - tile::ScopedDeferred defered([&] { tile::RemoveLogSink(&sink); }); + auto sink = std::make_shared(); + tile::AddLogSink(sink); + tile::ScopedDeferred defered([&] { tile::RemoveLogSink(sink); }); TILE_LOG_INFO("something"); @@ -54,7 +54,7 @@ TEST(Logging, Prefix) { my_prefix2 = "[prefix2]"; TILE_LOG_INFO("something"); - ASSERT_THAT(sink.msgs, + ASSERT_THAT(sink->msgs, ::testing::ElementsAre("something", "[prefix] something", "[prefix1] something", "[prefix1] [prefix2] something")); @@ -67,15 +67,15 @@ TEST(Logging, DontPanicOnFormatFailure) { TEST(Logging, EverySecond) { ResetLogPrefix(); - AwesomeLogSink sink; - tile::AddLogSink(&sink); - tile::ScopedDeferred defered([&] { tile::RemoveLogSink(&sink); }); + auto sink = std::make_shared(); + tile::AddLogSink(sink); + tile::ScopedDeferred defered([&] { tile::RemoveLogSink(sink); }); for (int i = 0; i < 30; i++) { TILE_LOG_INFO_EVERY_SECOND("something"); std::this_thread::sleep_for(std::chrono::milliseconds(100)); } - ASSERT_THAT(sink.msgs, + ASSERT_THAT(sink->msgs, ::testing::ElementsAre("something", "something", "something")); } diff --git a/tile/base/logging/console_sink.cc b/tile/base/logging/console_sink.cc new file mode 100644 index 0000000..2347bc4 --- /dev/null +++ b/tile/base/logging/console_sink.cc @@ -0,0 +1,28 @@ +#include "tile/base/logging/console_sink.h" + +#include +namespace tile { + +ConsoleSink::Ptr ConsoleSink::Create() { + return std::shared_ptr(new ConsoleSink()); +} + +ConsoleSink::~ConsoleSink() {} + +void ConsoleSink::send(LogSeverity severity, const char *full_filename, + const char *base_filename, int line, + const LogMessageTime &logmsgtime, const char *message, + size_t message_len) { + auto msg = ToString(severity, full_filename, base_filename, line, logmsgtime, + message, message_len); + while (!msg.empty() && msg.back() == '\n') { + } + msg.pop_back(); + fprintf(stdout, "%s\n", msg.c_str()); +} + +void ConsoleSink::WaitTillSent() {} + +ConsoleSink::ConsoleSink() {} + +} // namespace tile diff --git a/tile/base/logging/console_sink.h b/tile/base/logging/console_sink.h new file mode 100644 index 0000000..4bfb34d --- /dev/null +++ b/tile/base/logging/console_sink.h @@ -0,0 +1,25 @@ +#ifndef TILE_BASE_LOGGING_CONSOLE_SINK_H +#define TILE_BASE_LOGGING_CONSOLE_SINK_H + +#pragma once + +#include "tile/base/internal/logging.h" +namespace tile { +class ConsoleSink : public LogSink { +public: + using Ptr = std::shared_ptr; + static Ptr Create(); + + ~ConsoleSink() override; + void send(LogSeverity severity, const char *full_filename, + const char *base_filename, int line, + const LogMessageTime &logmsgtime, const char *message, + size_t message_len) override; + void WaitTillSent() override; + +protected: + ConsoleSink(); +}; +} // namespace tile + +#endif // TILE_BASE_LOGGING_CONSOLE_SINK_H diff --git a/tile/base/logging/splitter_sink.cc b/tile/base/logging/splitter_sink.cc index 42a0e2d..a2f54a1 100644 --- a/tile/base/logging/splitter_sink.cc +++ b/tile/base/logging/splitter_sink.cc @@ -2,14 +2,20 @@ #include namespace tile { -SplitterSink::SplitterSink() {} -SplitterSink::SplitterSink( - std::initializer_list> init_list) { - std::lock_guard _(sinks_mutex_); - for (auto &sink : init_list) { - sinks_.insert(sink); - } +std::shared_ptr SplitterSink::Create() { + return std::shared_ptr(new SplitterSink()); } + +std::shared_ptr SplitterSink::Create( + std::initializer_list> init_list) { + auto sink = Create(); + for (auto &s : init_list) { + sink->AddSink(s); + } + return sink; +} + +SplitterSink::SplitterSink() {} SplitterSink::~SplitterSink() {} void SplitterSink::send(LogSeverity severity, const char *full_filename, const char *base_filename, int line, @@ -49,5 +55,9 @@ void SplitterSink::ClearSinks() { std::lock_guard _(sinks_mutex_); sinks_.clear(); } +std::set SplitterSink::sinks() { + std::lock_guard _(sinks_mutex_); + return sinks_; +} } // namespace tile diff --git a/tile/base/logging/splitter_sink.h b/tile/base/logging/splitter_sink.h index 4f7e74b..aae5640 100644 --- a/tile/base/logging/splitter_sink.h +++ b/tile/base/logging/splitter_sink.h @@ -6,8 +6,10 @@ namespace tile { class SplitterSink : public LogSink { public: - SplitterSink(); - SplitterSink(std::initializer_list> init_list); + using Ptr = std::shared_ptr; + static Ptr Create(); + static Ptr Create(std::initializer_list> init_list); + ~SplitterSink() override; void send(LogSeverity severity, const char *full_filename, @@ -19,6 +21,10 @@ public: void AddSink(std::shared_ptr sink); void RemoveSink(std::shared_ptr sink); void ClearSinks(); + std::set sinks(); + +protected: + SplitterSink(); private: std::set> sinks_; diff --git a/tile/base/logging/splitter_sink_test.cc b/tile/base/logging/splitter_sink_test.cc new file mode 100644 index 0000000..3485691 --- /dev/null +++ b/tile/base/logging/splitter_sink_test.cc @@ -0,0 +1,56 @@ +#include "tile/base/logging/splitter_sink.h" +#include "gtest/gtest.h" + +namespace tile { +class SimpleSink : public LogSink { +public: + using Ptr = std::shared_ptr; + static Ptr Create() { return std::shared_ptr(new SimpleSink()); } + void send(LogSeverity severity, const char *full_filename, + const char *base_filename, int line, + const LogMessageTime &logmsgtime, const char *message, + size_t message_len) override { + message_ = std::string(message, message_len); + } + void WaitTillSent() override {} + std::string message_; +}; + +TEST(SplitterSink, One) { + auto sink = SimpleSink::Create(); + auto splitter = SplitterSink::Create({sink}); + splitter->send(LogSeverity::TILE_INFO, nullptr, nullptr, 0, LogMessageTime(), + "message", 7); + ASSERT_EQ(sink->message_, "message"); +} + +TEST(SplitterSink, Two) { + auto sink1 = SimpleSink::Create(); + auto sink2 = SimpleSink::Create(); + auto splitter = SplitterSink::Create({sink1, sink2}); + splitter->send(LogSeverity::TILE_INFO, nullptr, nullptr, 0, LogMessageTime(), + "message", 7); + ASSERT_EQ(sink1->message_, "message"); + ASSERT_EQ(sink2->message_, "message"); +} + +TEST(SplitterSink, Multi) { + auto splitter = SplitterSink::Create(); + for (int i = 0; i < 100; i++) { + splitter->AddSink(SimpleSink::Create()); + } + + for (int i = 0; i < 100; i++) { + std::stringstream ss; + ss << "message" << i; + auto msg = ss.str(); + splitter->send(LogSeverity::TILE_INFO, nullptr, nullptr, 0, + LogMessageTime(), msg.data(), msg.size()); + + for (auto &sink : splitter->sinks()) { + ASSERT_EQ(std::static_pointer_cast(sink)->message_, msg); + } + } +} + +} // namespace tile diff --git a/tile/init.cc b/tile/init.cc index f49f000..18b5858 100644 --- a/tile/init.cc +++ b/tile/init.cc @@ -6,6 +6,7 @@ #include "tile/base/internal/time_keeper.h" #include "tile/base/internal/utility.h" #include "tile/base/logging.h" +#include "tile/base/logging/console_sink.h" #include "tile/base/option.h" #include "tile/base/thread/latch.h" #include "tile/init/on_init.h" @@ -60,6 +61,8 @@ int Start(int argc, char **argv, std::function cb, gflags::ParseCommandLineFlags(&argc, &argv, true); detail::ApplyFlagOverrider(); + AddLogSink(ConsoleSink::Create()); + // TODO: Add Init log level // google::InitGoogleLogging(argv[0]);