feat add console_log

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"

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<LogSink *> g_sinks;
+static std::set<LogSink::Ptr> g_sinks;
+static std::atomic<int> 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() {
+    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(&timestamp, &t);
-  else
+  if (use_localtime_) {
     localtime_r(&timestamp, &t);
+  } else {
+    gmtime_r(&timestamp, &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(&timestamp, &t);
-  else
+  if (use_localtime_) {
     localtime_r(&timestamp, &t);
+  } else {
+    gmtime_r(&timestamp, &t);
+  }
+
   init(t, timestamp, 0);
+  usecs_ = std::chrono::duration_cast<std::chrono::microseconds>(
+               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<std::int32_t>((now - timestamp) * 1000000);
+  if (now < timestamp) {
+    usecs_ = 0;
+  } else {
+    usecs_ = static_cast<std::int32_t>((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<std::mutex> _(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<std::mutex> _(g_sink_mutex);
   g_sinks.erase(dest);
+  g_sink_count.fetch_sub(1);
 }
 
 void SetStderrLogging(LogSeverity min_severity) {}

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<LogSink>;
+
   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,

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<AwesomeLogSink>();
+  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<AwesomeLogSink>();
+  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"));
 }
 

tile/base/logging/console_sink.cc

@@ -0,0 +1,28 @@
+#include "tile/base/logging/console_sink.h"
+
+#include <stdio.h>
+namespace tile {
+
+ConsoleSink::Ptr ConsoleSink::Create() {
+  return std::shared_ptr<ConsoleSink>(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

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<ConsoleSink>;
+  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

tile/base/logging/splitter_sink.cc

@@ -2,14 +2,20 @@
 #include <cassert>
 
 namespace tile {
-SplitterSink::SplitterSink() {}
-SplitterSink::SplitterSink(
+std::shared_ptr<SplitterSink> SplitterSink::Create() {
+  return std::shared_ptr<SplitterSink>(new SplitterSink());
+}
+
+std::shared_ptr<SplitterSink> SplitterSink::Create(
     std::initializer_list<std::shared_ptr<LogSink>> init_list) {
-  std::lock_guard<std::mutex> _(sinks_mutex_);
-  for (auto &sink : init_list) {
-    sinks_.insert(sink);
+  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<std::mutex> _(sinks_mutex_);
   sinks_.clear();
 }
+std::set<LogSink::Ptr> SplitterSink::sinks() {
+  std::lock_guard<std::mutex> _(sinks_mutex_);
+  return sinks_;
+}
 
 } // namespace tile

tile/base/logging/splitter_sink.h

@@ -6,8 +6,10 @@
 namespace tile {
 class SplitterSink : public LogSink {
 public:
-  SplitterSink();
-  SplitterSink(std::initializer_list<std::shared_ptr<LogSink>> init_list);
+  using Ptr = std::shared_ptr<SplitterSink>;
+  static Ptr Create();
+  static Ptr Create(std::initializer_list<std::shared_ptr<LogSink>> init_list);
+
   ~SplitterSink() override;
 
   void send(LogSeverity severity, const char *full_filename,
@@ -19,6 +21,10 @@ public:
   void AddSink(std::shared_ptr<LogSink> sink);
   void RemoveSink(std::shared_ptr<LogSink> sink);
   void ClearSinks();
+  std::set<LogSink::Ptr> sinks();
+
+protected:
+  SplitterSink();
 
 private:
   std::set<std::shared_ptr<LogSink>> sinks_;

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<SimpleSink>;
+  static Ptr Create() { return std::shared_ptr<SimpleSink>(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<SimpleSink>(sink)->message_, msg);
+    }
+  }
+}
+
+} // namespace tile

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<int(int, char **)> cb,
   gflags::ParseCommandLineFlags(&argc, &argv, true);
   detail::ApplyFlagOverrider();
 
+  AddLogSink(ConsoleSink::Create());
+
   // TODO: Add Init log level
   // google::InitGoogleLogging(argv[0]);