feat: add timestamps in default log backend (#266)

Timestamps are always rendered in "Zulu" time, and with nanosecond
resolution (no matter what the actual resolution of a platform's
`system_clock::time_point`).

Fixes #261.

Author: devbww

google/cloud/log.cc

@@ -15,39 +15,77 @@
 #include "google/cloud/log.h"
 #include "google/cloud/internal/getenv.h"
 #include <array>
+#include <cstdint>
+#include <ctime>
+#include <iomanip>
 
 namespace google {
 namespace cloud {
 inline namespace GOOGLE_CLOUD_CPP_NS {
+
 static_assert(sizeof(Severity) <= sizeof(int),
               "Expected Severity to fit in an integer");
 
 static_assert(static_cast<int>(Severity::GCP_LS_LOWEST) <
                   static_cast<int>(Severity::GCP_LS_HIGHEST),
               "Expect LOWEST severity to be smaller than HIGHEST severity");
 
+namespace {
+struct Timestamp {
+  explicit Timestamp(std::chrono::system_clock::time_point const& tp) {
+    auto const tt = std::chrono::system_clock::to_time_t(tp);
+#if defined(_WIN32)
+    gmtime_s(&tm, &tt);
+#else
+    gmtime_r(&tt, &tm);
+#endif
+    auto const ss = tp - std::chrono::system_clock::from_time_t(tt);
+    nanos = std::chrono::duration_cast<std::chrono::nanoseconds>(ss).count();
+  }
+  std::tm tm;
+  std::int32_t nanos;
+};
+
+std::ostream& operator<<(std::ostream& os, Timestamp const& ts) {
+  auto const prev = os.fill(' ');
+  auto constexpr kTmYearOffset = 1900;
+  os << std::setw(4) << ts.tm.tm_year + kTmYearOffset;
+  os.fill('0');
+  os << '-' << std::setw(2) << ts.tm.tm_mon + 1;
+  os << '-' << std::setw(2) << ts.tm.tm_mday;
+  os << 'T' << std::setw(2) << ts.tm.tm_hour;
+  os << ':' << std::setw(2) << ts.tm.tm_min;
+  os << ':' << std::setw(2) << ts.tm.tm_sec;
+  // NOLINTNEXTLINE(readability-magic-numbers)
+  os << '.' << std::setw(9) << ts.nanos << 'Z';
+  os.fill(prev);
+  return os;
+}
+
+auto constexpr kSeverityCount = static_cast<int>(Severity::GCP_LS_HIGHEST) + 1;
+
+// Double braces needed to workaround a clang-3.8 bug.
+std::array<char const*, kSeverityCount> constexpr kSeverityNames{{
+    "TRACE",
+    "DEBUG",
+    "INFO",
+    "NOTICE",
+    "WARNING",
+    "ERROR",
+    "CRITICAL",
+    "ALERT",
+    "FATAL",
+}};
+}  // namespace
+
 std::ostream& operator<<(std::ostream& os, Severity x) {
-  auto constexpr kSeverityCount =
-      static_cast<int>(Severity::GCP_LS_HIGHEST) + 1;
-  // Double braces needed to workaround a clang-3.8 bug.
-  std::array<char const*, kSeverityCount> names{{
-      "TRACE",
-      "DEBUG",
-      "INFO",
-      "NOTICE",
-      "WARNING",
-      "ERROR",
-      "CRITICAL",
-      "ALERT",
-      "FATAL",
-  }};
   auto index = static_cast<int>(x);
-  return os << names[index];
+  return os << kSeverityNames[index];
 }
 
 std::ostream& operator<<(std::ostream& os, LogRecord const& rhs) {
-  return os << '[' << rhs.severity << "] " << rhs.message << " ("
-            << rhs.filename << ':' << rhs.lineno << ')';
+  return os << Timestamp{rhs.timestamp} << " [" << rhs.severity << "] "
+            << rhs.message << " (" << rhs.filename << ':' << rhs.lineno << ')';
 }
 
 LogSink::LogSink()

google/cloud/log.h

@@ -14,6 +14,7 @@
 
 #ifndef GOOGLE_CLOUD_CPP_GOOGLE_CLOUD_LOG_H
 #define GOOGLE_CLOUD_CPP_GOOGLE_CLOUD_LOG_H
+
 /**
  * @file log.h
  *
@@ -222,7 +223,7 @@ struct LogRecord {
 std::ostream& operator<<(std::ostream& os, LogRecord const& rhs);
 
 /**
- * A sink to receive log records.
+ * The logging backend interface.
  */
 class LogBackend {
  public:
@@ -233,7 +234,7 @@ class LogBackend {
 };
 
 /**
- *
+ * A sink to receive log records.
  */
 class LogSink {
  public:

google/cloud/log_test.cc

@@ -15,6 +15,7 @@
 #include "google/cloud/log.h"
 #include "google/cloud/testing_util/scoped_environment.h"
 #include <gmock/gmock.h>
+#include <chrono>
 
 namespace google {
 namespace cloud {
@@ -32,6 +33,21 @@ TEST(LogSeverityTest, Streaming) {
   EXPECT_EQ("TRACE", os.str());
 }
 
+TEST(LogRecordTest, Streaming) {
+  std::ostringstream os;
+  LogRecord lr;
+  lr.severity = Severity::GCP_LS_INFO;
+  lr.function = "Func";
+  lr.filename = "filename.cc";
+  lr.lineno = 123;
+  lr.timestamp = std::chrono::system_clock::from_time_t(1585112316) +
+                 std::chrono::microseconds(123456);
+  lr.message = "message";
+  os << lr;
+  EXPECT_EQ("2020-03-25T04:58:36.123456000Z [INFO] message (filename.cc:123)",
+            os.str());
+}
+
 TEST(LogSinkTest, CompileTimeEnabled) {
   EXPECT_TRUE(LogSink::CompileTimeEnabled(Severity::GCP_LS_CRITICAL));
   if (Severity::GCP_LS_LOWEST_ENABLED >= Severity::GCP_LS_TRACE) {