MB-30798: Update spdlog to version 1.1

As we need to make changes to spdlog we should first update
our version of it to 1.1. Make the necessary changes to
our code to use the new spdlog api.

Use the new buffer/size style string returned by fmtlib
where we perform custom formatting.

Change-Id: I616628d50008758e21a54003cf676c1eb3109cc9
Reviewed-on: http://review.couchbase.org/100224
Reviewed-by: Dave Rigby <[email protected]>
Tested-by: Build Bot <[email protected]>

Author: BenHuddleston

engines/ep/src/bucket_logger.cc

@@ -37,7 +37,7 @@ BucketLogger::BucketLogger(const BucketLogger& other)
     set_level(spdLogger->level());
 }
 
-void BucketLogger::_sink_it(spdlog::details::log_msg& msg) {
+void BucketLogger::sink_it_(spdlog::details::log_msg& msg) {
     // Get the engine pointer for logging the bucket name.
     // Normally we would wish to stop tracking memory at this point to avoid
     // tracking any allocations or de-allocations done by the logging library
@@ -74,7 +74,7 @@ void BucketLogger::_sink_it(spdlog::details::log_msg& msg) {
     }
 
     // Append the rest of the message and log
-    fmtString.append(msg.raw.c_str());
+    fmtString.append(msg.raw.data(), msg.raw.size());
     spdLogger->log(msg.level, fmtString);
 }
 

engines/ep/src/bucket_logger.h

@@ -51,7 +51,7 @@ const std::string globalBucketLoggerName = "globalBucketLogger";
  * type safety and we don't want to inline a lot of message formatting as
  * macros. One global BucketLogger object is created without sinks to perform
  * the spd style formatting without logging. Instead of "sinking" this message
- * with the BucketLogger we override the _sink_it method to prepend the
+ * with the BucketLogger we override the sink_it_ method to prepend the
  * engine name and log the message as a pre-formatted string using the
  * original spdlog::logger passed via the SERVER_API.
  *
@@ -81,7 +81,7 @@ class BucketLogger : public spdlog::logger {
             const std::string& name, const std::string& prefix = "");
 
 protected:
-    void _sink_it(spdlog::details::log_msg& msg) override;
+    void sink_it_(spdlog::details::log_msg& msg) override;
 
     // Connection ID prefix that is printed if set (printed before any other
     // prefix or message)

engines/ep/tests/module_tests/kvstore_test.cc

@@ -551,11 +551,13 @@ class MockBucketLogger : public BucketLogger {
                             const std::string& message));
 
 protected:
-    // Override the _sink_it method to redirect to the mocked method
+    // Override the sink_it_ method to redirect to the mocked method
     // Must call the mlog method to check the message details as they are
-    // bundled in the log_msg object
-    void _sink_it(spdlog::details::log_msg& msg) override {
-        mlog(msg.level, msg.raw.c_str());
+    // bundled in the log_msg object. Beware, msg.raw is not null terminated.
+    // In these test cases however we just search for a substring within the log
+    // message so this is okay.
+    void sink_it_(spdlog::details::log_msg& msg) override {
+        mlog(msg.level, msg.raw.data());
     }
 };
 

logger/custom_rotating_file_sink.cc

@@ -23,6 +23,8 @@
 #include "custom_rotating_file_sink.h"
 
 #include <platform/dirutils.h>
+#include <spdlog/details/file_helper.h>
+#include <spdlog/details/fmt_helper.h>
 #include <memory>
 
 static unsigned long find_first_logfile_id(const std::string& basename) {
@@ -64,7 +66,7 @@ custom_rotating_file_sink<Mutex>::custom_rotating_file_sink(
       _current_size(0),
       _file_helper(std::make_unique<spdlog::details::file_helper>()),
       _next_file_id(find_first_logfile_id(base_filename)) {
-    formatter = std::make_shared<spdlog::pattern_formatter>(
+    formatter = std::make_unique<spdlog::pattern_formatter>(
             log_pattern, spdlog::pattern_time_type::local);
     _file_helper->open(calc_filename());
     _current_size = _file_helper->size(); // expensive. called only once
@@ -75,17 +77,17 @@ custom_rotating_file_sink<Mutex>::custom_rotating_file_sink(
  * this class adds hooks marking the start and end of a logfile.
  */
 template <class Mutex>
-void custom_rotating_file_sink<Mutex>::_sink_it(
+void custom_rotating_file_sink<Mutex>::sink_it_(
         const spdlog::details::log_msg& msg) {
-    _current_size += msg.formatted.size();
+    _current_size += msg.raw.size();
     if (_current_size > _max_size) {
         std::unique_ptr<spdlog::details::file_helper> next =
                 std::make_unique<spdlog::details::file_helper>();
         try {
             next->open(calc_filename(), true);
             addHook(closingLogfile);
             std::swap(_file_helper, next);
-            _current_size = msg.formatted.size();
+            _current_size = msg.raw.size();
             addHook(openingLogfile);
         } catch (...) {
             // Keep on logging to the this file, but try swap at the next
@@ -94,11 +96,14 @@ void custom_rotating_file_sink<Mutex>::_sink_it(
             _next_file_id--;
         }
     }
-    _file_helper->write(msg);
+    fmt::memory_buffer formatted;
+    formatter->format(msg, formatted);
+
+    _file_helper->write(formatted);
 }
 
 template <class Mutex>
-void custom_rotating_file_sink<Mutex>::_flush() {
+void custom_rotating_file_sink<Mutex>::flush_() {
     _file_helper->flush();
 }
 
@@ -108,34 +113,43 @@ void custom_rotating_file_sink<Mutex>::addHook(const std::string& hook) {
     spdlog::details::log_msg msg;
     msg.time = spdlog::details::os::now();
     msg.level = spdlog::level::info;
-    msg.raw << hook;
+
+    // Append the hook to the msg
+    spdlog::details::fmt_helper::append_str(hook, msg.raw);
 
     if (hook == openingLogfile) {
-        msg.raw << fmt::StringRef(_file_helper->filename().data(),
-                                  _file_helper->filename().size());
+        spdlog::details::fmt_helper::append_str(
+                std::string(_file_helper->filename().data(),
+                            _file_helper->filename().size()),
+                msg.raw);
     }
-    formatter->format(msg);
-    _current_size += msg.formatted.size();
+    fmt::memory_buffer formatted;
+    formatter->format(msg, formatted);
+    _current_size += formatted.size();
 
-    _file_helper->write(msg);
+    _file_helper->write(formatted);
 }
 
+/**
+ * Create a new filename. If this breaks when updating spdlog then compare
+ * functionality to the calc_filename() method in the spdlog rotating_file_sink
+ * @tparam Mutex
+ * @return An spdlog filename
+ */
 template <class Mutex>
 spdlog::filename_t custom_rotating_file_sink<Mutex>::calc_filename() {
-    std::conditional<std::is_same<spdlog::filename_t::value_type, char>::value,
-                     fmt::MemoryWriter,
-                     fmt::WMemoryWriter>::type w;
-
     char fname[1024];
     unsigned long try_id = _next_file_id;
     do {
         sprintf(fname, "%s.%06lu.txt", _base_filename.c_str(), try_id++);
     } while (access(fname, F_OK) == 0);
 
     _next_file_id = try_id;
-
-    w.write(SPDLOG_FILENAME_T("{}"), fname);
-    return w.str();
+#if defined(_WIN32) && defined(SPDLOG_WCHAR_FILENAMES)
+    return fmt::to_wstring(fname);
+#else
+    return fmt::to_string(fname);
+#endif
 }
 
 template <class Mutex>

logger/custom_rotating_file_sink.h

@@ -25,7 +25,12 @@
 #include "config.h"
 
 #include <spdlog/sinks/base_sink.h>
-#include <spdlog/spdlog.h>
+
+namespace spdlog {
+namespace details {
+class file_helper;
+} // namespace details
+} // namespace spdlog
 
 /**
  * Customised version of spdlog's rotating_file_sink with the following
@@ -37,7 +42,7 @@
  * 2 Instead of renaming all of the files every time we're rotating to
  *   the next file we start a new log file with a higher number
  *
- * TODO: If updating spdlog from v0.14.0, check if this class also needs
+ * TODO: If updating spdlog from v1.1.0, check if this class also needs
  *       updating.
  */
 template <class Mutex>
@@ -50,8 +55,8 @@ class custom_rotating_file_sink : public spdlog::sinks::base_sink<Mutex> {
     ~custom_rotating_file_sink() override;
 
 protected:
-    void _sink_it(const spdlog::details::log_msg& msg) override;
-    void _flush() override;
+    void sink_it_(const spdlog::details::log_msg& msg) override;
+    void flush_() override;
 
 private:
     void addHook(const std::string& hook);
@@ -62,7 +67,7 @@ class custom_rotating_file_sink : public spdlog::sinks::base_sink<Mutex> {
     const std::size_t _max_size;
     std::size_t _current_size;
     std::unique_ptr<spdlog::details::file_helper> _file_helper;
-    spdlog::formatter_ptr formatter;
+    std::unique_ptr<spdlog::pattern_formatter> formatter;
     unsigned long _next_file_id;
 
     const std::string openingLogfile{"---------- Opening logfile: "};

logger/spdlogger.cc

@@ -23,18 +23,15 @@
 #include "logger_config.h"
 
 #include <memcached/engine.h>
+#include <spdlog/async.h>
+#include <spdlog/async_logger.h>
+#include <spdlog/sinks/ansicolor_sink.h>
 #include <spdlog/sinks/dist_sink.h>
 #include <spdlog/sinks/null_sink.h>
+#include <spdlog/sinks/stdout_color_sinks.h>
 #include <spdlog/sinks/stdout_sinks.h>
-#include <spdlog/spdlog.h>
 #include <chrono>
 #include <cstdio>
-
-#ifndef WIN32
-#include <spdlog/sinks/ansicolor_sink.h>
-
-#endif
-
 static const std::string logger_name{"spdlog_file_logger"};
 
 /**
@@ -44,7 +41,7 @@ static const std::string logger_name{"spdlog_file_logger"};
  * TODO: Remove the duplication in the future, by (maybe) moving
  *       the const to a header file.
  */
-static const std::string log_pattern{"%Y-%m-%dT%T.%fZ %l %v"};
+static const std::string log_pattern{"%^%Y-%m-%dT%T.%fZ %l %v%$"};
 
 /**
  * Instances of spdlog (async) file logger.
@@ -132,12 +129,11 @@ boost::optional<std::string> cb::logger::initialize(
         }
 
         if (logger_settings.console) {
-#ifdef WIN32
-            auto stderrsink = std::make_shared<spdlog::sinks::stderr_sink_mt>();
-#else
             auto stderrsink =
-                    std::make_shared<spdlog::sinks::ansicolor_stderr_sink_mt>();
-#endif
+                    std::make_shared<spdlog::sinks::stderr_color_sink_mt>();
+
+            // Set the formatting pattern of this sink
+            stderrsink->set_pattern(log_pattern);
             if (logger_settings.unit_test) {
                 stderrsink->set_level(spdlog::level::trace);
             } else {
@@ -147,25 +143,35 @@ boost::optional<std::string> cb::logger::initialize(
         }
 
         spdlog::drop(logger_name);
+
         if (logger_settings.unit_test) {
-            file_logger = spdlog::create(logger_name, sink);
+            file_logger = std::make_shared<spdlog::logger>(logger_name, sink);
         } else {
-            file_logger = spdlog::create_async(
+            // Create the default thread pool for async logging
+            spdlog::init_thread_pool(buffersz, 1);
+
+            // Get the thread pool so that we can actually construct the
+            // object with already created sinks...
+            auto tp = spdlog::thread_pool();
+            file_logger = std::make_shared<spdlog::async_logger>(
                     logger_name,
                     sink,
-                    buffersz,
-                    spdlog::async_overflow_policy::block_retry,
-                    nullptr,
-                    std::chrono::milliseconds(200));
+                    tp,
+                    spdlog::async_overflow_policy::block);
         }
+
+        file_logger->set_pattern(log_pattern);
+        file_logger->set_level(logger_settings.log_level);
+
+        // Set the flushing interval policy
+        spdlog::flush_every(std::chrono::seconds(1));
+
+        spdlog::register_logger(file_logger);
     } catch (const spdlog::spdlog_ex& ex) {
         std::string msg =
                 std::string{"Log initialization failed: "} + ex.what();
         return boost::optional<std::string>{msg};
     }
-
-    file_logger->set_pattern(log_pattern);
-    file_logger->set_level(logger_settings.log_level);
     return {};
 }
 
@@ -174,24 +180,33 @@ spdlog::logger* cb::logger::get() {
 }
 
 void cb::logger::reset() {
+    spdlog::drop(logger_name);
     file_logger.reset();
 }
 
 void cb::logger::createBlackholeLogger() {
     // delete if already exists
     spdlog::drop(logger_name);
 
-    file_logger = spdlog::create(
+    file_logger = std::make_shared<spdlog::logger>(
             logger_name, std::make_shared<spdlog::sinks::null_sink_mt>());
 
     file_logger->set_level(spdlog::level::off);
     file_logger->set_pattern(log_pattern);
+
+    spdlog::register_logger(file_logger);
 }
 
 void cb::logger::createConsoleLogger() {
     // delete if already exists
     spdlog::drop(logger_name);
-    file_logger = spdlog::stderr_color_mt(logger_name);
+
+    auto stderrsink =
+            std::make_shared<spdlog::sinks::ansicolor_stderr_sink_mt>();
+
+    file_logger = std::make_shared<spdlog::logger>(logger_name, stderrsink);
     file_logger->set_level(spdlog::level::info);
     file_logger->set_pattern(log_pattern);
+
+    spdlog::register_logger(file_logger);
 }