SERVER-63843 Don't allow recursive doLog in sync signal handlers

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);
 }