From 7d0c51c21c432c9a3445ee45e80d28d1689dd1ed Mon Sep 17 00:00:00 2001 From: Gabriel Marks Date: Fri, 27 May 2022 16:39:11 +0000 Subject: SERVER-63843 Don't allow recursive doLog in sync signal handlers --- src/mongo/logv2/log_detail.cpp | 41 +++++++++++++++++++++++++++++++++++++++-- src/mongo/logv2/log_detail.h | 14 ++++++++++---- src/mongo/logv2/logv2_test.cpp | 39 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 88 insertions(+), 6 deletions(-) (limited to 'src/mongo/logv2') 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 +#ifdef _WIN32 +#include +#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 +#include #include #include #include @@ -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 { +public: + static auto create() { + return boost::make_shared>( + boost::make_shared()); + } + + 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; -- cgit v1.2.1