Add sync_level option to the logging config

Summary:
GLOG has `-logbuflevel` option that allows a user to specify the level above which none of the logs should be buffered. This is helpful as we can configure it such that `INFO` and all verbose logs are buffered before being output, but all logs above `INFO` should be flushed synchronously. This will ensure that all logs above a certain level are printed before any sort of crash.

This diff allows a user to specify a config `sync_level`. The value for this can be any `LogLevel`. Example config:

  .=WARN,akkio.cli=INFO; default:async=true,sync_level=WARN

The default value for GLOG's -logbuflevel is `0` (`INFO`).
To match GLOG's behavior, this diff sets the following as defaults:

  async=true,sync_level=WARN

Reviewed By: simpkins

Differential Revision: D8867555

fbshipit-source-id: 7ec30dfb41b2f3cd3568d70304db7a9fcf668779

folly/logging/StandardLogHandler.cpp

@@ -24,8 +24,10 @@ namespace folly {
 StandardLogHandler::StandardLogHandler(
     LogHandlerConfig config,
     std::shared_ptr<LogFormatter> formatter,
-    std::shared_ptr<LogWriter> writer)
-    : formatter_{std::move(formatter)},
+    std::shared_ptr<LogWriter> writer,
+    LogLevel syncLevel)
+    : syncLevel_(syncLevel),
+      formatter_{std::move(formatter)},
       writer_{std::move(writer)},
       config_{config} {}
 
@@ -38,6 +40,9 @@ void StandardLogHandler::handleMessage(
     return;
   }
   writer_->writeMessage(formatter_->formatMessage(message, handlerCategory));
+  if (message.getLevel() >= syncLevel_.load(std::memory_order_relaxed)) {
+    flush();
+  }
 }
 
 void StandardLogHandler::flush() {

folly/logging/StandardLogHandler.h

@@ -43,7 +43,8 @@ class StandardLogHandler : public LogHandler {
   StandardLogHandler(
       LogHandlerConfig config,
       std::shared_ptr<LogFormatter> formatter,
-      std::shared_ptr<LogWriter> writer);
+      std::shared_ptr<LogWriter> writer,
+      LogLevel syncLevel = LogLevel::MAX_LEVEL);
   ~StandardLogHandler();
 
   /**
@@ -89,6 +90,7 @@ class StandardLogHandler : public LogHandler {
 
  private:
   std::atomic<LogLevel> level_{LogLevel::NONE};
+  std::atomic<LogLevel> syncLevel_{LogLevel::MAX_LEVEL};
 
   // The following variables are const, and cannot be modified after the
   // log handler is constructed.  This allows us to access them without

folly/logging/StandardLogHandlerFactory.cpp

@@ -50,6 +50,8 @@ std::shared_ptr<StandardLogHandler> StandardLogHandlerFactory::createHandler(
         to<string>("unknown log formatter type \"", *formatterType, "\""));
   }
 
+  Optional<LogLevel> syncLevel;
+
   // Process the log formatter and log handler options
   std::vector<string> errors;
   for (const auto& entry : options) {
@@ -69,6 +71,20 @@ std::shared_ptr<StandardLogHandler> StandardLogHandlerFactory::createHandler(
     // We explicitly processed the "formatter" option above.
     handled |= handled || (entry.first == "formatter");
 
+    // Process the "sync_level" option.
+    if (entry.first == "sync_level") {
+      try {
+        syncLevel = stringToLogLevel(entry.second);
+      } catch (const std::exception& ex) {
+        errors.push_back(to<string>(
+            "unable to parse value for option \"",
+            entry.first,
+            "\": ",
+            ex.what()));
+      }
+      handled = true;
+    }
+
     // Complain about unknown options.
     if (!handled) {
       errors.push_back(to<string>("unknown option \"", entry.first, "\""));
@@ -83,8 +99,13 @@ std::shared_ptr<StandardLogHandler> StandardLogHandlerFactory::createHandler(
   auto formatter = formatterFactory->createFormatter();
   auto writer = writerFactory->createWriter();
 
+  if (syncLevel) {
+    return std::make_shared<StandardLogHandler>(
+        LogHandlerConfig{type, options}, formatter, writer, *syncLevel);
+  } else {
     return std::make_shared<StandardLogHandler>(
         LogHandlerConfig{type, options}, formatter, writer);
+  }
 }
 
 } // namespace folly

folly/logging/docs/Config.md

@@ -203,6 +203,15 @@ Example log configuration strings:
   `LoggerDB::updateConfig()`, and cannot be used with
   `LoggerDB::resetConfig()`.
 
+* `INFO; default:async=true,sync_level=WARN`  
+
+  Sets the root log category level to INFO, and sets the "async" property to
+  true and "sync_level" property to WARN. Setting "async" property ensures that
+  we enable asynchronous logging but the "sync_level" flag specifies that all
+  logs of the level WARN and above are processed synchronously. This can help
+  ensure that all logs of the level WARN or above are persisted before a
+  potential crash while ensuring that all logs below the level WARN are
+  non-blocking.
 
 JSON Configuration Syntax
 -------------------------
@@ -285,6 +294,7 @@ following fields:
       "options": {
         "stream": "stderr",
         "async": true,
+        "sync_level": "WARN",
         "max_buffer_size": 4096000
       }
     }

folly/logging/docs/Overview.md

@@ -77,7 +77,11 @@ suddenly makes your code log more messages than normal.
 
 This behavior is easily configurable, so that you can choose the best trade-off
 for your program (possibly dropping some messages vs possibly blocking threads
-on logging I/O).
+on logging I/O). When using asynchronous logging, you also have the option to
+specify levels above which you would like to enable synchronous logging.
+This can help ensure that all logs of a certain level or above are persisted
+before a potential crash while ensuring that all logs below that level remain
+non-blocking.
 
 ## Support for folly::format()
 

folly/logging/example/main.cpp

@@ -28,8 +28,10 @@ static ExampleObject staticInitialized("static");
 // Configure folly to enable INFO+ messages, and everything else to
 // enable WARNING+.
 //
-// Set the default log handler to log asynchronously by default.
-FOLLY_INIT_LOGGING_CONFIG(".=WARNING,folly=INFO; default:async=true");
+// Set the default log handler to log asynchronously by default
+// (except log messages with level WARNING and above synchronously)
+FOLLY_INIT_LOGGING_CONFIG(
+    ".=WARNING,folly=INFO; default:async=true,sync_level=WARNING");
 
 int main(int argc, char* argv[]) {
   // Using log macros before calling folly::initLogging() will use the default

folly/logging/test/SyncLevelTest.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 <folly/test/TestUtils.h>
+#include <queue>
+
+#include <folly/logging/Init.h>
+#include <folly/logging/LogConfigParser.h>
+#include <folly/logging/LogHandlerFactory.h>
+#include <folly/logging/LogWriter.h>
+#include <folly/logging/LoggerDB.h>
+#include <folly/logging/StandardLogHandler.h>
+#include <folly/logging/StandardLogHandlerFactory.h>
+#include <folly/logging/xlog.h>
+
+namespace folly {
+
+class TestLogWriter : public LogWriter {
+ public:
+  void writeMessage(folly::StringPiece /* buffer */, uint32_t /* flags */ = 0)
+      override {
+    unflushed_messages_count++;
+  }
+
+  void flush() override {
+    flushed_messages_count += unflushed_messages_count;
+    unflushed_messages_count = 0;
+  }
+
+  int flushed_messages_count{0};
+  int unflushed_messages_count{0};
+};
+
+class TestHandlerFactory : public LogHandlerFactory {
+ public:
+  TestHandlerFactory(const std::shared_ptr<TestLogWriter> writer)
+      : writer_(writer) {}
+
+  StringPiece getType() const override {
+    return "test";
+  }
+
+  std::shared_ptr<LogHandler> createHandler(const Options& options) override {
+    TestWriterFactory writerFactory{writer_};
+    return StandardLogHandlerFactory::createHandler(
+        getType(), &writerFactory, options);
+  }
+
+ private:
+  std::shared_ptr<TestLogWriter> writer_;
+  class TestWriterFactory : public StandardLogHandlerFactory::WriterFactory {
+   public:
+    TestWriterFactory(std::shared_ptr<TestLogWriter> writer)
+        : writer_(writer) {}
+
+    bool processOption(StringPiece /* name */, StringPiece /* value */)
+        override {
+      return false;
+    }
+
+    std::shared_ptr<LogWriter> createWriter() override {
+      return writer_;
+    }
+
+   private:
+    std::shared_ptr<TestLogWriter> writer_;
+  };
+};
+
+} // namespace folly
+
+using namespace folly;
+
+namespace {
+class SyncLevelTest : public testing::Test {
+ public:
+  SyncLevelTest() {
+    writer = std::make_shared<TestLogWriter>();
+    db.registerHandlerFactory(
+        std::make_unique<TestHandlerFactory>(writer), true);
+    db.resetConfig(
+        parseLogConfig("test=INFO:default; default=test:sync_level=WARN"));
+  }
+
+  LoggerDB db{LoggerDB::TESTING};
+  Logger logger{&db, "test"};
+  std::shared_ptr<TestLogWriter> writer;
+};
+} // namespace
+
+TEST_F(SyncLevelTest, NoLogTest) {
+  FB_LOG(logger, DBG9) << "DBG9";
+  FB_LOG(logger, DBG1) << "DBG1";
+  FB_LOG(logger, DBG0) << "DBG0";
+
+  EXPECT_EQ(writer->unflushed_messages_count, 0);
+  EXPECT_EQ(writer->flushed_messages_count, 0);
+}
+
+TEST_F(SyncLevelTest, SimpleAsyncTest) {
+  FB_LOG(logger, INFO) << "INFO";
+  FB_LOG(logger, INFO) << "INFO";
+  FB_LOG(logger, INFO) << "INFO";
+  FB_LOG(logger, INFO) << "INFO";
+
+  EXPECT_EQ(writer->unflushed_messages_count, 4);
+  EXPECT_EQ(writer->flushed_messages_count, 0);
+
+  FB_LOG(logger, WARN) << "WARN";
+
+  EXPECT_EQ(writer->unflushed_messages_count, 0);
+  EXPECT_EQ(writer->flushed_messages_count, 5);
+
+  FB_LOG(logger, DBG0) << "DBG0";
+  FB_LOG(logger, INFO9) << "INFO9";
+
+  EXPECT_EQ(writer->unflushed_messages_count, 1);
+  EXPECT_EQ(writer->flushed_messages_count, 5);
+
+  FB_LOG(logger, INFO) << "INFO";
+  FB_LOG(logger, WARN) << "WARN";
+
+  EXPECT_EQ(writer->unflushed_messages_count, 0);
+  EXPECT_EQ(writer->flushed_messages_count, 8);
+
+  FB_LOG(logger, INFO) << "INFO";
+  FB_LOG(logger, CRITICAL) << "CRITICAL";
+
+  EXPECT_EQ(writer->unflushed_messages_count, 0);
+  EXPECT_EQ(writer->flushed_messages_count, 10);
+}