logging: implement FATAL and DFATAL log levels
authorAdam Simpkins <simpkins@fb.com>
Tue, 20 Jun 2017 21:01:59 +0000 (14:01 -0700)
committerFacebook Github Bot <facebook-github-bot@users.noreply.github.com>
Tue, 20 Jun 2017 21:09:59 +0000 (14:09 -0700)
Summary:
Add new `FATAL` and `DFATAL` log levels.

Any log message with a level of `FATAL` always crashes the program.  Log
messages with a level of `DFATAL` crash the program in debug build modes.

Before crashing, the code makes sure to flush all LogHandlers, so that the
fatal message is not lost if some of the LogHandlers process messages
asynchronously.  If no LogHandlers were configured, the message is printed to
stderr.

Reviewed By: wez

Differential Revision: D5189497

fbshipit-source-id: c45dbd582fb1c3a962d00effb2967737ef97cc8b

13 files changed:
folly/experimental/logging/LogCategory.cpp
folly/experimental/logging/LogCategory.h
folly/experimental/logging/LogLevel.cpp
folly/experimental/logging/LogLevel.h
folly/experimental/logging/LogStreamProcessor.cpp
folly/experimental/logging/LogStreamProcessor.h
folly/experimental/logging/Logger.h
folly/experimental/logging/LoggerDB.cpp
folly/experimental/logging/LoggerDB.h
folly/experimental/logging/test/FatalHelper.cpp [new file with mode: 0644]
folly/experimental/logging/test/LogLevelTest.cpp
folly/experimental/logging/test/fatal_test.py [new file with mode: 0644]
folly/experimental/logging/xlog.h

index c475bf6..ff06ba5 100644 (file)
 #include <folly/experimental/logging/LogCategory.h>
 
 #include <cstdio>
+#include <cstdlib>
 
 #include <folly/ExceptionString.h>
+#include <folly/FileUtil.h>
 #include <folly/experimental/logging/LogHandler.h>
 #include <folly/experimental/logging/LogMessage.h>
 #include <folly/experimental/logging/LogName.h>
@@ -42,6 +44,31 @@ LogCategory::LogCategory(StringPiece name, LogCategory* parent)
   parent_->firstChild_ = this;
 }
 
+void LogCategory::admitMessage(const LogMessage& message) const {
+  processMessage(message);
+
+  // If this is a fatal message, flush the handlers to make sure the log
+  // message was written out, then crash.
+  if (isLogLevelFatal(message.getLevel())) {
+    auto numHandlers = db_->flushAllHandlers();
+    if (numHandlers == 0) {
+      // No log handlers were configured.
+      // Print the message to stderr, to make sure we always print the reason
+      // we are crashing somewhere.
+      auto msg = folly::to<std::string>(
+          "FATAL:",
+          message.getFileName(),
+          ":",
+          message.getLineNumber(),
+          ": ",
+          message.getMessage(),
+          "\n");
+      folly::writeFull(STDERR_FILENO, msg.data(), msg.size());
+    }
+    std::abort();
+  }
+}
+
 void LogCategory::processMessage(const LogMessage& message) const {
   // Make a copy of any attached LogHandlers, so we can release the handlers_
   // lock before holding them.
index d7989f4..ce97c91 100644 (file)
@@ -158,17 +158,15 @@ class LogCategory {
   /* Internal methods for use by other parts of the logging library code */
 
   /**
-   * Process a log message.
+   * Admit a message into the LogCategory hierarchy to be logged.
+   *
+   * The caller is responsible for having already performed log level
+   * admittance checks.
    *
    * This method generally should be invoked only through the logging macros,
    * rather than calling this directly.
-   *
-   * This method assumes that log level admittance checks have already been
-   * performed.  This method unconditionally passes the message to the
-   * LogHandlers attached to this LogCategory, without any additional log level
-   * checks (apart from the ones done in the LogHandlers).
    */
-  void processMessage(const LogMessage& message) const;
+  void admitMessage(const LogMessage& message) const;
 
   /**
    * Note: setLevelLocked() may only be called while holding the main
@@ -197,6 +195,7 @@ class LogCategory {
   LogCategory(LogCategory const&) = delete;
   LogCategory& operator=(LogCategory const&) = delete;
 
+  void processMessage(const LogMessage& message) const;
   void updateEffectiveLevel(LogLevel newEffectiveLevel);
   void parentLevelUpdated(LogLevel parentEffectiveLevel);
 
index 03e13d3..c16eadb 100644 (file)
@@ -59,6 +59,10 @@ LogLevel stringToLogLevel(StringPiece name) {
     return LogLevel::ERR;
   } else if (lowerName == "critical") {
     return LogLevel::CRITICAL;
+  } else if (lowerName == "dfatal") {
+    return LogLevel::DFATAL;
+  } else if (lowerName == "fatal") {
+    return LogLevel::FATAL;
   } else if (lowerName == "max" || lowerName == "max_level") {
     return LogLevel::MAX_LEVEL;
   }
@@ -96,8 +100,10 @@ string logLevelToString(LogLevel level) {
     return "LogLevel::ERR";
   } else if (level == LogLevel::CRITICAL) {
     return "LogLevel::CRITICAL";
-  } else if (level == LogLevel::MAX_LEVEL) {
-    return "LogLevel::MAX_LEVEL";
+  } else if (level == LogLevel::DFATAL) {
+    return "LogLevel::DFATAL";
+  } else if (level == LogLevel::FATAL) {
+    return "LogLevel::FATAL";
   }
 
   if (static_cast<uint32_t>(level) <= static_cast<uint32_t>(LogLevel::DBG0) &&
index 05c1603..0c751b1 100644 (file)
@@ -18,7 +18,9 @@
 #include <cstdint>
 #include <iosfwd>
 #include <string>
+#include <type_traits>
 
+#include <folly/Portability.h>
 #include <folly/Range.h>
 
 namespace folly {
@@ -66,6 +68,12 @@ enum class LogLevel : uint32_t {
 
   CRITICAL = 5000,
 
+  // DFATAL log messages crash the program on debug builds.
+  DFATAL = 0x7ffffffe,
+  // FATAL log messages always abort the program.
+  // This level is equivalent to MAX_LEVEL.
+  FATAL = 0x7fffffff,
+
   // The most significant bit is used by LogCategory to store a flag value,
   // so the maximum value has that bit cleared.
   //
@@ -78,7 +86,7 @@ enum class LogLevel : uint32_t {
  * Support adding and subtracting integers from LogLevels, to create slightly
  * adjusted log level values.
  */
-inline LogLevel operator+(LogLevel level, uint32_t value) {
+inline constexpr LogLevel operator+(LogLevel level, uint32_t value) {
   auto newValue = static_cast<uint32_t>(level) + value;
   // Cap the result at LogLevel::MAX_LEVEL
   if (newValue > static_cast<uint32_t>(LogLevel::MAX_LEVEL)) {
@@ -90,7 +98,7 @@ inline LogLevel& operator+=(LogLevel& level, uint32_t value) {
   level = level + value;
   return level;
 }
-inline LogLevel operator-(LogLevel level, uint32_t value) {
+inline constexpr LogLevel operator-(LogLevel level, uint32_t value) {
   return static_cast<LogLevel>(static_cast<uint32_t>(level) - value);
 }
 inline LogLevel& operator-=(LogLevel& level, uint32_t value) {
@@ -112,4 +120,15 @@ std::string logLevelToString(LogLevel level);
  * Print a LogLevel in a human readable format.
  */
 std::ostream& operator<<(std::ostream& os, LogLevel level);
+
+/**
+ * Returns true if and only if a LogLevel is fatal.
+ */
+inline constexpr bool isLogLevelFatal(LogLevel level) {
+  if (folly::kIsDebug) {
+    return level >= LogLevel::DFATAL;
+  } else {
+    return level >= LogLevel::FATAL;
+  }
+}
 }
index 84c8e0d..f74f3a7 100644 (file)
@@ -21,7 +21,7 @@
 
 namespace folly {
 void LogStreamProcessor::operator&(std::ostream& stream) noexcept {
-  // Note that processMessage() is not noexcept and theoretically may throw.
+  // Note that admitMessage() is not noexcept and theoretically may throw.
   // However, the only exception that should be possible is std::bad_alloc if
   // we fail to allocate memory.  We intentionally let our noexcept specifier
   // crash in that case, since the program likely won't be able to continue
@@ -30,11 +30,11 @@ void LogStreamProcessor::operator&(std::ostream& stream) noexcept {
   // Any other error here is unexpected and we also want to fail hard
   // in that situation too.
   auto& logStream = static_cast<LogStream&>(stream);
-  category_->processMessage(LogMessage{category_,
-                                       level_,
-                                       filename_,
-                                       lineNumber_,
-                                       extractMessageString(logStream)});
+  category_->admitMessage(LogMessage{category_,
+                                     level_,
+                                     filename_,
+                                     lineNumber_,
+                                     extractMessageString(logStream)});
 }
 
 void LogStreamProcessor::operator&(LogStream&& stream) noexcept {
@@ -44,7 +44,7 @@ void LogStreamProcessor::operator&(LogStream&& stream) noexcept {
   // and just directly use message_.
   DCHECK(stream.empty());
 
-  category_->processMessage(LogMessage{
+  category_->admitMessage(LogMessage{
       category_, level_, filename_, lineNumber_, std::move(message_)});
 }
 
index f95e00e..bb24d4d 100644 (file)
@@ -20,6 +20,7 @@
 #include <folly/Format.h>
 #include <folly/experimental/logging/LogCategory.h>
 #include <folly/experimental/logging/LogMessage.h>
+#include <cstdlib>
 
 namespace folly {
 
@@ -253,4 +254,43 @@ class LogStreamProcessor {
   unsigned int lineNumber_;
   std::string message_;
 };
+
+/*
+ * This template subclass of LogStreamProcessor exists primarily so that
+ * we can specify the [[noreturn]] attribute correctly on operator&()
+ * This lets the compiler know that code after LOG(FATAL) is unreachable.
+ */
+template <bool Fatal>
+class LogStreamProcessorT : public LogStreamProcessor {
+ public:
+  using LogStreamProcessor::LogStreamProcessor;
+
+  void operator&(std::ostream& stream) noexcept {
+    LogStreamProcessor::operator&(stream);
+  }
+  void operator&(LogStream&& stream) noexcept {
+    LogStreamProcessor::operator&(std::move(stream));
+  }
+};
+
+template <>
+class LogStreamProcessorT<true> : public LogStreamProcessor {
+ public:
+  using LogStreamProcessor::LogStreamProcessor;
+
+  [[noreturn]] void operator&(std::ostream& stream) noexcept {
+    LogStreamProcessor::operator&(stream);
+    // We'll never actually reach here: the LogCategory code is responsible for
+    // crashing on FATAL messages.  However, add an abort() call so the
+    // compiler knows we really cannot return here.
+    std::abort();
+  }
+  [[noreturn]] void operator&(LogStream&& stream) noexcept {
+    LogStreamProcessor::operator&(std::move(stream));
+    // We'll never actually reach here: the LogCategory code is responsible for
+    // crashing on FATAL messages.  However, add an abort() call so the
+    // compiler knows we really cannot return here.
+    std::abort();
+  }
+};
 }
index ab9bd24..2fae9e2 100644 (file)
  *
  * This macro generally should not be used directly by end users.
  */
-#define FB_LOG_IMPL(logger, level, type, ...)               \
-  (!(logger).getCategory()->logCheck(level))                \
-      ? (void)0                                             \
-      : ::folly::LogStreamProcessor{(logger).getCategory(), \
-                                    (level),                \
-                                    __FILE__,               \
-                                    __LINE__,               \
-                                    (type),                 \
-                                    ##__VA_ARGS__} &        \
+#define FB_LOG_IMPL(logger, level, type, ...)                  \
+  (!(logger).getCategory()->logCheck(level))                   \
+      ? (void)0                                                \
+      : ::folly::LogStreamProcessorT<::folly::isLogLevelFatal( \
+            level)>{(logger).getCategory(),                    \
+                    (level),                                   \
+                    __FILE__,                                  \
+                    __LINE__,                                  \
+                    (type),                                    \
+                    ##__VA_ARGS__} &                           \
           ::folly::LogStream()
 
 /**
index 4c8d3a8..bd92a63 100644 (file)
@@ -178,7 +178,7 @@ void LoggerDB::cleanupHandlers() {
   }
 }
 
-void LoggerDB::flushAllHandlers() {
+size_t LoggerDB::flushAllHandlers() {
   // Build a set of all LogHandlers.  We use a set to avoid calling flush()
   // more than once on the same handler if it is registered on multiple
   // different categories.
@@ -196,6 +196,7 @@ void LoggerDB::flushAllHandlers() {
   for (const auto& handler : handlers) {
     handler->flush();
   }
+  return handlers.size();
 }
 
 LogLevel LoggerDB::xlogInit(
index 9580b74..0f7fed2 100644 (file)
@@ -94,8 +94,10 @@ class LoggerDB {
   /**
    * Call flush() on all LogHandler objects registered on any LogCategory in
    * this LoggerDB.
+   *
+   * Returns the number of registered LogHandlers.
    */
-  void flushAllHandlers();
+  size_t flushAllHandlers();
 
   /**
    * Initialize the LogCategory* and std::atomic<LogLevel> used by an XLOG()
diff --git a/folly/experimental/logging/test/FatalHelper.cpp b/folly/experimental/logging/test/FatalHelper.cpp
new file mode 100644 (file)
index 0000000..e89ef2c
--- /dev/null
@@ -0,0 +1,57 @@
+/*
+ * 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/Init.h>
+#include <folly/experimental/logging/xlog.h>
+#include <folly/init/Init.h>
+
+DEFINE_string(logging, "", "Logging category configuration string");
+DEFINE_string(
+    handler_style,
+    "async",
+    "Log handler style: async, immediate, or none");
+
+DEFINE_string(
+    category,
+    "",
+    "Crash with a message to this category instead of the default");
+
+using folly::LogLevel;
+
+/*
+ * This is a simple helper program to exercise the LOG(FATAL) functionality.
+ */
+int main(int argc, char* argv[]) {
+  // Call folly::init() and then initialize log levels and handlers
+  folly::init(&argc, &argv);
+
+  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);
+  }
+
+  XLOG(FATAL) << "test program crashing!";
+  // Even though main() is defined to return an integer, the compiler
+  // should be able to detect that XLOG(FATAL) never returns.  It shouldn't
+  // complain that we don't return an integer here.
+}
index 0537948..3415f97 100644 (file)
@@ -51,6 +51,14 @@ TEST(LogLevel, fromString) {
   EXPECT_EQ(LogLevel::CRITICAL, stringToLogLevel("critical"));
   EXPECT_EQ(LogLevel::CRITICAL, stringToLogLevel("CRITICAL"));
 
+  EXPECT_EQ(LogLevel::DFATAL, stringToLogLevel("dfatal"));
+  EXPECT_EQ(LogLevel::DFATAL, stringToLogLevel("DFatal"));
+  EXPECT_EQ(LogLevel::DFATAL, stringToLogLevel("DFATAL"));
+
+  EXPECT_EQ(LogLevel::FATAL, stringToLogLevel("fatal"));
+  EXPECT_EQ(LogLevel::FATAL, stringToLogLevel("FaTaL"));
+  EXPECT_EQ(LogLevel::FATAL, stringToLogLevel("FATAL"));
+
   EXPECT_EQ(LogLevel::MAX_LEVEL, stringToLogLevel("max"));
   EXPECT_EQ(LogLevel::MAX_LEVEL, stringToLogLevel("Max_Level"));
   EXPECT_EQ(LogLevel::MAX_LEVEL, stringToLogLevel("LogLevel::MAX"));
@@ -82,7 +90,9 @@ TEST(LogLevel, toString) {
   EXPECT_EQ("LogLevel::DEBUG", logLevelToString(LogLevel::DEBUG));
   EXPECT_EQ("LogLevel::ERR", logLevelToString(LogLevel::ERR));
   EXPECT_EQ("LogLevel::CRITICAL", logLevelToString(LogLevel::CRITICAL));
-  EXPECT_EQ("LogLevel::MAX_LEVEL", logLevelToString(LogLevel::MAX_LEVEL));
+  EXPECT_EQ("LogLevel::DFATAL", logLevelToString(LogLevel::DFATAL));
+  EXPECT_EQ("LogLevel::FATAL", logLevelToString(LogLevel::FATAL));
+  EXPECT_EQ("LogLevel::FATAL", logLevelToString(LogLevel::MAX_LEVEL));
 
   EXPECT_EQ("LogLevel::DBG0", logLevelToString(LogLevel::DBG0));
   EXPECT_EQ("LogLevel::DBG2", logLevelToString(LogLevel::DBG2));
@@ -123,7 +133,8 @@ TEST(LogLevel, toStringAndBack) {
   checkLevel(LogLevel::WARNING);
   checkLevel(LogLevel::ERR);
   checkLevel(LogLevel::CRITICAL);
-  checkLevel(LogLevel::MAX_LEVEL);
+  checkLevel(LogLevel::DFATAL);
+  checkLevel(LogLevel::FATAL);
 
   // Try with some random integer values
   for (uint32_t numIters = 0; numIters < 10000; ++numIters) {
diff --git a/folly/experimental/logging/test/fatal_test.py b/folly/experimental/logging/test/fatal_test.py
new file mode 100644 (file)
index 0000000..de7274f
--- /dev/null
@@ -0,0 +1,81 @@
+#!/usr/bin/env python3
+#
+# 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.
+#
+import os
+import re
+import signal
+import subprocess
+import unittest
+
+
+class FatalTests(unittest.TestCase):
+    def setUp(self):
+        fatal_helper_env = os.environ.get('FOLLY_FATAL_HELPER')
+        if fatal_helper_env:
+            self.helper = fatal_helper_env
+        else:
+            build_dir = os.path.join(os.getcwd(), 'buck-out', 'gen')
+            self.helper = os.path.join(build_dir, 'folly', 'experimental',
+                                       'logging', 'test', 'fatal_helper')
+
+    def run_helper(self, *args):
+        '''
+        Run the helper.
+        Check that it crashes with SIGABRT and prints nothing on stdout.
+        Returns the data printed to stderr.
+        '''
+        cmd = [self.helper]
+        cmd.extend(args)
+        p = subprocess.Popen(cmd,
+                             stdout=subprocess.PIPE,
+                             stderr=subprocess.PIPE)
+        out, err = p.communicate()
+        status = p.returncode
+
+        self.assertEqual(status, -signal.SIGABRT)
+        self.assertEqual(out, b'')
+        return err
+
+    def glog_crash_regex(self):
+        return re.compile(
+            br'^C[0-9]{4} .* FatalHelper.cpp:[0-9]+\] test program crashing!$',
+            re.MULTILINE)
+
+    def test_async(self):
+        err = self.run_helper('--handler_style=async')
+        self.assertRegex(err, self.glog_crash_regex())
+
+    def test_immediate(self):
+        err = self.run_helper('--handler_style=immediate')
+        self.assertRegex(err, self.glog_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')
+        return re.compile(
+            br'^FATAL:.*/FatalHelper.cpp:[0-9]+: test program crashing!$',
+            re.MULTILINE)
+        self.assertRegex(err, self.glog_crash_regex())
+
+    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'crashing to category foo\.bar$',
+            re.MULTILINE)
+        self.assertRegex(err, regex)
index 452041f..8840dd5 100644 (file)
  *   initialized.  On all subsequent calls, disabled log statements can be
  *   skipped with just a single check of the LogLevel.
  */
-#define XLOG_IMPL(level, type, ...)                        \
-  (!XLOG_IS_ON_IMPL(level)) ? static_cast<void>(0)         \
-                            : ::folly::LogStreamProcessor( \
-                                  XLOG_GET_CATEGORY(),     \
-                                  (level),                 \
-                                  __FILE__,                \
-                                  __LINE__,                \
-                                  (type),                  \
-                                  ##__VA_ARGS__) &         \
+#define XLOG_IMPL(level, type, ...)                                    \
+  (!XLOG_IS_ON_IMPL(level))                                            \
+      ? static_cast<void>(0)                                           \
+      : ::folly::LogStreamProcessorT<::folly::isLogLevelFatal(level)>( \
+            XLOG_GET_CATEGORY(),                                       \
+            (level),                                                   \
+            __FILE__,                                                  \
+            __LINE__,                                                  \
+            (type),                                                    \
+            ##__VA_ARGS__) &                                           \
           ::folly::LogStream()
 
 /**