diff options
author | Gabriel Marks <gabriel.marks@mongodb.com> | 2022-05-27 16:39:11 +0000 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2022-08-17 15:04:54 +0000 |
commit | 7d0c51c21c432c9a3445ee45e80d28d1689dd1ed (patch) | |
tree | 4f2a52893b9fbcce9d80fb864a76ab7ab1bab28d /src | |
parent | c557a829e725cffdd4f1cd76814e6c2be3672bfb (diff) | |
download | mongo-7d0c51c21c432c9a3445ee45e80d28d1689dd1ed.tar.gz |
SERVER-63843 Don't allow recursive doLog in sync signal handlers
Diffstat (limited to 'src')
-rw-r--r-- | src/mongo/logv2/log_detail.cpp | 41 | ||||
-rw-r--r-- | src/mongo/logv2/log_detail.h | 14 | ||||
-rw-r--r-- | src/mongo/logv2/logv2_test.cpp | 39 | ||||
-rw-r--r-- | src/mongo/util/signal_handlers_synchronous.cpp | 56 |
4 files changed, 122 insertions, 28 deletions
diff --git a/src/mongo/logv2/log_detail.cpp b/src/mongo/logv2/log_detail.cpp index 95ea258a5a3..074c5e6b4f4 100644 --- a/src/mongo/logv2/log_detail.cpp +++ b/src/mongo/logv2/log_detail.cpp @@ -32,6 +32,9 @@ #include "mongo/platform/basic.h" #include <fmt/format.h> +#ifdef _WIN32 +#include <io.h> +#endif #include "mongo/logv2/attributes.h" #include "mongo/logv2/log.h" @@ -39,9 +42,38 @@ #include "mongo/logv2/log_domain_internal.h" #include "mongo/logv2/log_options.h" #include "mongo/logv2/log_source.h" +#include "mongo/util/scopeguard.h" #include "mongo/util/testing_proctor.h" -namespace mongo::logv2::detail { +namespace mongo::logv2 { +namespace { +thread_local int loggingDepth = 0; +} // namespace + +bool loggingInProgress() { + return loggingDepth > 0; +} + +void signalSafeWriteToStderr(StringData message) { + while (!message.empty()) { +#if defined(_WIN32) + auto ret = _write(_fileno(stderr), message.rawData(), message.size()); +#else + auto ret = write(STDERR_FILENO, message.rawData(), message.size()); +#endif + if (ret == -1) { +#if !defined(_WIN32) + if (errno == EINTR) { + continue; + } +#endif + return; + } + message = message.substr(ret); + } +} + +namespace detail { struct UnstructuredValueExtractor { void operator()(const char* name, CustomAttributeValue const& val) { @@ -131,6 +163,9 @@ void doLogImpl(int32_t id, LogOptions const& options, StringData message, TypeErasedAttributeStorage const& attrs) { + loggingDepth++; + auto updateDepth = makeGuard([] { loggingDepth--; }); + dassert(options.component() != LogComponent::kNumLogComponents); // TestingProctor isEnabled cannot be called before it has been // initialized. But log statements occurring earlier than that still need @@ -177,4 +212,6 @@ void doUnstructuredLogImpl(LogSeverity const& severity, // NOLINT doLogImpl(0, severity, options, formatted, TypeErasedAttributeStorage()); } -} // namespace mongo::logv2::detail +} // namespace detail + +} // namespace mongo::logv2 diff --git a/src/mongo/logv2/log_detail.h b/src/mongo/logv2/log_detail.h index 53c28ae7152..e34625b824d 100644 --- a/src/mongo/logv2/log_detail.h +++ b/src/mongo/logv2/log_detail.h @@ -39,8 +39,14 @@ #include "mongo/logv2/log_severity.h" #include "mongo/util/errno_util.h" -namespace mongo { -namespace logv2::detail { +namespace mongo::logv2 { + +// Whether there is a doLogImpl call currently on this thread's stack. +bool loggingInProgress(); + +// Write message to stderr in a signal-safe manner. +void signalSafeWriteToStderr(StringData message); +namespace detail { void doLogImpl(int32_t id, LogSeverity const& severity, @@ -125,6 +131,6 @@ void doLog(int32_t id, std::tuple_cat(toFlatAttributesTupleRef(args)...)); } -} // namespace logv2::detail +} // namespace detail -} // namespace mongo +} // namespace mongo::logv2 diff --git a/src/mongo/logv2/logv2_test.cpp b/src/mongo/logv2/logv2_test.cpp index a20f202b3e2..cc831cdd7ca 100644 --- a/src/mongo/logv2/logv2_test.cpp +++ b/src/mongo/logv2/logv2_test.cpp @@ -32,6 +32,7 @@ #include "mongo/platform/basic.h" #include <fstream> +#include <signal.h> #include <sstream> #include <string> #include <vector> @@ -58,6 +59,7 @@ #include "mongo/logv2/uassert_sink.h" #include "mongo/platform/decimal128.h" #include "mongo/stdx/thread.h" +#include "mongo/unittest/death_test.h" #include "mongo/unittest/temp_dir.h" #include "mongo/unittest/unittest.h" #include "mongo/util/str_escape.h" @@ -356,6 +358,43 @@ TEST_F(LogV2Test, Basic) { } } +namespace bl_sinks = boost::log::sinks; +// Sink backend which will grab a mutex, then immediately segfault. +class ConsumeSegfaultsBackend + : public bl_sinks::basic_formatted_sink_backend<char, bl_sinks::synchronized_feeding> { +public: + static auto create() { + return boost::make_shared<bl_sinks::synchronous_sink<ConsumeSegfaultsBackend>>( + boost::make_shared<ConsumeSegfaultsBackend>()); + } + + void consume(boost::log::record_view const& rec, string_type const& formattedString) { + if (firstRun) { + firstRun = false; + raise(SIGSEGV); + } else { + // Reentrance of consume(), which could cause deadlock. Exit normally, causing the death + // test to fail. + exit(0); + } + } + +private: + bool firstRun = true; +}; + +// Test that signals thrown during logging will not hang process death. Uses the +// ConsumeSegfaultsBackend so that upon the initial log call, ConsumeSegfaultsBackend::consume will +// be called, sending SIGSEGV. If the signal handler incorrectly invokes the logging subsystem, the +// ConsumeSegfaultsBackend::consume function will be again invoked, failing the test since this +// could result in deadlock. +DEATH_TEST_F(LogV2Test, SIGSEGVDoesNotHang, "Got signal: ") { + auto sink = ConsumeSegfaultsBackend::create(); + attachSink(sink); + LOGV2(6384304, "will SIGSEGV {str}", "str"_attr = "sigsegv"); + // If we get here, we didn't segfault, and the test will fail. +} + class LogV2TypesTest : public LogV2Test { public: using LogV2Test::LogV2Test; diff --git a/src/mongo/util/signal_handlers_synchronous.cpp b/src/mongo/util/signal_handlers_synchronous.cpp index 8f052ea134b..59e2e2ef923 100644 --- a/src/mongo/util/signal_handlers_synchronous.cpp +++ b/src/mongo/util/signal_handlers_synchronous.cpp @@ -65,6 +65,8 @@ namespace mongo { namespace { +using namespace fmt::literals; + #if defined(_WIN32) const char* strsignal(int signalNum) { // should only see SIGABRT on windows @@ -191,22 +193,38 @@ private: stdx::mutex MallocFreeOStreamGuard::_streamMutex; // NOLINT thread_local int MallocFreeOStreamGuard::terminateDepth = 0; +void logNoRecursion(StringData message) { + // If we were within a log call when we hit a signal, don't call back into the logging + // subsystem. + if (logv2::loggingInProgress()) { + logv2::signalSafeWriteToStderr(message); + } else { + LOGV2_FATAL_CONTINUE(6384300, "Writing fatal message", "message"_attr = message); + } +} + // must hold MallocFreeOStreamGuard to call void writeMallocFreeStreamToLog() { - LOGV2_FATAL_OPTIONS( - 4757800, - logv2::LogOptions(logv2::FatalMode::kContinue, logv2::LogTruncation::Disabled), - "{message}", - "Writing fatal message", - "message"_attr = mallocFreeOStream.str()); + mallocFreeOStream << "\n"; + logNoRecursion(mallocFreeOStream.str()); mallocFreeOStream.rewind(); } // must hold MallocFreeOStreamGuard to call +void printStackTraceNoRecursion() { + if (logv2::loggingInProgress()) { + printStackTrace(mallocFreeOStream); + writeMallocFreeStreamToLog(); + } else { + printStackTrace(); + } +} + +// must hold MallocFreeOStreamGuard to call void printSignalAndBacktrace(int signalNum) { - mallocFreeOStream << "Got signal: " << signalNum << " (" << strsignal(signalNum) << ").\n"; + mallocFreeOStream << "Got signal: " << signalNum << " (" << strsignal(signalNum) << ")."; writeMallocFreeStreamToLog(); - printStackTrace(); + printStackTraceNoRecursion(); } // this will be called in certain c++ error cases, for example if there are two active @@ -222,7 +240,7 @@ void myTerminate() { mallocFreeOStream << " No exception is active"; } writeMallocFreeStreamToLog(); - printStackTrace(); + printStackTraceNoRecursion(); breakpoint(); endProcessWithSignal(SIGABRT); } @@ -241,22 +259,16 @@ void myInvalidParameterHandler(const wchar_t* expression, const wchar_t* file, unsigned int line, uintptr_t pReserved) { - LOGV2_FATAL_CONTINUE( - 23815, - "Invalid parameter detected in function {function} in {file} at line {line} " - "with expression '{expression}'", - "Invalid parameter detected", - "function"_attr = toUtf8String(function), - "file"_attr = toUtf8String(file), - "line"_attr = line, - "expression"_attr = toUtf8String(expression)); + + logNoRecursion( + "Invalid parameter detected in function {} in {} at line {} with expression '{}'\n"_format( + toUtf8String(function), toUtf8String(file), line, toUtf8String(expression))); abruptQuit(SIGABRT); } void myPureCallHandler() { - LOGV2_FATAL_CONTINUE(23818, - "Pure call handler invoked. Immediate exit due to invalid pure call"); + logNoRecursion("Pure call handler invoked. Immediate exit due to invalid pure call\n"); abruptQuit(SIGABRT); } @@ -345,9 +357,9 @@ void setupSynchronousSignalHandlers() { void reportOutOfMemoryErrorAndExit() { MallocFreeOStreamGuard lk{}; - mallocFreeOStream << "out of memory.\n"; + mallocFreeOStream << "out of memory."; writeMallocFreeStreamToLog(); - printStackTrace(); + printStackTraceNoRecursion(); quickExit(EXIT_ABRUPT); } |