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 c475bf6e686e9851e6bb13cb90da756298c7cf01..ff06ba52d8eda0c507674c723b3fba1bf3e2e4e8 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 d7989f4b62bbc50ababde25290b557b5145c8ec7..ce97c918bbe75660098ddfb970efcc6e9aeeea1d 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 03e13d33e0f5566ea690229784625023039800e8..c16eadba972e0cc57d08d6347fa8751d07d3a1d4 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 05c1603efcc72955134d0de177dd61d1161651e5..0c751b15bd33af5f1390aa279c7a227fdde294da 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 84c8e0d6882e49ee23cf890784f889690fcd724a..f74f3a76611bdbb39a439608c3dd590bee49881f 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 f95e00e44e6168da5422bba255fee363a917441d..bb24d4deb7b655584426bf5817df73948fdb89aa 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 ab9bd24f0950c346704dad1923ba6bb1b1172d31..2fae9e2acfabf1fca49af75d8a9abbe09b9cde7d 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 4c8d3a80423e5837c9f53f1a848c329cf9fb0a36..bd92a6371129f6ce19e7357afa0a3ca77b8f0e7b 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 9580b7434c2adc0f9ac403431faa6921f48243f4..0f7fed2d21e898748e64f572c7beecf3ae307342 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 0537948d1dff3fd703af598cd40914da2f3fe6a4..3415f971a7592f853b95030fe417a8fc7b92444f 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 452041f6fa150e1e16d7cbed94bcf2d6f97462ac..8840dd5109b4165c8c56eeeb7fb95f7c07e4f507 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()
 
 /**