SERVER-66368 no reentrancy during logging

4 files changed, 78 insertions, 38 deletions

diff --git a/src/mongo/logv2/log_detail.cpp b/src/mongo/logv2/log_detail.cpp
index 89e5c32745e..d3004ce85e4 100644
--- a/src/mongo/logv2/log_detail.cpp
+++ b/src/mongo/logv2/log_detail.cpp
@@ -174,14 +174,21 @@ static void checkUniqueAttrs(int32_t id, const TypeErasedAttributeStorage& attrs
     }
 }
 
-void doLogImpl(int32_t id,
+void doSafeLog(int32_t id,
                LogSeverity const& severity,
                LogOptions const& options,
                StringData message,
                TypeErasedAttributeStorage const& attrs) {
-    loggingDepth++;
-    ScopeGuard updateDepth = [] { loggingDepth--; };
 
+    signalSafeWriteToStderr(
+        format(FMT_STRING("{}({}): {}\n"), severity.toStringData(), id, message));
+}
+
+void _doLogImpl(int32_t id,
+                LogSeverity const& severity,
+                LogOptions const& options,
+                StringData message,
+                TypeErasedAttributeStorage const& attrs) {
     dassert(options.component() != LogComponent::kNumLogComponents);
     // TestingProctor isEnabled cannot be called before it has been
     // initialized. But log statements occurring earlier than that still need
@@ -223,6 +230,35 @@ void doLogImpl(int32_t id,
     }
 }
 
+void doLogImpl(int32_t id,
+               LogSeverity const& severity,
+               LogOptions const& options,
+               StringData message,
+               TypeErasedAttributeStorage const& attrs) {
+    if (loggingInProgress()) {
+        doSafeLog(id, severity, options, message, attrs);
+        return;
+    }
+
+    loggingDepth++;
+    ScopeGuard updateDepth = [] { loggingDepth--; };
+
+    try {
+        _doLogImpl(id, severity, options, message, attrs);
+    } catch (const fmt::format_error& ex) {
+        _doLogImpl(4638200,
+                   LogSeverity::Error(),
+                   LogOptions(LogComponent::kAssert),
+                   "Exception during log"_sd,
+                   AttributeStorage{"original_msg"_attr = message, "what"_attr = ex.what()});
+
+        invariant(!kDebugBuild, format(FMT_STRING("Exception during log: {}"), ex.what()));
+    } catch (...) {
+        doSafeLog(id, severity, options, message, attrs);
+        throw;
+    }
+}
+
 void doUnstructuredLogImpl(LogSeverity const& severity,  // NOLINT
                            LogOptions const& options,
                            StringData message,
diff --git a/src/mongo/logv2/log_manager.cpp b/src/mongo/logv2/log_manager.cpp
index 0a39ffb778e..68f97592f46 100644
--- a/src/mongo/logv2/log_manager.cpp
+++ b/src/mongo/logv2/log_manager.cpp
@@ -36,6 +36,7 @@
 
 #include "mongo/base/init.h"
 #include "mongo/logv2/log.h"
+#include "mongo/logv2/log_detail.h"
 #include "mongo/logv2/log_domain.h"
 #include "mongo/logv2/log_domain_global.h"
 #include "mongo/logv2/log_util.h"
@@ -54,33 +55,6 @@ struct LogManager::Impl {
 
 LogManager::LogManager() {
     _impl = std::make_unique<Impl>();
-
-    boost::log::core::get()->set_exception_handler([]() {
-        thread_local uint32_t depth = 0;
-        ScopeGuard depthGuard([]() { --depth; });
-        ++depth;
-        // Try and log that we failed to log
-        if (depth == 1) {
-            std::exception_ptr ex = nullptr;
-            try {
-                throw;
-            } catch (const DBException&) {
-                ex = std::current_exception();
-            } catch (...) {
-                LOGV2(4638200,
-                      "Exception during log, message not written to stream",
-                      "exception"_attr = exceptionToStatus());
-            }
-            if (ex)
-                std::rethrow_exception(ex);
-        }
-
-        // Logging exceptions are fatal in debug builds. Guard ourselves from additional logging
-        // during the assert that might also fail
-        if (kDebugBuild && depth <= 2) {
-            dassert(false, "Exception during log");
-        }
-    });
 }
 
 LogManager::~LogManager() {}
diff --git a/src/mongo/logv2/log_severity.h b/src/mongo/logv2/log_severity.h
index 796dd43548e..8334ced8137 100644
--- a/src/mongo/logv2/log_severity.h
+++ b/src/mongo/logv2/log_severity.h
@@ -103,13 +103,6 @@ public:
     }
 
     /**
-     * Returns a std::string naming this severity level.
-     *
-     * See toStringData(), below.
-     */
-    std::string toString() const;
-
-    /**
      * Returns a StringData naming this security level.
      *
      * Not all levels are uniquely named.  Debug(N) is named "debug", regardless of "N",
diff --git a/src/mongo/logv2/logv2_test.cpp b/src/mongo/logv2/logv2_test.cpp
index 0144f9a86b2..fdf1cadedd0 100644
--- a/src/mongo/logv2/logv2_test.cpp
+++ b/src/mongo/logv2/logv2_test.cpp
@@ -287,6 +287,12 @@ public:
         _attachedSinks.push_back(sink);
     }
 
+    void popSink() {
+        auto sink = _attachedSinks.back();
+        boost::log::core::get()->remove_sink(sink);
+        _attachedSinks.pop_back();
+    }
+
     template <typename Fmt>
     LineCapture makeLineCapture(Fmt&& formatter, bool stripEol = true) {
         LineCapture ret(stripEol);
@@ -355,14 +361,24 @@ TEST_F(LogV2Test, Basic) {
     // Message string is selected when using API that also take a format string
     LOGV2(20084, "fmtstr {name}", "msgstr", "name"_attr = 1);
     ASSERT_EQUALS(lines.back(), "msgstr");
+}
 
-    // Test that logging exceptions does not propagate out to user code in release builds
+TEST_F(LogV2Test, MismatchAttrInLogging) {
+    auto lines = makeLineCapture(PlainFormatter());
     if (!kDebugBuild) {
         LOGV2(4638203, "mismatch {name}", "not_name"_attr = 1);
         ASSERT(StringData(lines.back()).startsWith("Exception during log"_sd));
     }
 }
 
+TEST_F(LogV2Test, MissingAttrInLogging) {
+    auto lines = makeLineCapture(PlainFormatter());
+    if (!kDebugBuild) {
+        LOGV2(6636803, "Log missing {attr}");
+        ASSERT(StringData(lines.back()).startsWith("Exception during log"_sd));
+    }
+}
+
 namespace bl_sinks = boost::log::sinks;
 // Sink backend which will grab a mutex, then immediately segfault.
 class ConsumeSegfaultsBackend
@@ -400,6 +416,27 @@ DEATH_TEST_F(LogV2Test, SIGSEGVDoesNotHang, "Got signal: ") {
     // If we get here, we didn't segfault, and the test will fail.
 }
 
+class ConsumeThrowsBackend
+    : public bl_sinks::basic_formatted_sink_backend<char, bl_sinks::synchronized_feeding> {
+public:
+    struct LocalException : std::exception {};
+    static auto create() {
+        return boost::make_shared<bl_sinks::synchronous_sink<ConsumeThrowsBackend>>(
+            boost::make_shared<ConsumeThrowsBackend>());
+    }
+
+    void consume(boost::log::record_view const& rec, string_type const& formattedString) {
+        throw LocalException();
+    }
+};
+
+TEST_F(LogV2Test, ExceptInLogging) {
+    auto sink = ConsumeThrowsBackend::create();
+    attachSink(sink);
+    ASSERT_THROWS(LOGV2(6636801, "will throw exception"), ConsumeThrowsBackend::LocalException);
+    popSink();
+}
+
 class LogV2TypesTest : public LogV2Test {
 public:
     using LogV2Test::LogV2Test;