Added CustomLogFormatter

Summary:
A `CustomLogFormatter` can be enabled by setting the `formatter` option to `custom`. This formatter reads an option named `log_format` which specifies the format of the logs. The format string is similar to what `folly::vformat(format,...)` expects. Check out the following example format:

  {L}{m:02d}{D:02d} {H:02d}:{M:02d}:{S:02d}.{USECS:06d} {THREAD:5d} {FILE}:{LINE}]

The format above prints logs in the same format as GLOGs.

Another option `colored` takes in one of the following values: `never`, `auto`, and `always`. When enabled, the output will be colored in the following way:

{F135233848}

The config used for the image above is:
  FOLLY_INIT_LOGGING_CONFIG(".=DBG; default:formatter=custom,log_format={L} {FILE}::{FUN}():{LINE}],colored=true");

As you can see, we have also included the function name using `{FUN}`. This can be particularly helpful when debugging errors.

Reviewed By: simpkins

Differential Revision: D8974950

fbshipit-source-id: 87d624f53dd67c0630fb222093c46fe79ff44ee1

folly/logging/AsyncFileWriter.cpp

@@ -30,7 +30,6 @@ constexpr size_t AsyncFileWriter::kDefaultMaxBufferSize;
 
 AsyncFileWriter::AsyncFileWriter(StringPiece path)
     : AsyncFileWriter{File{path.str(), O_WRONLY | O_APPEND | O_CREAT}} {}
-
 AsyncFileWriter::AsyncFileWriter(folly::File&& file) : file_{std::move(file)} {
   folly::detail::AtFork::registerHandler(
       this,
@@ -79,6 +78,10 @@ AsyncFileWriter::~AsyncFileWriter() {
   }
 }
 
+bool AsyncFileWriter::ttyOutput() const {
+  return isatty(file_.fd());
+}
+
 void AsyncFileWriter::writeMessage(StringPiece buffer, uint32_t flags) {
   return writeMessage(buffer.str(), flags);
 }

folly/logging/AsyncFileWriter.h

@@ -72,6 +72,11 @@ class AsyncFileWriter : public LogWriter {
    */
   void flush() override;
 
+  /**
+   * Returns true if the output steam is a tty.
+   */
+  bool ttyOutput() const override;
+
   /**
    * Set the maximum buffer size for this AsyncFileWriter, in bytes.
    *
@@ -149,6 +154,7 @@ class AsyncFileWriter : public LogWriter {
   void restartThread();
 
   folly::File file_;
+
   folly::Synchronized<Data, std::mutex> data_;
   /**
    * messageReady_ is signaled by writer threads whenever they add a new

folly/logging/CustomLogFormatter.h

+/*
+ * Copyright 2017-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/logging/LogFormatter.h>
+#include <string>
+
+namespace folly {
+
+/**
+ * A LogFormatter implementation that produces messages in a format specified
+ * using a config.
+ *
+ * The glog message format is:
+ *
+ *   {L}{m:02d}{D:02d} {H:2d}:{M:02d}:{S:02d}.{USECS:06d} {THREAD:5d}
+ *   {FILE}:{LINE}]
+ *
+ * L:  A 1-character code describing the log level (e.g., E, W, I, V)
+ * m: month
+ * D: day
+ * H: hour, 24-hour format
+ * M: minute
+ * S: second
+ * USECS: microseconds
+ * THREAD: Thread ID
+ * FILE: Filename (just the last component)
+ * FUN: The function that logged the message
+ * LINE: Line number
+ *
+ * TODO: enable support for the following 2:
+ *   - THREADNAME: the thread name.
+ *   - THREADCTX: thread-local log context data, if it has been set.  (This is
+ *                a Facebook-specific modification)
+ */
+class CustomLogFormatter : public LogFormatter {
+ public:
+  explicit CustomLogFormatter(StringPiece format, bool colored);
+  std::string formatMessage(
+      const LogMessage& message,
+      const LogCategory* handlerCategory) override;
+
+ private:
+  void parseFormatString(StringPiece format);
+
+  std::string logFormat_;
+  std::string singleLineLogFormat_;
+  std::size_t staticEstimatedWidth_{0};
+  std::size_t fileNameCount_{0};
+  std::size_t functionNameCount_{0};
+  const bool colored_;
+};
+} // namespace folly

folly/logging/GlogStyleFormatter.cpp

@@ -33,8 +33,10 @@ StringPiece getGlogLevelName(LogLevel level) {
     return "WARNING";
   } else if (level < LogLevel::CRITICAL) {
     return "ERROR";
-  }
+  } else if (level < LogLevel::DFATAL) {
     return "CRITICAL";
+  }
+  return "FATAL";
 }
 } // namespace
 

folly/logging/ImmediateFileWriter.cpp

@@ -18,6 +18,7 @@
 #include <folly/FileUtil.h>
 #include <folly/String.h>
 #include <folly/logging/LoggerDB.h>
+#include <folly/portability/Unistd.h>
 
 using folly::StringPiece;
 

folly/logging/ImmediateFileWriter.h

@@ -50,6 +50,13 @@ class ImmediateFileWriter : public LogWriter {
   void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) override;
   void flush() override;
 
+  /**
+   * Returns true if the output steam is a tty.
+   */
+  bool ttyOutput() const override {
+    return isatty(file_.fd());
+  }
+
   /**
    * Get the output file.
    */

folly/logging/LogWriter.h

@@ -72,5 +72,10 @@ class LogWriter {
    * will not necessarily be processed by the flush call.
    */
   virtual void flush() = 0;
+
+  /**
+   * Is the log writer writing to a tty or not.
+   */
+  virtual bool ttyOutput() const = 0;
 };
 } // namespace folly

folly/logging/StandardLogHandlerFactory.cpp

@@ -17,12 +17,15 @@
 
 #include <folly/MapUtil.h>
 #include <folly/String.h>
+#include <folly/logging/CustomLogFormatter.h>
 #include <folly/logging/GlogStyleFormatter.h>
+#include <folly/logging/LogWriter.h>
 #include <folly/logging/StandardLogHandler.h>
 
 using std::string;
 
 namespace folly {
+namespace {
 
 class GlogFormatterFactory
     : public StandardLogHandlerFactory::FormatterFactory {
@@ -30,11 +33,62 @@ class GlogFormatterFactory
   bool processOption(StringPiece /* name */, StringPiece /* value */) override {
     return false;
   }
-  std::shared_ptr<LogFormatter> createFormatter() override {
+  std::shared_ptr<LogFormatter> createFormatter(
+      const std::shared_ptr<LogWriter>& /* logWriter */) override {
     return std::make_shared<GlogStyleFormatter>();
   }
 };
 
+class CustomLogFormatterFactory
+    : public StandardLogHandlerFactory::FormatterFactory {
+ public:
+  enum Colored { ALWAYS, AUTO, NEVER };
+
+  bool processOption(StringPiece name, StringPiece value) override {
+    if (name == "log_format") {
+      format_ = value.str();
+      return true;
+    } else if (name == "colored") {
+      if (value == "always") {
+        colored_ = ALWAYS;
+      } else if (value == "auto") {
+        colored_ = AUTO;
+      } else if (value == "never") {
+        colored_ = NEVER;
+      } else {
+        throw std::invalid_argument(to<string>(
+            "unknown colored type \"",
+            value,
+            "\". Needs to be always/never/auto"));
+      }
+      return true;
+    }
+    return false;
+  }
+
+  std::shared_ptr<LogFormatter> createFormatter(
+      const std::shared_ptr<LogWriter>& logWriter) override {
+    bool colored;
+    switch (colored_) {
+      case ALWAYS:
+        colored = true;
+        break;
+      case AUTO:
+        colored = logWriter->ttyOutput();
+        break;
+      case NEVER:
+        colored = false;
+        break;
+    }
+    return std::make_shared<CustomLogFormatter>(format_, colored);
+  }
+
+ private:
+  std::string format_;
+  Colored colored_{NEVER}; // Turn off coloring by default.
+};
+} // namespace
+
 std::shared_ptr<StandardLogHandler> StandardLogHandlerFactory::createHandler(
     StringPiece type,
     WriterFactory* writerFactory,
@@ -45,6 +99,8 @@ std::shared_ptr<StandardLogHandler> StandardLogHandlerFactory::createHandler(
   auto* formatterType = get_ptr(options, "formatter");
   if (!formatterType || *formatterType == "glog") {
     formatterFactory = std::make_unique<GlogFormatterFactory>();
+  } else if (!formatterType || *formatterType == "custom") {
+    formatterFactory = std::make_unique<CustomLogFormatterFactory>();
   } else {
     throw std::invalid_argument(
         to<string>("unknown log formatter type \"", *formatterType, "\""));
@@ -96,8 +152,8 @@ std::shared_ptr<StandardLogHandler> StandardLogHandlerFactory::createHandler(
   }
 
   // Construct the formatter and writer
-  auto formatter = formatterFactory->createFormatter();
   auto writer = writerFactory->createWriter();
+  auto formatter = formatterFactory->createFormatter(writer);
 
   if (syncLevel) {
     return std::make_shared<StandardLogHandler>(

folly/logging/StandardLogHandlerFactory.h

@@ -53,7 +53,8 @@ class StandardLogHandlerFactory {
 
   class FormatterFactory : public OptionProcessor {
    public:
-    virtual std::shared_ptr<LogFormatter> createFormatter() = 0;
+    virtual std::shared_ptr<LogFormatter> createFormatter(
+        const std::shared_ptr<LogWriter>& logWriter) = 0;
   };
 
   class WriterFactory : public OptionProcessor {

folly/logging/test/CustomLogFormatterTest.cpp

+/*
+ * Copyright 2017-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/init/Init.h>
+#include <folly/logging/CustomLogFormatter.h>
+#include <folly/logging/LogMessage.h>
+#include <folly/logging/Logger.h>
+#include <folly/logging/LoggerDB.h>
+#include <folly/portability/GTest.h>
+#include <folly/portability/Stdlib.h>
+
+using namespace folly;
+
+namespace {
+
+const std::string kGlogFormatString =
+    "{L}{m:02d}{D:02d} {H:2d}:{M:02d}:{S:02d}.{USECS:06d} "
+    "{THREAD:5d} {FILE}:{LINE}]";
+
+const std::string kGlogFormatStringWithFunctionName =
+    "{L}{m:02d}{D:02d} {H:2d}:{M:02d}:{S:02d}.{USECS:06d} "
+    "{THREAD:5d} {FILE}:{LINE} {FUN}()]";
+
+/**
+ * Helper function to format a LogMessage using the CustomLogFormatter.
+ *
+ * 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(
+    StringPiece formatString,
+    LogLevel level,
+    StringPiece msg,
+    StringPiece filename,
+    StringPiece functionName,
+    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");
+  CustomLogFormatter formatter{formatString, false};
+
+  std::chrono::system_clock::time_point logTimePoint{
+      std::chrono::duration_cast<std::chrono::system_clock::duration>(
+          std::chrono::nanoseconds{timestampNS})};
+  LogMessage logMessage{category,
+                        level,
+                        logTimePoint,
+                        filename,
+                        lineNumber,
+                        functionName,
+                        msg.str()};
+
+  return formatter.formatMessage(logMessage, category);
+}
+} // namespace
+
+TEST(CustomLogFormatter, 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(
+          kGlogFormatString,
+          LogLevel::WARN,
+          "hello world",
+          "myfile.cpp",
+          "testFunction",
+          1234));
+}
+
+TEST(CustomLogFormatter, 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(
+          kGlogFormatString,
+          LogLevel::WARN,
+          "hello world",
+          "src/test/logging/code/myfile.cpp",
+          "testFunction",
+          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(
+          kGlogFormatString,
+          LogLevel::WARN,
+          "oh noes",
+          "this_is_a_really_long_file_name_that_will_probably_exceed_"
+          "our_buffer_allocation_guess.cpp",
+          "testFunction",
+          123456789));
+}
+
+TEST(CustomLogFormatter, functionName) {
+  auto tid = getOSThreadID();
+
+  // Make sure the function name gets logged
+  auto expected = folly::sformat(
+      "W0417 13:45:56.123456 {:5d} myfile.cpp:1234 testFunction()] "
+      "hello world\n",
+      tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          kGlogFormatStringWithFunctionName,
+          LogLevel::WARN,
+          "hello world",
+          "src/test/logging/code/myfile.cpp",
+          "testFunction",
+          1234));
+}
+
+TEST(CustomLogFormatter, 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(
+          kGlogFormatString,
+          LogLevel::DBG9,
+          "Eeek, a mouse!\n"
+          "   .   .\n"
+          "  ( ).( )\n"
+          "   (o o) .-._.'\n"
+          "  (  -  )\n"
+          "   mm mm\n"
+          "\n"
+          "=============",
+          "src/rodent.cpp",
+          "testFunction",
+          777));
+}
+
+TEST(CustomLogFormatter, 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(
+          kGlogFormatString,
+          LogLevel::DBG9,
+          "\n",
+          "foo.txt",
+          "testFunction",
+          123));
+}
+
+TEST(CustomLogFormatter, 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(
+          kGlogFormatString,
+          LogLevel::ERR,
+          "foo\abar\x1btest",
+          "escapes.cpp",
+          "testFunction",
+          97));
+  expected = folly::sformat(
+      "I0417 13:45:56.123456 {:5d} escapes.cpp:98] foo\\\\bar\"test\n", tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          kGlogFormatString,
+          LogLevel::INFO,
+          "foo\\bar\"test",
+          "escapes.cpp",
+          "testFunction",
+          98));
+  expected = folly::sformat(
+      "C0417 13:45:56.123456 {:5d} escapes.cpp:99] nul\\x00byte\n", tid);
+  EXPECT_EQ(
+      expected,
+      formatMsg(
+          kGlogFormatString,
+          LogLevel::CRITICAL,
+          std::string("nul\0byte", 8),
+          "escapes.cpp",
+          "testFunction",
+          99));
+}
+
+TEST(CustomLogFormatter, invalidFormatStrings) {
+  EXPECT_THROW(CustomLogFormatter("{", false), std::runtime_error);
+  EXPECT_THROW(CustomLogFormatter("{}", false), std::runtime_error);
+  EXPECT_THROW(CustomLogFormatter("{0}", false), std::runtime_error);
+  EXPECT_THROW(CustomLogFormatter("{WRONG}", false), std::runtime_error);
+  EXPECT_THROW(CustomLogFormatter("{L} {FORMAT}", false), std::runtime_error);
+  EXPECT_THROW(CustomLogFormatter("{L}{m:1} {KEY}", false), std::runtime_error);
+  EXPECT_THROW(CustomLogFormatter("{L", false), std::runtime_error);
+}
+
+TEST(CustomLogFormatter, validFormatStringsEdgeCases) {
+  EXPECT_EQ("msg\n", formatMsg("", LogLevel::INFO, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "I msg\n", formatMsg("{L}", LogLevel::INFO, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "{L} msg\n",
+      formatMsg("{{L}}", LogLevel::INFO, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "E:099 msg\n",
+      formatMsg("{L}:{LINE:03}", LogLevel::ERR, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "{L}:099 msg\n",
+      formatMsg("{{L}}:{LINE:03}", LogLevel::ERR, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "E:099{ msg\n",
+      formatMsg("{L}:{LINE:03}{{", LogLevel::ERR, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "E:099} msg\n",
+      formatMsg("{L}:{LINE:03}}}", LogLevel::ERR, "msg", "file", "fun", 99));
+  EXPECT_EQ(
+      "{E} msg\n",
+      formatMsg("{{{L}}}", LogLevel::ERR, "msg", "file", "fun", 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();
+}

folly/logging/test/StandardLogHandlerTest.cpp

@@ -64,6 +64,10 @@ class TestLogWriter : public LogWriter {
     return messages_;
   }
 
+  bool ttyOutput() const override {
+    return false;
+  }
+
  private:
   std::vector<std::string> messages_;
 };

folly/logging/test/SyncLevelTest.cpp

@@ -42,6 +42,10 @@ class TestLogWriter : public LogWriter {
 
   int flushed_messages_count{0};
   int unflushed_messages_count{0};
+
+  bool ttyOutput() const override {
+    return false;
+  }
 };
 
 class TestHandlerFactory : public LogHandlerFactory {

folly/logging/test/fatal_test.py

@@ -73,7 +73,7 @@ class FatalTests(unittest.TestCase):
 
     def get_crash_regex(self, msg=b"test program crashing!", glog=True):
         if glog:
-            prefix = br"^C[0-9]{4} .* FatalHelper.cpp:[0-9]+\] "
+            prefix = br"^F[0-9]{4} .* FatalHelper.cpp:[0-9]+\] "
         else:
             prefix = br"^FATAL:.*FatalHelper.cpp:[0-9]+: "
         regex = prefix + re.escape(msg) + b"$"
@@ -106,7 +106,7 @@ class FatalTests(unittest.TestCase):
     def test_other_category(self):
         err = self.run_helper("--category=foo.bar", "--logging", ".=FATAL")
         regex = re.compile(
-            br"^C[0-9]{4} .* FatalHelper.cpp:[0-9]+\] "
+            br"^F[0-9]{4} .* FatalHelper.cpp:[0-9]+\] "
             br"crashing to category foo\.bar$",
             re.MULTILINE,
         )