Add PrefixLogger which appends some predefined context to logs

Refactor more of BucketLogger into the core. PrefixLogger instances can
be used to create a logger scoped to a component, like we already do
with EP-Engine and DCP ConnHandler logging.

Note PrefixLogger, like other loggers, needs to be registered if the
logger needs to support dynamic change of verbosity. In the future, we
could have a (one) PrefixLogger instance in the core which reads conn_id
and other thread_local state and automatically prefixes logs with that.

Now BucketLogger is left only with the functionality of prepending the
engine and conn_id.

Change-Id: I4531991e047b41bfda54fcaec2e432fb900f1613
Reviewed-on: https://review.couchbase.org/c/kv_engine/+/226362
Tested-by: Build Bot <build@couchbase.com>
Reviewed-by: Trond Norbye <trond.norbye@couchbase.com>

Author: veselink1

engines/ep/src/bucket_logger.cc

@@ -20,7 +20,7 @@
 // Construct the base logger with a nullptr for the sinks as they will never be
 // used. Requires a unique name for registry
 BucketLogger::BucketLogger(const std::string& name)
-    : Logger(name, cb::logger::get()) {
+    : PrefixLogger(name, cb::logger::get()) {
 }
 
 void BucketLogger::logWithContext(spdlog::level::level_enum lvl,
@@ -40,40 +40,31 @@ void BucketLogger::logWithContext(spdlog::level::level_enum lvl,
     // handler - see MB-61032.
     NonBucketAllocationGuard guard;
     try {
-        if (!ctx.is_object()) {
-#if CB_DEVELOPMENT_ASSERTS
-            throw std::invalid_argument(fmt::format(
-                    "JSON context must be an object, not `{}`", ctx.dump()));
-#else
-            // In production, handle this case gracefully.
-            ctx = Json{{"context", std::move(ctx)}};
-#endif
-        }
-
-        auto& object = ctx.get_ref<cb::logger::Json::object_t&>();
-        object.reserve(object.size() + prefixContext.size() + bool(engine) +
-                       bool(connectionId));
+        using namespace cb::logger;
+        // Get the prefix early so we can reserve space in the final context.
+        Json basePrefix = static_cast<BasicJsonType>(getContextPrefix());
+        // Create a new context object into which we will merge all keys.
+        // Final context is the conn_id + engine + static prefix + context.
+        Json finalContext = Json::object();
+        finalContext.get_ref<Json::object_t&>().reserve(
+                ctx.size() + basePrefix.size() + bool(engine) +
+                bool(connectionId));
 
-        if (!prefixContext.empty()) {
-            const auto& prefixObject =
-                    prefixContext.get_ref<const nlohmann::json::object_t&>();
-            for (auto it = prefixObject.crbegin(); it != prefixObject.crend();
-                 ++it) {
-                object.insert(object.begin(),
-                              cb::logger::Json{it->first, it->second});
-            }
+        // Write the ID.
+        if (connectionId != 0) {
+            finalContext["conn_id"] = connectionId;
         }
 
         // Write the bucket
         if (engine) {
-            object.insert(object.begin(), {"bucket", engine->getName()});
-        }
-        // Write the ID.
-        if (connectionId != 0) {
-            object.insert(object.begin(), {"conn_id", connectionId});
+            finalContext["bucket"] = engine->getName();
         }
 
-        Logger::logWithContext(lvl, msg, std::move(ctx));
+        mergeContext(finalContext, std::move(basePrefix));
+        mergeContext(finalContext, std::move(ctx));
+        // Call the Logger, not the PrefixLogger, since we don't want to add
+        // the prefix again.
+        Logger::logWithContext(lvl, msg, std::move(finalContext));
     } catch (const std::exception& e) {
         // Log a fixed message about this failing - we can't really be sure
         // what arguments failed above.

engines/ep/src/bucket_logger.h

@@ -11,8 +11,7 @@
 
 #pragma once
 
-#include "logger/logger.h"
-#include "spdlog/logger.h"
+#include "logger/prefix_logger.h"
 #include <fmt/core.h>
 #include <platform/json_log.h>
 #include <spdlog/fmt/ostr.h>
@@ -80,7 +79,7 @@ const std::string globalBucketLoggerName = "globalBucketLogger";
  * is registered correctly. BucketLoggers must be registered to ensure that
  * their verbosity can be changed at runtime.
  */
-class BucketLogger : public cb::logger::Logger {
+class BucketLogger : public cb::logger::PrefixLogger {
 public:
     /**
      * Record a log message for the bucket currently associated with the calling
@@ -111,12 +110,6 @@ class BucketLogger : public cb::logger::Logger {
         this->connectionId = id;
     }
 
-    /// The prefix printed before the log message contents
-    std::string prefix;
-
-    /// Context to merge into logs.
-    nlohmann::json prefixContext;
-
 protected:
     /**
      * Connection ID prefix that is printed if set (printed before any other

engines/ep/src/connhandler.cc

@@ -380,12 +380,11 @@ void ConnHandler::pause(ConnHandler::PausedReason r) {
 
 void ConnHandler::setLogContext(const std::string& header,
                                 const nlohmann::json& ctx) {
-    logger->prefix = header;
-    logger->prefixContext = ctx;
+    logger->setPrefix(ctx, header);
 }
 
 const char* ConnHandler::logHeader() const {
-    return logger->prefix.c_str();
+    return logger->getFmtPrefix().c_str();
 }
 
 void ConnHandler::unPause() {

engines/ep/tests/module_tests/bucket_logger_test.cc

@@ -239,7 +239,7 @@ TEST_F(BucketLoggerTest, InfoContextMacroWithCurlyBraces) {
  * characters which could be interpreted as fmtlib format strings.
  */
 TEST_F(BucketLoggerTest, FmtlibPrefix) {
-    getGlobalBucketLogger()->prefix = "abc:{def}";
+    getGlobalBucketLogger()->setPrefix({}, "abc:{def}");
     EP_LOG_INFO("Test {}", "abc");
 }
 
@@ -248,7 +248,7 @@ TEST_F(BucketLoggerTest, FmtlibPrefix) {
  * characters which is an invalid fmtlib format string.
  */
 TEST_F(BucketLoggerTest, IllegalFmtlibPrefix) {
-    getGlobalBucketLogger()->prefix = "abc:{def";
+    getGlobalBucketLogger()->setPrefix({}, "abc:{def");
     EP_LOG_INFO("Test {}", "abc");
 }
 

logger/CMakeLists.txt

@@ -6,7 +6,9 @@ add_library(memcached_logger STATIC
             custom_rotating_file_sink.cc
             custom_rotating_file_sink.h
             logger_test_fixture.h
-            logger_iface.h)
+            logger_iface.h
+            prefix_logger.h
+            prefix_logger.cc)
 set_property(TARGET memcached_logger PROPERTY POSITION_INDEPENDENT_CODE 1)
 kv_enable_pch(memcached_logger)
 cb_enable_unity_build(memcached_logger)

logger/logger.h

@@ -160,6 +160,13 @@ class Logger : protected spdlog::logger,
     /// Overriden flush_ method to flush via the inner spdlog::logger.
     void flush_() override;
 
+    /**
+     * Fix up the context object to ensure it is a JSON object.
+     *
+     * @param ctx The context object to fix up.
+     */
+    void fixupContext(Json& ctx) const;
+
 private:
     /**
      * Pointer to the inner spdlog::logger.

logger/logger_test_fixture.cc

@@ -10,6 +10,7 @@
  */
 
 #include "logger_test_fixture.h"
+#include "logger/prefix_logger.h"
 
 #include <gsl/gsl-lite.hpp>
 #include <spdlog/spdlog.h>
@@ -101,3 +102,28 @@ std::string SpdloggerTest::getLogContents() {
 
     return ret;
 }
+
+TEST_F(SpdloggerTest, PrefixLogger) {
+    auto prefixLogger = std::make_shared<cb::logger::PrefixLogger>(
+            "prefix_logger", cb::logger::get());
+    prefixLogger->setPrefix(cb::logger::BasicJsonType({{"prefix", "test"}}),
+                            "prefix=test");
+
+    prefixLogger->log(spdlog::level::info, "my message");
+    prefixLogger->logWithContext(
+            spdlog::level::info, "my message", {{"key", "value"}});
+
+    cb::logger::shutdown();
+    files = cb::io::findFilesWithPrefix(config.filename);
+    ASSERT_EQ(1, files.size()) << "We should only have a single logfile";
+    EXPECT_EQ(
+            1,
+            countInFile(files.front(), "INFO my message {\"prefix\":\"test\"}"))
+            << getLogContents();
+    EXPECT_EQ(
+            1,
+            countInFile(
+                    files.front(),
+                    "INFO my message {\"prefix\":\"test\",\"key\":\"value\"}"))
+            << getLogContents();
+}

logger/prefix_logger.cc

@@ -0,0 +1,39 @@
+/*
+ *     Copyright 2025-Present Couchbase, Inc.
+ *
+ *   Use of this software is governed by the Business Source License included
+ *   in the file licenses/BSL-Couchbase.txt.  As of the Change Date specified
+ *   in that file, in accordance with the Business Source License, use of this
+ *   software will be governed by the Apache License, Version 2.0, included in
+ *   the file licenses/APL2.txt.
+ */
+
+#include "prefix_logger.h"
+
+cb::logger::PrefixLogger::PrefixLogger(const std::string& name,
+                                       std::shared_ptr<Logger> baseLogger)
+    : Logger(name, baseLogger->getSpdLogger()),
+      contextPrefix(nlohmann::ordered_json::object()) {
+}
+
+void cb::logger::PrefixLogger::setPrefix(nlohmann::ordered_json contextPrefix,
+                                         std::string_view fmtPrefix) {
+    this->contextPrefix = contextPrefix;
+    this->fmtPrefix = fmtPrefix;
+}
+
+void cb::logger::PrefixLogger::logWithContext(spdlog::level::level_enum lvl,
+                                              std::string_view msg,
+                                              Json ctx) {
+    auto finalCtx = Json(BasicJsonType(contextPrefix));
+    mergeContext(finalCtx, std::move(ctx));
+    Logger::logWithContext(lvl, msg, std::move(finalCtx));
+}
+
+void cb::logger::PrefixLogger::mergeContext(Json& dest, Json src) const {
+    fixupContext(dest);
+    fixupContext(src);
+    auto& destObj = dest.get_ref<Json::object_t&>();
+    auto& srcObj = src.get_ref<Json::object_t&>();
+    std::move(srcObj.begin(), srcObj.end(), std::back_inserter(destObj));
+}

logger/prefix_logger.h

@@ -0,0 +1,65 @@
+/*
+ *     Copyright 2025-Present Couchbase, Inc.
+ *
+ *   Use of this software is governed by the Business Source License included
+ *   in the file licenses/BSL-Couchbase.txt.  As of the Change Date specified
+ *   in that file, in accordance with the Business Source License, use of this
+ *   software will be governed by the Apache License, Version 2.0, included in
+ *   the file licenses/APL2.txt.
+ */
+
+#pragma once
+
+#include "logger/logger.h"
+
+namespace cb::logger {
+
+/**
+ * A logger that prefixes all log messages with a context.
+ */
+class PrefixLogger : public Logger {
+public:
+    PrefixLogger(const std::string& name, std::shared_ptr<Logger> baseLogger);
+
+    void logWithContext(spdlog::level::level_enum lvl,
+                        std::string_view msg,
+                        Json ctx) override;
+
+    /**
+     * Set the prefix for the logger.
+     *
+     * @param contextPrefix The prefix to be added to a JSON context message.
+     * @param fmtPrefix The prefix to be added to a fmtlib formatted message.
+     */
+    void setPrefix(nlohmann::ordered_json contextPrefix,
+                   std::string_view fmtPrefix);
+
+    const nlohmann::ordered_json& getContextPrefix() const {
+        return contextPrefix;
+    }
+
+    const std::string& getFmtPrefix() const {
+        return fmtPrefix;
+    }
+
+protected:
+    /**
+     * Append the source object to the destination context.
+     */
+    void mergeContext(Json& dest, Json src) const;
+
+private:
+    /**
+     * The prefix to be added to a JSON context message.
+     */
+    nlohmann::ordered_json contextPrefix;
+
+    /**
+     * The prefix to be added to a fmtlib formatted message.
+     * Note: this is currently not used for formatting, but can be read back
+     * from the instance, which is currently used.
+     */
+    std::string fmtPrefix;
+};
+
+} // namespace cb::logger

logger/spdlogger.cc

@@ -81,6 +81,22 @@ void cb::logger::Logger::flush_() {
     baseLogger->flush();
 }
 
+void cb::logger::Logger::fixupContext(Json& ctx) const {
+    if (ctx.is_null()) {
+        ctx = Json::object();
+        return;
+    }
+    if (!ctx.is_object()) {
+#if CB_DEVELOPMENT_ASSERTS
+        throw std::invalid_argument(fmt::format(
+                "JSON context must be an object, not `{}`", ctx.dump()));
+#else
+        // In production, handle this case gracefully.
+        ctx = Json{{"context", std::move(ctx)}};
+#endif
+    }
+}
+
 void cb::logger::Logger::logFormatted(spdlog::level::level_enum lvl,
                                       fmt::string_view fmt,
                                       fmt::format_args args) {
@@ -366,15 +382,7 @@ void cb::logger::setLogLevels(spdlog::level::level_enum level) {
 void cb::logger::Logger::logWithContext(spdlog::level::level_enum lvl,
                                         std::string_view msg,
                                         Json ctx) {
-    if (!ctx.is_object()) {
-#if CB_DEVELOPMENT_ASSERTS
-        throw std::invalid_argument(fmt::format(
-                "JSON context must be an object, not `{}`", ctx.dump()));
-#else
-        // In production, handle this case gracefully.
-        ctx = Json{{"context", std::move(ctx)}};
-#endif
-    }
+    fixupContext(ctx);
 
     // TODO: Consider checking that the message conforms to the conventions and
     // doesn't contain ".:()", starts with a capital, etc.