MB-46216: Check log format strings at compile-time (ep-engine)

Make use of the FMT_STRING macro to check format strings at
compile-time using fmtlib v7 in ep-engine.

If a call to the logger omits one or more arguments, then a
compile-time error will be seen - given the following (incorrect) call
missing a argument for 'bar':

    EP_LOG_DEBUG("Foo:{} bar:{}", foo);

The compiler fails with:

   fmt/format.h:2873:27: constexpr variable 'invalid_format' must be initialized by a constant expression

(admittedly not the most obvious, but you get what you get with C++
compiler errors...)

Note that this now requires that the EP_LOG_<LEVEL> macros always take
a valid fmtlib format string as the first argument, a raw string
literal is no longer supported - the following will no longer compile:

    EP_LOG_DEBUG("Something happened"); // compile-time error.

Instead, the _RAW macros added in the previous patch should be used:

    EP_LOG_DEBUG_RAW("Something else happened"); OK

Note: The issue here is that to perform compile-time format string
      checking, the format string must be wrapped in FMT_STRING() -
      before the format string is evaluated / passed into the actual
      logging functions / methods. However, one cannot pass a
      non-string literal to FMT_STRING - essentially by design it
      fails at compile-time if it doesn't have {} placeholders.

      To address this (and still allow both styles of parameters) we
      _could_ in theory do some complex preprocessor logic - count the
      number of variadic arguments at compile-time and only apply
      FMT_STRING() macro to first if there is 2 or more arguments in
      total. I got something working for GCC and clang and which did
      this, but it didn't work for MSVC and the GCC one triggered a
      load of warnings, hence just making original macros always
      fmt-style, and adding _RAW for plan unformatted values.

Change-Id: I32c37dfc9672663e5741433885787f1e941fe795
Reviewed-on: http://review.couchbase.org/c/kv_engine/+/153272
Tested-by: Dave Rigby <daver@couchbase.com>
Reviewed-by: Ben Huddleston <ben.huddleston@couchbase.com>

Author: daverigby

engines/ep/src/bucket_logger.cc

@@ -42,6 +42,22 @@ void BucketLogger::flush_() {
     spdLogger->flush();
 }
 
+void BucketLogger::logInner(spdlog::level::level_enum lvl,
+                            fmt::string_view fmt,
+                            fmt::format_args args) {
+    EventuallyPersistentEngine* engine = ObjectRegistry::getCurrentEngine();
+    // Disable memory tracking for the formatting and logging of the message.
+    // This is necessary because the message will be written to disk (and
+    // subsequently freed) by the shared background thread (as part of
+    // spdlog::async_logger) and hence we do not know which engine to associate
+    // the deallocation to.
+    // 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));
+}
+
 void BucketLogger::setLoggerAPI(ServerLogIface* api) {
     BucketLogger::loggerAPI.store(api, std::memory_order_relaxed);
 
@@ -78,7 +94,7 @@ void BucketLogger::unregister() {
 }
 
 std::string BucketLogger::prefixStringWithBucketName(
-        const EventuallyPersistentEngine* engine, const char* fmt) {
+        const EventuallyPersistentEngine* engine, fmt::string_view fmt) {
     std::string fmtString;
 
     // Append the id (if set)
@@ -99,7 +115,7 @@ std::string BucketLogger::prefixStringWithBucketName(
     }
 
     // Append the original format string
-    fmtString.append(fmt);
+    fmtString.append(fmt.begin(), fmt.end());
     return fmtString;
 }
 

engines/ep/src/bucket_logger.h

@@ -14,7 +14,6 @@
 #include "spdlog/logger.h"
 
 #include <memcached/server_log_iface.h>
-#include <spdlog/fmt/ostr.h>
 
 class EventuallyPersistentEngine;
 
@@ -95,10 +94,9 @@ class BucketLogger : public spdlog::logger {
      * @param fmt The format string to use (fmtlib style).
      * @param args Variable arguments to include in the format string.
      */
-    template <typename... Args>
-    void log(spdlog::level::level_enum lvl,
-             const char* fmt,
-             const Args&... args);
+    template <typename S, typename... Args>
+    void log(spdlog::level::level_enum lvl, const S& fmt, Args&&... args);
+
     template <typename... Args>
     void log(spdlog::level::level_enum lvl, const char* msg);
     template <typename T>
@@ -179,19 +177,16 @@ class BucketLogger : public spdlog::logger {
     /// Overriden flush_ method to flush via the ServerAPI logger.
     void flush_() override;
 
-    template <typename... Args>
     void logInner(spdlog::level::level_enum lvl,
-                  const char* fmt,
-                  const Args&... args);
-    template <typename T>
-    void logInner(spdlog::level::level_enum lvl, const T& msg);
+                  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, const char* fmt);
+            const EventuallyPersistentEngine* engine, fmt::string_view fmt);
 
     /**
      * Connection ID prefix that is printed if set (printed before any other
@@ -244,11 +239,21 @@ std::shared_ptr<BucketLogger>& getGlobalBucketLogger();
 // Various implementation details for the EP_LOG_<level> macros below.
 // End-users shouldn't use these directly, instead use EP_LOG_<level>.
 
-#define EP_LOG_FMT(severity, ...)                                \
-    do {                                                         \
-        if (getGlobalBucketLogger()->should_log(severity)) {     \
-            getGlobalBucketLogger()->log(severity, __VA_ARGS__); \
-        }                                                        \
+// Visual Studio prior to 2019 doens't correctly handle the constexpr
+// format string checking - see https://github.com/fmtlib/fmt/issues/2328.
+// As such, only apply the compile-time check for non-MSVC or VS 2019+
+#if FMT_MSC_VER && FMT_MSC_VER < 1920
+#define CHECK_FMT_STRING(fmt) fmt
+#else
+#define CHECK_FMT_STRING(fmt) FMT_STRING(fmt)
+#endif
+
+#define EP_LOG_FMT(severity, fmt, ...)                                 \
+    do {                                                               \
+        auto& logger = getGlobalBucketLogger();                        \
+        if (logger->should_log(severity)) {                            \
+            logger->log(severity, CHECK_FMT_STRING(fmt), __VA_ARGS__); \
+        }                                                              \
     } while (false)
 
 #define EP_LOG_RAW(severity, msg)               \
@@ -259,6 +264,23 @@ std::shared_ptr<BucketLogger>& getGlobalBucketLogger();
         }                                       \
     } while (false)
 
+// Convenience macros which call globalBucketLogger->log() with the given level,
+// format string and variadic arguments.
+// @param fmt Format string in fmtlib style (https://fmt.dev)
+// @param args Variable-length arguments, matching the number of placeholders
+//             ({}) specified in the format string.
+//
+// For example:
+//
+//     EP_LOG_INFO("Starting flusher on bucket:{} at {}", bucketName, now);
+//
+// Due to the combination of compile-time checking of format string (which must
+// be a string literal), these macros require both a format string and at least
+// one argument - i.e. you can't just pass a single element such as:
+//
+//     EP_LOG_INFO("Fixed message")
+//
+// Instead, see the EP_LOG_<LEVEL>_R (Raw) macros below.
 #define EP_LOG_TRACE(...) \
     EP_LOG_FMT(spdlog::level::level_enum::trace, __VA_ARGS__)
 

engines/ep/src/bucket_logger_impl.h

@@ -10,36 +10,36 @@
  */
 #pragma once
 
-#include "objectregistry.h"
+#include <spdlog/fmt/ostr.h>
 
 /*
  * Definitions of BucketLogger code which must be inline.
  */
 
-template <typename... Args>
+template <typename S, typename... Args>
 void BucketLogger::log(spdlog::level::level_enum lvl,
-                       const char* fmt,
-                       const Args&... args) {
+                       const S& fmt,
+                       Args&&... args) {
     if (!should_log(lvl)) {
         return;
     }
-    logInner(lvl, fmt, args...);
+    logInner(lvl, fmt, fmt::make_args_checked<Args...>(fmt, args...));
 }
 
 template <typename... Args>
 void BucketLogger::log(spdlog::level::level_enum lvl, const char* msg) {
     if (!should_log(lvl)) {
         return;
     }
-    logInner(lvl, msg);
+    logInner(lvl, msg, {});
 }
 
 template <typename T>
 void BucketLogger::log(spdlog::level::level_enum lvl, const T& msg) {
     if (!should_log(lvl)) {
         return;
     }
-    logInner(lvl, msg);
+    logInner(lvl, "{}", fmt::make_args_checked<T>("{}", msg));
 }
 
 template <typename... Args>
@@ -101,30 +101,3 @@ template <typename T>
 void BucketLogger::critical(const T& msg) {
     log(spdlog::level::critical, msg);
 }
-
-template <typename... Args>
-void BucketLogger::logInner(spdlog::level::level_enum lvl,
-                            const char* fmt,
-                            const Args&... args) {
-    EventuallyPersistentEngine* engine = ObjectRegistry::getCurrentEngine();
-    // Disable memory tracking for the formatting and logging of the message.
-    // This is necessary because the message will be written to disk (and
-    // subsequently freed) by the shared background thread (as part of
-    // spdlog::async_logger) and hence we do not know which engine to associate
-    // the deallocation to.
-    // 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, prefixedFmt.c_str(), args...);
-}
-
-template <typename T>
-void BucketLogger::logInner(spdlog::level::level_enum lvl, const T& msg) {
-    EventuallyPersistentEngine* engine = ObjectRegistry::getCurrentEngine();
-    // See comment in above logInner overload for why NonBucketAllocationGuard
-    // is required.
-    NonBucketAllocationGuard guard;
-    const auto prefixedMsg = prefixStringWithBucketName(engine, "");
-    spdlog::logger::log(lvl, "{}{}", prefixedMsg.c_str(), msg);
-}

engines/ep/src/cb3_executorpool.cc

@@ -14,6 +14,7 @@
 #include "cb3_executorthread.h"
 #include "ep_engine.h"
 #include "ep_time.h"
+#include "objectregistry.h"
 #include "taskqueue.h"
 
 #include <nlohmann/json.hpp>

engines/ep/src/cb3_executorthread.cc

@@ -13,6 +13,7 @@
 #include "bucket_logger.h"
 #include "cb3_executorpool.h"
 #include "globaltask.h"
+#include "objectregistry.h"
 #include "taskqueue.h"
 
 #include <folly/Portability.h>

engines/ep/src/dcp/consumer.cc

@@ -23,6 +23,7 @@
 #include "executorpool.h"
 #include "failover-table.h"
 #include "kv_bucket.h"
+#include "objectregistry.h"
 #include "replicationthrottle.h"
 
 #include <memcached/server_cookie_iface.h>

engines/ep/src/dcp/dcpconnmap.cc

@@ -18,6 +18,7 @@
 #include "dcp/consumer.h"
 #include "dcp/producer.h"
 #include "ep_engine.h"
+#include "objectregistry.h"
 #include <daemon/tracing.h>
 #include <memcached/server_cookie_iface.h>
 #include <memcached/vbucket.h>

engines/ep/src/dcp/producer.cc

@@ -29,6 +29,7 @@
 #include "failover-table.h"
 #include "item_eviction.h"
 #include "kv_bucket.h"
+#include "objectregistry.h"
 #include "snappy-c.h"
 
 #include <memcached/server_cookie_iface.h>

engines/ep/src/flusher.cc

@@ -14,6 +14,7 @@
 #include "bucket_logger.h"
 #include "ep_bucket.h"
 #include "executorpool.h"
+#include "objectregistry.h"
 #include "tasks.h"
 
 #include <platform/timeutils.h>

engines/ep/src/folly_executorpool.cc

@@ -14,6 +14,7 @@
 #include "bucket_logger.h"
 #include "ep_time.h"
 #include "globaltask.h"
+#include "objectregistry.h"
 #include "taskable.h"
 
 #include <folly/executors/CPUThreadPoolExecutor.h>