logging: update initialization code to use the new LogConfig logic

Summary:
Replace the initLoggingGlogStyle() function with a more generic initLogging()
function that accepts a log config string to be parsed with parseLogConfig().

Reviewed By: bolinfest, yfeldblum

Differential Revision: D6342086

fbshipit-source-id: fb1bffd11f190b70e03e2ccbf2b30be08d655242

folly/experimental/logging/Init.cpp

@@ -15,66 +15,58 @@
  */
 #include <folly/experimental/logging/Init.h>
 
-#include <folly/experimental/logging/AsyncFileWriter.h>
-#include <folly/experimental/logging/GlogStyleFormatter.h>
-#include <folly/experimental/logging/ImmediateFileWriter.h>
-#include <folly/experimental/logging/LogCategory.h>
-#include <folly/experimental/logging/LogHandlerConfig.h>
+#include <folly/experimental/logging/FileHandlerFactory.h>
+#include <folly/experimental/logging/LogConfig.h>
+#include <folly/experimental/logging/LogConfigParser.h>
 #include <folly/experimental/logging/LoggerDB.h>
-#include <folly/experimental/logging/StandardLogHandler.h>
-
-using std::shared_ptr;
-using std::string;
-using std::vector;
 
 namespace folly {
 
-void initLogLevels(StringPiece configString, LogLevel defaultRootLevel) {
-  // Set the default root category log level first
-  LoggerDB::get()->getCategory(".")->setLevel(defaultRootLevel);
+/**
+ * The base logging settings to be applied in initLogging(),
+ * before any user-specified settings.
+ *
+ * This defines a log handler named "default" that writes to stderr,
+ * and configures the root log category to log to this handler and have a log
+ * level setting of WARN.
+ *
+ * Note that the default log handler uses async=false, so that log messages are
+ * written immediately to stderr from the thread that generated the log
+ * message.  This is often undesirable, as it can slow down normal processing
+ * waiting for logging I/O.  However, using async=true has some trade-offs of
+ * its own: it causes a new thread to be started, and not all message may get
+ * flushed to stderr if the program crashes.  For now, using async=false seems
+ * like the safer trade-off here, but many programs may wish to change this
+ * default.
+ *
+ * The user-specified config string may override any of these values.
+ * If the user-specified config string ends up not using the default log
+ * handler, the handler will be automatically forgotten by the LoggerDB code.
+ */
+constexpr StringPiece kDefaultLoggingConfig =
+    ".=WARN:default; default=file,stream=stderr,async=false";
 
-  // Then apply the configuration string
-  if (!configString.empty()) {
-    auto ret = LoggerDB::get()->processConfigString(configString);
-    if (!ret.empty()) {
-      throw LoggingConfigError(ret);
-    }
-  }
-}
+void initLogging(StringPiece configString) {
+  // Register the FileHandlerFactory
+  //
+  // TODO: In the future it would be nice to build a better mechanism so that
+  // additional LogHandlerFactory objects could be automatically registered on
+  // startup if they are linked into our current executable.
+  LoggerDB::get()->registerHandlerFactory(
+      std::make_unique<FileHandlerFactory>());
 
-void initLoggingGlogStyle(
-    StringPiece configString,
-    LogLevel defaultRootLevel,
-    bool asyncWrites) {
-  // Configure log levels
-  initLogLevels(configString, defaultRootLevel);
+  // Parse the default log level settings before processing the input config
+  // string.
+  auto config = parseLogConfig(kDefaultLoggingConfig);
 
-  // Create the LogHandler
-  std::shared_ptr<LogWriter> writer;
-  folly::File file{STDERR_FILENO, false};
-  LogHandlerConfig handlerConfig{"file", {{"stream", "stderr"}}};
-  if (asyncWrites) {
-    writer = std::make_shared<AsyncFileWriter>(std::move(file));
-    handlerConfig.options.emplace("async", "true");
-  } else {
-    writer = std::make_shared<ImmediateFileWriter>(std::move(file));
-    handlerConfig.options.emplace("async", "false");
+  // Then apply the configuration string
+  if (!configString.empty()) {
+    auto inputConfig = parseLogConfig(configString);
+    config.update(inputConfig);
   }
-  auto handler = std::make_shared<StandardLogHandler>(
-      handlerConfig, std::make_shared<GlogStyleFormatter>(), std::move(writer));
 
-  // Add the handler to the root category.
-  LoggerDB::get()->getCategory(".")->addHandler(std::move(handler));
+  // Now apply the configuration to the LoggerDB
+  LoggerDB::get()->updateConfig(config);
 }
 
-LoggingConfigError::LoggingConfigError(const vector<string>& errors)
-    : invalid_argument{computeMessage(errors)} {}
-
-std::string LoggingConfigError::computeMessage(const vector<string>& errors) {
-  string msg = "error parsing logging configuration:";
-  for (const auto& error : errors) {
-    msg += "\n" + error;
-  }
-  return msg;
-}
 } // namespace folly

folly/experimental/logging/Init.h

@@ -20,46 +20,26 @@
  * during program start-up.
  */
 
-#include <stdexcept>
-#include <string>
-#include <vector>
-
 #include <folly/Range.h>
-#include <folly/experimental/logging/LogLevel.h>
 
 namespace folly {
 
 /**
- * Configure log category levels based on a configuration string.
+ * Initialize the logging library.
  *
- * This can be used to process a logging configuration string (such as received
- * via a command line flag) during program start-up.
- */
-void initLogLevels(
-    folly::StringPiece configString = "",
-    LogLevel defaultRootLevel = LogLevel::WARNING);
-
-/**
- * Initialize the logging library to write glog-style messages to stderr.
+ * The input string will be parsed with parseLogConfig() and then applied to
+ * the main LoggerDB singleton.
  *
- * This initializes the log category levels as specified (using
- * initLogLevels()), and adds a log handler that prints messages in glog-style
- * format to stderr.
- */
-void initLoggingGlogStyle(
-    folly::StringPiece configString = "",
-    LogLevel defaultRootLevel = LogLevel::WARNING,
-    bool asyncWrites = true);
-
-/**
- * LoggingConfigError may be thrown by initLogLevels() if an error occurs
- * parsing the configuration string.
+ * Before it is applied, the input configuration settings are first combined
+ * with some basic defaults on the root log category.  The defaults set the
+ * root log level to WARN, and attach a log handler named "default" that writes
+ * messages to stderr.  However, these base settings can be overridden if the
+ * input string specifies alternate settings for the root log category.
+ *
+ * Note that it is safe for code to use logging functions before calling
+ * initLogging().  However, messages logged before initLogging() is called will
+ * be ignored since no log handler objects have been defined.
  */
-class LoggingConfigError : public std::invalid_argument {
- public:
-  explicit LoggingConfigError(const std::vector<std::string>& errors);
+void initLogging(folly::StringPiece configString = "");
 
- private:
-  std::string computeMessage(const std::vector<std::string>& errors);
-};
 } // namespace folly

folly/experimental/logging/LoggerDB.cpp

@@ -107,40 +107,6 @@ void LoggerDB::setLevel(LogCategory* category, LogLevel level, bool inherit) {
   category->setLevelLocked(level, inherit);
 }
 
-std::vector<std::string> LoggerDB::processConfigString(
-    folly::StringPiece config) {
-  std::vector<std::string> errors;
-  if (config.empty()) {
-    return errors;
-  }
-
-  std::vector<StringPiece> pieces;
-  folly::split(",", config, pieces);
-  for (const auto& p : pieces) {
-    auto idx = p.rfind('=');
-    if (idx == folly::StringPiece::npos) {
-      errors.emplace_back(
-          folly::sformat("missing '=' in logger configuration: \"{}\"", p));
-      continue;
-    }
-
-    auto category = p.subpiece(0, idx);
-    auto level_str = p.subpiece(idx + 1);
-    LogLevel level;
-    try {
-      level = stringToLogLevel(level_str);
-    } catch (const std::exception&) {
-      errors.emplace_back(folly::sformat(
-          "invalid log level \"{}\" for category \"{}\"", level_str, category));
-      continue;
-    }
-
-    setLevel(category, level);
-  }
-
-  return errors;
-}
-
 LogConfig LoggerDB::getConfig() const {
   auto handlerInfo = handlerInfo_.rlock();
 

folly/experimental/logging/LoggerDB.h

@@ -111,18 +111,6 @@ class LoggerDB {
    */
   void resetConfig(const LogConfig& config);
 
-  /**
-   * Apply a configuration string specifying a series a log levels.
-   *
-   * The string format is a comma separated list of <name>=<level> sections.
-   * e.g.: "foo=DBG3,log.bar=WARN"
-   *
-   * Returns a list of error messages for each error encountered trying to
-   * parse the config string.  The return value will be an empty vector if no
-   * errors were encountered.
-   */
-  std::vector<std::string> processConfigString(folly::StringPiece config);
-
   /**
    * Remove all registered LogHandlers on all LogCategory objects.
    *

folly/experimental/logging/example/main.cpp

@@ -38,7 +38,7 @@ int main(int argc, char* argv[]) {
 
   // Call folly::init() and then initialize log levels and handlers
   folly::init(&argc, &argv);
-  initLoggingGlogStyle(FLAGS_logging, LogLevel::INFO);
+  folly::initLogging(FLAGS_logging);
 
   // All XLOG() statements in this file will log to the category
   // folly.experimental.logging.example.main

folly/experimental/logging/test/AsyncFileWriterTest.cpp

@@ -615,8 +615,7 @@ TEST(AsyncFileWriter, discard) {
 int main(int argc, char* argv[]) {
   testing::InitGoogleTest(&argc, argv);
   folly::init(&argc, &argv);
-  // Don't use async logging in the async logging tests :-)
-  folly::initLoggingGlogStyle(FLAGS_logging, LogLevel::INFO, /* async */ false);
+  folly::initLogging(FLAGS_logging);
 
   return RUN_ALL_TESTS();
 }

folly/experimental/logging/test/FatalHelper.cpp

@@ -19,10 +19,6 @@
 #include <folly/portability/Stdlib.h>
 
 DEFINE_string(logging, "", "Logging category configuration string");
-DEFINE_string(
-    handler_style,
-    "async",
-    "Log handler style: async, immediate, or none");
 
 DEFINE_string(
     category,
@@ -61,14 +57,6 @@ static InitChecker initChecker;
 
 namespace {
 int runHelper() {
-  if (FLAGS_handler_style == "async") {
-    initLoggingGlogStyle(FLAGS_logging, LogLevel::INFO, true);
-  } else if (FLAGS_handler_style == "immediate") {
-    initLoggingGlogStyle(FLAGS_logging, LogLevel::INFO, false);
-  } else if (FLAGS_handler_style != "none") {
-    XLOGF(FATAL, "unknown log handler style \"{}\"", FLAGS_handler_style);
-  }
-
   if (!FLAGS_category.empty()) {
     folly::Logger logger{FLAGS_category};
     FB_LOG(logger, FATAL, "crashing to category ", FLAGS_category);
@@ -98,6 +86,7 @@ std::string fbLogFatalCheck() {
 int main(int argc, char* argv[]) {
   // Call folly::init() and then initialize log levels and handlers
   folly::init(&argc, &argv);
+  folly::initLogging(FLAGS_logging);
 
   // Do most of the work in a separate helper function.
   //

folly/experimental/logging/test/LoggerDBTest.cpp

@@ -73,27 +73,3 @@ TEST(LoggerDB, flushAllHandlers) {
   EXPECT_EQ(2, h2->getFlushCount());
   EXPECT_EQ(2, h3->getFlushCount());
 }
-
-TEST(LoggerDB, processConfigString) {
-  LoggerDB db{LoggerDB::TESTING};
-  db.processConfigString("foo.bar=dbg5");
-  EXPECT_EQ(LogLevel::DBG5, db.getCategory("foo.bar")->getLevel());
-  EXPECT_EQ(LogLevel::DBG5, db.getCategory("foo.bar")->getEffectiveLevel());
-  EXPECT_EQ(LogLevel::MAX_LEVEL, db.getCategory("foo")->getLevel());
-  EXPECT_EQ(LogLevel::ERR, db.getCategory("foo")->getEffectiveLevel());
-  EXPECT_EQ(LogLevel::ERR, db.getCategory("")->getLevel());
-  EXPECT_EQ(LogLevel::ERR, db.getCategory("")->getEffectiveLevel());
-
-  EXPECT_EQ(LogLevel::MAX_LEVEL, db.getCategory("foo.bar.test")->getLevel());
-  EXPECT_EQ(
-      LogLevel::DBG5, db.getCategory("foo.bar.test")->getEffectiveLevel());
-
-  db.processConfigString("sys=warn,foo.test=debug,foo.test.stuff=warn");
-  EXPECT_EQ(LogLevel::WARN, db.getCategory("sys")->getLevel());
-  EXPECT_EQ(LogLevel::WARN, db.getCategory("sys")->getEffectiveLevel());
-  EXPECT_EQ(LogLevel::DEBUG, db.getCategory("foo.test")->getLevel());
-  EXPECT_EQ(LogLevel::DEBUG, db.getCategory("foo.test")->getEffectiveLevel());
-  EXPECT_EQ(LogLevel::WARN, db.getCategory("foo.test.stuff")->getLevel());
-  EXPECT_EQ(
-      LogLevel::DEBUG, db.getCategory("foo.test.stuff")->getEffectiveLevel());
-}

folly/experimental/logging/test/fatal_test.py

@@ -69,17 +69,19 @@ class FatalTests(unittest.TestCase):
         subprocess.check_output([self.helper, '--crash=no'])
 
     def test_async(self):
-        err = self.run_helper('--handler_style=async')
+        handler_setings = 'default=file,stream=stderr,async=true'
+        err = self.run_helper('--logging=;' + handler_setings)
         self.assertRegex(err, self.get_crash_regex())
 
     def test_immediate(self):
-        err = self.run_helper('--handler_style=immediate')
+        handler_setings = 'default=file,stream=stderr,async=false'
+        err = self.run_helper('--logging=;' + handler_setings)
         self.assertRegex(err, self.get_crash_regex())
 
     def test_none(self):
         # The fatal message should be printed directly to stderr when there
         # are no logging handlers configured.
-        err = self.run_helper('--handler_style=none')
+        err = self.run_helper('--logging=ERR:')
         self.assertRegex(err, self.get_crash_regex(glog=False))
 
     def test_other_category(self):