MB-46900: Don't interpret BucketLogger prefix as fmt string

As part of "MB-46216: Check log format strings at compile-time
(ep-engine)" (f038ea0), the behaviour of BucketLogger when it has a
prefix which contained fmtlib formatting characters
changed. Previously this would throw an exception which spdlog would
catch, and print a log message along the lines of:

    "[*** LOG ERROR #1 ***] [2021-06-15 19:06:07] [globalBucketLogger] {argument not found}"

However, with the changes in f038ea0 we perform the formatting of the
message outselves in bucket_logger.cc, and the thrown exception isn't
caught and can result in kv_engine terminating.

Fix by changing how we add the BucketLogger prefixes - don't append
them to the format string but instead explicilty format everything,
then pass the formatted log string down to spdlog.

Change-Id: Iae8212cd02e1ff9c28ae12921a10cedb7d3c6b0f
Reviewed-on: http://review.couchbase.org/c/kv_engine/+/155932
Reviewed-by: Ben Huddleston <[email protected]>
Tested-by: Build Bot <[email protected]>

Author: daverigby

engines/ep/src/bucket_logger.cc

@@ -54,8 +54,30 @@ void BucketLogger::logInner(spdlog::level::level_enum lvl,
     // Instead account any log message memory to "NonBucket" (it is only
     // transient and typically small - of the order of the log message length).
     NonBucketAllocationGuard guard;
-    const auto prefixedFmt = prefixStringWithBucketName(engine, fmt);
-    spdlog::logger::log(lvl, fmt::vformat(prefixedFmt, args));
+
+    // We want to prefix the specified message with the bucket name & optional
+    // prefix, but we cannot be sure that bucket name / prefix
+    // doesn't contain any fmtlib formatting characters. Therefore we build up
+    // the log string here then pass the already-formatted string down to
+    // spdlog directly, not using spdlog's formatting functions.
+    fmt::memory_buffer msg;
+
+    // Append the id (if set)
+    if (connectionId != 0) {
+        fmt::format_to(msg, "{}: ", connectionId);
+    }
+
+    // Append the engine name (if applicable)
+    fmt::format_to(msg, "({}) ", engine ? engine->getName() : "No Engine");
+
+    // Append the given prefix (if set)
+    if (!prefix.empty()) {
+        fmt::format_to(msg, "{} ", prefix);
+    }
+
+    // Finally format the actual user-specified format string & args.
+    fmt::vformat_to(msg, fmt, args);
+    spdlog::logger::log(lvl, {msg.data(), msg.size()});
 }
 
 void BucketLogger::setLoggerAPI(ServerLogIface* api) {
@@ -93,32 +115,6 @@ void BucketLogger::unregister() {
     getServerLogIface()->unregister_spdlogger(name());
 }
 
-std::string BucketLogger::prefixStringWithBucketName(
-        const EventuallyPersistentEngine* engine, fmt::string_view fmt) {
-    std::string fmtString;
-
-    // Append the id (if set)
-    if (connectionId != 0) {
-        fmtString.append(std::to_string(connectionId) + ": ");
-    }
-
-    // Append the engine name (if applicable)
-    if (engine) {
-        fmtString.append('(' + std::string(engine->getName().c_str()) + ") ");
-    } else {
-        fmtString.append("(No Engine) ");
-    }
-
-    // Append the given prefix (if set)
-    if (!prefix.empty()) {
-        fmtString.append(prefix + " ");
-    }
-
-    // Append the original format string
-    fmtString.append(fmt.begin(), fmt.end());
-    return fmtString;
-}
-
 ServerLogIface* BucketLogger::getServerLogIface() {
     return loggerAPI.load(std::memory_order_relaxed);
 }

engines/ep/src/bucket_logger.h

@@ -181,13 +181,6 @@ class BucketLogger : public spdlog::logger {
                   fmt::string_view fmt,
                   fmt::format_args args);
 
-    /**
-     * Helper function which prefixes the string with the name of the
-     * specified engine, or "No Engine" if engine is null.
-     */
-    std::string prefixStringWithBucketName(
-            const EventuallyPersistentEngine* engine, fmt::string_view fmt);
-
     /**
      * Connection ID prefix that is printed if set (printed before any other
      * prefix or message)

engines/ep/tests/module_tests/bucket_logger_test.cc

@@ -175,6 +175,24 @@ TEST_F(BucketLoggerTest, CriticalRawMacro) {
     EXPECT_EQ(1, countInFile(files.front(), "CRITICAL (No Engine) rawtext"));
 }
 
+/**
+ * Regression test for MB-46900 - don't error if the logger prefix contains
+ * characters which could be interpreted as fmtlib format strings.
+ */
+TEST_F(BucketLoggerTest, FmtlibPrefix) {
+    getGlobalBucketLogger()->prefix = "abc:{def}";
+    EP_LOG_INFO("Test {}", "abc");
+}
+
+/**
+ * Regression test for MB-46900 - don't error if the logger prefix contains
+ * characters which is an invalid fmtlib format string.
+ */
+TEST_F(BucketLoggerTest, IllegalFmtlibPrefix) {
+    getGlobalBucketLogger()->prefix = "abc:{def";
+    EP_LOG_INFO("Test {}", "abc");
+}
+
 /**
  * Test class with ThreadGates that allows us to test the destruction of a
  * BucketLogger when it is owned solely by the background flushing thread.