logging: add GlogStyleFormatter

Summary:
Add a LogFormatter implementation that logs messages using a similar format to
the glog library.

Reviewed By: wez

Differential Revision: D5083108

fbshipit-source-id: 75f0a6b78ce5406b4557d6c4394f033d5e019f71

CMakeLists.txt

@@ -321,6 +321,7 @@ if (BUILD_TESTS)
           XlogHeader2.h
         SOURCES
           AsyncFileWriterTest.cpp
+          GlogFormatterTest.cpp
           ImmediateFileWriterTest.cpp
           LogCategoryTest.cpp
           LoggerDBTest.cpp

folly/Makefile.am

@@ -122,6 +122,7 @@ nobase_follyinclude_HEADERS = \
 	experimental/JSONSchema.h \
 	experimental/LockFreeRingBuffer.h \
 	experimental/logging/AsyncFileWriter.h \
+	experimental/logging/GlogStyleFormatter.h \
 	experimental/logging/ImmediateFileWriter.h \
 	experimental/logging/LogCategory.h \
 	experimental/logging/LogFormatter.h \

folly/experimental/logging/GlogStyleFormatter.cpp

+/*
+ * Copyright 2004-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#include <folly/experimental/logging/GlogStyleFormatter.h>
+
+#include <folly/Format.h>
+#include <folly/experimental/logging/LogLevel.h>
+#include <folly/experimental/logging/LogMessage.h>
+
+namespace {
+using folly::StringPiece;
+using folly::LogLevel;
+
+StringPiece getGlogLevelName(LogLevel level) {
+  if (level < LogLevel::INFO) {
+    return "VERBOSE";
+  } else if (level < LogLevel::WARN) {
+    return "INFO";
+  } else if (level < LogLevel::ERROR) {
+    return "WARNING";
+  } else if (level < LogLevel::CRITICAL) {
+    return "ERROR";
+  }
+  return "CRITICAL";
+}
+}
+
+namespace folly {
+
+std::string GlogStyleFormatter::formatMessage(
+    const LogMessage& message,
+    const LogCategory* /* handlerCategory */) {
+  // Get the local time info
+  struct tm ltime;
+  auto timeSinceEpoch = message.getTimestamp().time_since_epoch();
+  auto epochSeconds =
+      std::chrono::duration_cast<std::chrono::seconds>(timeSinceEpoch);
+  std::chrono::microseconds usecs =
+      std::chrono::duration_cast<std::chrono::microseconds>(timeSinceEpoch) -
+      epochSeconds;
+  time_t unixTimestamp = epochSeconds.count();
+  if (!localtime_r(&unixTimestamp, &ltime)) {
+    memset(&ltime, 0, sizeof(ltime));
+  }
+
+  auto basename = message.getFileBaseName();
+  auto headerFormatter = folly::format(
+      "{}{:02d}{:02d} {:02d}:{:02d}:{:02d}.{:06d} {:5d} {}:{}] ",
+      getGlogLevelName(message.getLevel())[0],
+      ltime.tm_mon + 1,
+      ltime.tm_mday,
+      ltime.tm_hour,
+      ltime.tm_min,
+      ltime.tm_sec,
+      usecs.count(),
+      message.getThreadID(),
+      basename,
+      message.getLineNumber());
+
+  // TODO: Support including thread names and thread context info.
+
+  // The fixed portion of the header takes up 31 bytes.
+  //
+  // The variable portions that we can't account for here include the line
+  // number and the thread ID (just in case it is larger than 6 digits long).
+  // Here we guess that 40 bytes will be long enough to include room for this.
+  //
+  // If this still isn't long enough the string will grow as necessary, so the
+  // code will still be correct, but just slightly less efficient than if we
+  // had allocated a large enough buffer the first time around.
+  size_t headerLengthGuess = 40 + basename.size();
+
+  // Format the data into a buffer.
+  std::string buffer;
+  StringPiece msgData{message.getMessage()};
+  if (message.containsNewlines()) {
+    // If there are multiple lines in the log message, add a header
+    // before each one.
+    std::string header;
+    header.reserve(headerLengthGuess);
+    headerFormatter.appendTo(header);
+
+    // Make a guess at how many lines will be in the message, just to make an
+    // initial buffer allocation.  If the guess is too small then the string
+    // will reallocate and grow as necessary, it will just be slightly less
+    // efficient than if we had guessed enough space.
+    size_t numLinesGuess = 4;
+    buffer.reserve(((header.size() + 1) * numLinesGuess) + msgData.size());
+
+    size_t idx = 0;
+    while (true) {
+      auto end = msgData.find('\n', idx);
+      if (end == StringPiece::npos) {
+        end = msgData.size();
+      }
+
+      buffer.append(header);
+      auto line = msgData.subpiece(idx, end - idx);
+      buffer.append(line.data(), line.size());
+      buffer.push_back('\n');
+
+      if (end == msgData.size()) {
+        break;
+      }
+      idx = end + 1;
+    }
+  } else {
+    buffer.reserve(headerLengthGuess + msgData.size());
+    headerFormatter.appendTo(buffer);
+    buffer.append(msgData.data(), msgData.size());
+    buffer.push_back('\n');
+  }
+
+  return buffer;
+}
+}

folly/experimental/logging/GlogStyleFormatter.h

+/*
+ * Copyright 2004-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#pragma once
+
+#include <folly/Range.h>
+#include <folly/experimental/logging/LogFormatter.h>
+
+namespace folly {
+
+/**
+ * A LogFormatter implementation that produces messages in a format similar to
+ * that produced by the Google logging library.
+ *
+ * The glog message format is:
+ *
+ *   LmmDD HH:MM:SS.USECS THREAD [THREADNAME] (THREADCTX) FILE:LINE] MSG
+ *
+ * L:  A 1-character code describing the log level (e.g., E, W, I, V)
+ * mm: 2-digit month
+ * DD: 2-digit day
+ * HH: 2-digit hour, 24-hour format
+ * MM: 2-digit minute
+ * SS: 2-digit second
+ * USECS: 6-digit microseconds
+ * THREAD: Thread ID
+ * FILE: Filename (just the last component)
+ * LINE: Line number
+ * MSG: The actual log message
+ *
+ * [THREADNAME] is the thread name, and is only included if --logthreadnames
+ * was enabled on the command line.
+ *
+ * (THREADCTX) is thread-local log context data, if it has been set.  (This is
+ * a Facebook-specific modification, and is disabled unless --logthreadcontext
+ * was enabled on the command line.)
+ *
+ * Exception information and a custom log prefix may also appear after the
+ * file name and line number, before the ']' character.
+ */
+class GlogStyleFormatter : public LogFormatter {
+ public:
+  std::string formatMessage(
+      const LogMessage& message,
+      const LogCategory* handlerCategory) override;
+};
+}

folly/experimental/logging/Makefile.am

@@ -4,6 +4,7 @@ lib_LTLIBRARIES = libfollylogging.la
 
 libfollylogging_la_SOURCES = \
 	AsyncFileWriter.cpp \
+	GlogStyleFormatter.cpp \
 	ImmediateFileWriter.cpp \
 	LogCategory.cpp \
 	Logger.cpp \

folly/experimental/logging/test/GlogFormatterTest.cpp

+/*
+ * Copyright 2004-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#include <cstdlib>
+
+#include <folly/experimental/logging/GlogStyleFormatter.h>
+#include <folly/experimental/logging/LogMessage.h>
+#include <folly/experimental/logging/Logger.h>
+#include <folly/experimental/logging/LoggerDB.h>
+#include <folly/init/Init.h>
+#include <folly/portability/GTest.h>
+
+using namespace folly;
+
+namespace {
+/**
+ * Helper function to format a LogMessage using the GlogStyleFormatter.
+ *
+ * formatMsg() accepts the timestamp as a plain integer simply to reduce the
+ * verbosity of the test code.
+ *
+ * Note that in this test's main() function we set the timezone to "UTC"
+ * so that the logged time values will be consistent regardless of the actual
+ * local time on this host.
+ */
+std::string formatMsg(
+    LogLevel level,
+    StringPiece msg,
+    StringPiece filename,
+    unsigned int lineNumber,
+    // Default timestamp: 2017-04-17 13:45:56.123456 UTC
+    uint64_t timestampNS = 1492436756123456789ULL) {
+  LoggerDB db{LoggerDB::TESTING};
+  auto* category = db.getCategory("test");
+  GlogStyleFormatter formatter;
+
+  std::chrono::system_clock::time_point logTimePoint{
+      std::chrono::nanoseconds{timestampNS}};
+  LogMessage logMessage{
+      category, level, logTimePoint, filename, lineNumber, msg.str()};
+
+  return formatter.formatMessage(logMessage, category);
+}
+} // unnamed namespace
+
+TEST(GlogFormatter, log) {
+  auto tid = getOSThreadID();
+
+  // Test a very simple single-line log message
+  auto expected = folly::sformat(
+      "W0417 13:45:56.123456 {:5d} myfile.cpp:1234] hello world\n", tid);
+  EXPECT_EQ(
+      expected, formatMsg(LogLevel::WARN, "hello world", "myfile.cpp", 1234));
+}
+
+TEST(GlogFormatter, filename) {
+  auto tid = getOSThreadID();
+
+  // Make sure only the file basename gets logged
+  auto expected = folly::sformat(
+      "W0417 13:45:56.123456 {:5d} myfile.cpp:1234] hello world\n", tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          LogLevel::WARN,
+          "hello world",
+          "src/test/logging/code/myfile.cpp",
+          1234));
+
+  // Log a message with a very long file name.
+  expected = folly::sformat(
+      "W0417 13:45:56.123456 {:5d} "
+      "this_is_a_really_long_file_name_that_will_probably_exceed_"
+      "our_buffer_allocation_guess.cpp:123456789] oh noes\n",
+      tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          LogLevel::WARN,
+          "oh noes",
+          "this_is_a_really_long_file_name_that_will_probably_exceed_"
+          "our_buffer_allocation_guess.cpp",
+          123456789));
+}
+
+TEST(GlogFormatter, multiline) {
+  auto tid = getOSThreadID();
+  std::map<std::string, std::string> formatMap{
+      {"tid", folly::to<std::string>(tid)}};
+
+  // Log a multi-line message
+  auto expected = folly::svformat(
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] Eeek, a mouse!\n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]    .   .\n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]   ( ).( )\n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]    (o o) .-._.'\n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]   (  -  )\n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777]    mm mm\n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] \n"
+      "V0417 13:45:56.123456 {tid:>5s} rodent.cpp:777] =============\n",
+      formatMap);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          LogLevel::DBG9,
+          "Eeek, a mouse!\n"
+          "   .   .\n"
+          "  ( ).( )\n"
+          "   (o o) .-._.'\n"
+          "  (  -  )\n"
+          "   mm mm\n"
+          "\n"
+          "=============",
+          "src/rodent.cpp",
+          777));
+}
+
+TEST(GlogFormatter, singleNewline) {
+  auto tid = getOSThreadID();
+  std::map<std::string, std::string> formatMap{
+      {"tid", folly::to<std::string>(tid)}};
+
+  // Logging a single newline is basically two empty strings.
+  auto expected = folly::svformat(
+      "V0417 13:45:56.123456 {tid:>5s} foo.txt:123] \n"
+      "V0417 13:45:56.123456 {tid:>5s} foo.txt:123] \n",
+      formatMap);
+  EXPECT_EQ(expected, formatMsg(LogLevel::DBG9, "\n", "foo.txt", 123));
+}
+
+TEST(GlogFormatter, unprintableChars) {
+  auto tid = getOSThreadID();
+
+  // Unprintable characters should be backslash escaped, as should backslashes.
+  auto expected = folly::sformat(
+      "E0417 13:45:56.123456 {:5d} escapes.cpp:97] foo\\x07bar\\x1btest\n",
+      tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(LogLevel::ERROR, "foo\abar\x1btest", "escapes.cpp", 97));
+  expected = folly::sformat(
+      "I0417 13:45:56.123456 {:5d} escapes.cpp:98] foo\\\\bar\"test\n", tid);
+  EXPECT_EQ(
+      expected, formatMsg(LogLevel::INFO, "foo\\bar\"test", "escapes.cpp", 98));
+  expected = folly::sformat(
+      "C0417 13:45:56.123456 {:5d} escapes.cpp:99] nul\\x00byte\n", tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          LogLevel::CRITICAL, std::string("nul\0byte", 8), "escapes.cpp", 99));
+}
+
+int main(int argc, char* argv[]) {
+  testing::InitGoogleTest(&argc, argv);
+  folly::init(&argc, &argv);
+
+  // Some of our tests check timestamps emitted by the formatter.
+  // Set the timezone to a consistent value so that the tests are not
+  // affected by the local time of the user running the test.
+  //
+  // UTC is the only timezone that we can really rely on to work consistently.
+  // This will work even in the absence of a proper tzdata installation on the
+  // local system.
+  setenv("TZ", "UTC", 1);
+
+  return RUN_ALL_TESTS();
+}