From 61fbd6698139d3f797401da6350371c7afc4030c Mon Sep 17 00:00:00 2001 From: Adam Simpkins Date: Tue, 20 Jun 2017 14:01:59 -0700 Subject: [PATCH] logging: implement FATAL and DFATAL log levels 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 --- folly/experimental/logging/LogCategory.cpp | 27 +++++++ folly/experimental/logging/LogCategory.h | 13 ++- folly/experimental/logging/LogLevel.cpp | 10 ++- folly/experimental/logging/LogLevel.h | 23 +++++- .../logging/LogStreamProcessor.cpp | 14 ++-- .../experimental/logging/LogStreamProcessor.h | 40 +++++++++ folly/experimental/logging/Logger.h | 19 ++--- folly/experimental/logging/LoggerDB.cpp | 3 +- folly/experimental/logging/LoggerDB.h | 4 +- .../experimental/logging/test/FatalHelper.cpp | 57 +++++++++++++ .../logging/test/LogLevelTest.cpp | 15 +++- folly/experimental/logging/test/fatal_test.py | 81 +++++++++++++++++++ folly/experimental/logging/xlog.h | 19 ++--- 13 files changed, 285 insertions(+), 40 deletions(-) create mode 100644 folly/experimental/logging/test/FatalHelper.cpp create mode 100644 folly/experimental/logging/test/fatal_test.py diff --git a/folly/experimental/logging/LogCategory.cpp b/folly/experimental/logging/LogCategory.cpp index c475bf6e..ff06ba52 100644 --- a/folly/experimental/logging/LogCategory.cpp +++ b/folly/experimental/logging/LogCategory.cpp @@ -16,8 +16,10 @@ #include #include +#include #include +#include #include #include #include @@ -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( + "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. diff --git a/folly/experimental/logging/LogCategory.h b/folly/experimental/logging/LogCategory.h index d7989f4b..ce97c918 100644 --- a/folly/experimental/logging/LogCategory.h +++ b/folly/experimental/logging/LogCategory.h @@ -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); diff --git a/folly/experimental/logging/LogLevel.cpp b/folly/experimental/logging/LogLevel.cpp index 03e13d33..c16eadba 100644 --- a/folly/experimental/logging/LogLevel.cpp +++ b/folly/experimental/logging/LogLevel.cpp @@ -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(level) <= static_cast(LogLevel::DBG0) && diff --git a/folly/experimental/logging/LogLevel.h b/folly/experimental/logging/LogLevel.h index 05c1603e..0c751b15 100644 --- a/folly/experimental/logging/LogLevel.h +++ b/folly/experimental/logging/LogLevel.h @@ -18,7 +18,9 @@ #include #include #include +#include +#include #include 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(level) + value; // Cap the result at LogLevel::MAX_LEVEL if (newValue > static_cast(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(static_cast(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; + } +} } diff --git a/folly/experimental/logging/LogStreamProcessor.cpp b/folly/experimental/logging/LogStreamProcessor.cpp index 84c8e0d6..f74f3a76 100644 --- a/folly/experimental/logging/LogStreamProcessor.cpp +++ b/folly/experimental/logging/LogStreamProcessor.cpp @@ -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(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_)}); } diff --git a/folly/experimental/logging/LogStreamProcessor.h b/folly/experimental/logging/LogStreamProcessor.h index f95e00e4..bb24d4de 100644 --- a/folly/experimental/logging/LogStreamProcessor.h +++ b/folly/experimental/logging/LogStreamProcessor.h @@ -20,6 +20,7 @@ #include #include #include +#include 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 +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 : 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(); + } +}; } diff --git a/folly/experimental/logging/Logger.h b/folly/experimental/logging/Logger.h index ab9bd24f..2fae9e2a 100644 --- a/folly/experimental/logging/Logger.h +++ b/folly/experimental/logging/Logger.h @@ -27,15 +27,16 @@ * * 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() /** diff --git a/folly/experimental/logging/LoggerDB.cpp b/folly/experimental/logging/LoggerDB.cpp index 4c8d3a80..bd92a637 100644 --- a/folly/experimental/logging/LoggerDB.cpp +++ b/folly/experimental/logging/LoggerDB.cpp @@ -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( diff --git a/folly/experimental/logging/LoggerDB.h b/folly/experimental/logging/LoggerDB.h index 9580b743..0f7fed2d 100644 --- a/folly/experimental/logging/LoggerDB.h +++ b/folly/experimental/logging/LoggerDB.h @@ -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 used by an XLOG() diff --git a/folly/experimental/logging/test/FatalHelper.cpp b/folly/experimental/logging/test/FatalHelper.cpp new file mode 100644 index 00000000..e89ef2cd --- /dev/null +++ b/folly/experimental/logging/test/FatalHelper.cpp @@ -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 +#include +#include + +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. +} diff --git a/folly/experimental/logging/test/LogLevelTest.cpp b/folly/experimental/logging/test/LogLevelTest.cpp index 0537948d..3415f971 100644 --- a/folly/experimental/logging/test/LogLevelTest.cpp +++ b/folly/experimental/logging/test/LogLevelTest.cpp @@ -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 index 00000000..de7274f9 --- /dev/null +++ b/folly/experimental/logging/test/fatal_test.py @@ -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) diff --git a/folly/experimental/logging/xlog.h b/folly/experimental/logging/xlog.h index 452041f6..8840dd51 100644 --- a/folly/experimental/logging/xlog.h +++ b/folly/experimental/logging/xlog.h @@ -111,15 +111,16 @@ * 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(0) \ - : ::folly::LogStreamProcessor( \ - XLOG_GET_CATEGORY(), \ - (level), \ - __FILE__, \ - __LINE__, \ - (type), \ - ##__VA_ARGS__) & \ +#define XLOG_IMPL(level, type, ...) \ + (!XLOG_IS_ON_IMPL(level)) \ + ? static_cast(0) \ + : ::folly::LogStreamProcessorT<::folly::isLogLevelFatal(level)>( \ + XLOG_GET_CATEGORY(), \ + (level), \ + __FILE__, \ + __LINE__, \ + (type), \ + ##__VA_ARGS__) & \ ::folly::LogStream() /** -- 2.34.1