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:12:54 +0000 |
commit | 9783ab2652858dd6e9175160d6d7a4c14e2d5ea5 (patch) | |
tree | ca144c7e9f49d54aae8b19da5ed02d00cea8945f | |
parent | 6192908ab3bcf8350e9ec5c7ecc6654d5708c320 (diff) | |
download | mongo-9783ab2652858dd6e9175160d6d7a4c14e2d5ea5.tar.gz |
SERVER-63843 Don't allow recursive doLog in sync signal handlers
-rw-r--r-- | src/mongo/logv2/log_detail.cpp | 43 | ||||
-rw-r--r-- | src/mongo/logv2/log_detail.h | 15 | ||||
-rw-r--r-- | src/mongo/logv2/logv2_test.cpp | 39 | ||||
-rw-r--r-- | src/mongo/util/signal_handlers_synchronous.cpp | 56 |
4 files changed, 125 insertions, 28 deletions
diff --git a/src/mongo/logv2/log_detail.cpp b/src/mongo/logv2/log_detail.cpp index 188ede8032a..fb13b99e435 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/db/tenant_id.h" #include "mongo/logv2/attributes.h" @@ -40,10 +43,41 @@ #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/static_immortal.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 { + namespace { GetTenantIDFn& getTenantID() { // Ensure that we avoid undefined initialization ordering @@ -146,6 +180,9 @@ void doLogImpl(int32_t id, LogOptions const& options, StringData message, TypeErasedAttributeStorage const& attrs) { + loggingDepth++; + ScopeGuard updateDepth = [] { 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 @@ -201,4 +238,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 6f60ae10c74..7b3360662a2 100644 --- a/src/mongo/logv2/log_detail.h +++ b/src/mongo/logv2/log_detail.h @@ -42,8 +42,15 @@ #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 { + using GetTenantIDFn = std::function<boost::optional<TenantId>()>; void setGetTenantIDCallback(GetTenantIDFn&& fn); @@ -130,6 +137,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 bc8c402010c..2477d27033b 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> @@ -60,6 +61,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" @@ -360,6 +362,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); } |