RSDK-5986 - module logging propagation and resource-level loggers

src/viam/examples/modules/complex/gizmo/impl.cpp

@@ -13,8 +13,8 @@
 
 using namespace viam::sdk;
 
-std::string find_arg1(ResourceConfig cfg) {
-    auto gizmo_name = cfg.name();
+std::string find_arg1(const ResourceConfig& cfg) {
+    const auto& gizmo_name = cfg.name();
     auto arg1 = cfg.attributes().find("arg1");
     if (arg1 == cfg.attributes().end()) {
         std::ostringstream buffer;
@@ -31,11 +31,11 @@ std::string find_arg1(ResourceConfig cfg) {
     return *arg1_string;
 }
 
-void MyGizmo::reconfigure(const Dependencies& deps, const ResourceConfig& cfg) {
+void MyGizmo::reconfigure(const Dependencies&, const ResourceConfig& cfg) {
     arg1_ = find_arg1(cfg);
 }
 
-std::vector<std::string> MyGizmo::validate(ResourceConfig cfg) {
+std::vector<std::string> MyGizmo::validate(const ResourceConfig& cfg) {
     // Custom validation can be done by specifying a validate function at the
     // time of resource registration (see complex/main.cpp) like this one.
     // Validate functions can `throw` exceptions that will be returned to the

src/viam/examples/modules/complex/gizmo/impl.hpp

@@ -19,7 +19,7 @@ class MyGizmo : public Gizmo, public Reconfigurable {
         this->reconfigure(deps, cfg);
     };
     void reconfigure(const Dependencies& deps, const ResourceConfig& cfg) override;
-    static std::vector<std::string> validate(ResourceConfig cfg);
+    static std::vector<std::string> validate(const ResourceConfig& cfg);
 
     bool do_one(std::string arg1) override;
     bool do_one_client_stream(std::vector<std::string> arg1) override;

src/viam/examples/modules/complex/main.cpp

@@ -1,7 +1,6 @@
 #include <memory>
 #include <signal.h>
 
-#include <boost/log/trivial.hpp>
 #include <grpcpp/grpcpp.h>
 #include <grpcpp/server_context.h>
 

src/viam/examples/modules/complex/proto/buf.lock

@@ -4,5 +4,5 @@ deps:
   - remote: buf.build
     owner: googleapis
     repository: googleapis
-    commit: e7f8d366f5264595bcc4cd4139af9973
-    digest: shake256:e5e5f1c12f82e028ea696faa43b4f9dc6258a6d1226282962a8c8b282e10946281d815884f574bd279ebd9cd7588629beb3db17b892af6c33b56f92f8f67f509
+    commit: f52d4f76a8434cc5966798b1d3b4f110
+    digest: shake256:71566dd80e39b7d85fdaa9b7f82107385181d5b6d17ea56c0aacce61099b35f9f1bcf7333ad9838ca19d24d7f076b039de7c9c09c55d23bb4c2fddfceff4d2c2

src/viam/examples/modules/simple/main.cpp

@@ -2,7 +2,6 @@
 #include <memory>
 #include <sstream>
 
-#include <boost/log/trivial.hpp>
 #include <grpcpp/grpcpp.h>
 #include <grpcpp/server_context.h>
 

src/viam/sdk/CMakeLists.txt

@@ -49,6 +49,7 @@ target_sources(viamsdk
     common/client_helper.cpp
     common/exception.cpp
     common/linear_algebra.cpp
+    common/logger.cpp
     common/pose.cpp
     common/proto_value.cpp
     common/service_helper.cpp
@@ -137,6 +138,7 @@ target_sources(viamsdk
       ../../viam/sdk/common/client_helper.hpp
       ../../viam/sdk/common/exception.hpp
       ../../viam/sdk/common/linear_algebra.hpp
+      ../../viam/sdk/common/logger.hpp
       ../../viam/sdk/common/pose.hpp
       ../../viam/sdk/common/proto_value.hpp
       ../../viam/sdk/common/service_helper.hpp

src/viam/sdk/common/client_helper.cpp

@@ -2,16 +2,18 @@
 
 #include <cstdlib>
 
-#include <boost/log/trivial.hpp>
+#include <viam/sdk/common/logger.hpp>
 
 namespace viam {
 namespace sdk {
 
 namespace client_helper_details {
 
 [[noreturn]] void errorHandlerReturnedUnexpectedly(const ::grpc::Status& status) noexcept {
-    BOOST_LOG_TRIVIAL(fatal) << "ClientHelper error handler callback returned instead of throwing: "
-                             << status.error_message() << '(' << status.error_details() << ')';
+    VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(
+        log_level::fatal,
+        "ClientHelper error handler callback returned instead of throwing: "
+            << status.error_message() << '(' << status.error_details() << ')');
     std::abort();
 }
 

src/viam/sdk/common/logger.cpp

@@ -0,0 +1,214 @@
+#include <viam/sdk/common/logger.hpp>
+
+#include <atomic>
+#include <iostream>
+
+#include <boost/date_time/posix_time/posix_time_types.hpp>
+#include <boost/log/attributes/mutable_constant.hpp>
+#include <boost/log/core.hpp>
+#include <boost/log/expressions.hpp>
+#include <boost/log/sources/severity_logger.hpp>
+#include <boost/log/support/date_time.hpp>
+#include <boost/log/trivial.hpp>
+#include <boost/log/utility/setup/common_attributes.hpp>
+#include <boost/log/utility/setup/console.hpp>
+#include <boost/log/utility/setup/file.hpp>
+
+namespace viam {
+namespace sdk {
+
+namespace logging = boost::log;
+namespace attrs = boost::log::attributes;
+namespace expr = boost::log::expressions;
+namespace keywords = boost::log::keywords;
+
+using ll = log_level;
+using bll = logging::trivial::severity_level;
+
+struct Logger::impl {
+    impl()
+        : logger_(std::make_shared<logging::sources::severity_logger<bll>>()), level_(ll::info) {}
+    impl(ll level)
+        : logger_(std::make_shared<logging::sources::severity_logger<bll>>()), level_(level) {}
+
+    std::shared_ptr<logging::sources::severity_logger<bll>> logger_;
+    ll level_;
+};
+
+// Convert file path to only the filename
+std::string path_to_filename(const std::string& path) {
+    return path.substr(path.find_last_of("/\\") + 1);
+}
+
+namespace {
+std::atomic<bool> inited(false);
+std::atomic<bool> inited_with_ostrm(false);
+}  // namespace
+
+std::shared_ptr<Logger> default_logger() {
+    static const auto default_logger = [] { return std::make_shared<Logger>("viam-cpp-sdk"); }();
+    return default_logger;
+}
+
+void init_attributes() {
+    logging::core::get()->add_thread_attribute("File", attrs::mutable_constant<std::string>(""));
+    logging::core::get()->add_thread_attribute("LogLevel",
+                                               attrs::mutable_constant<std::string>(""));
+    logging::core::get()->add_thread_attribute("LoggerName",
+                                               attrs::mutable_constant<std::string>(""));
+    logging::core::get()->add_thread_attribute("Line", attrs::mutable_constant<int>(0));
+}
+
+ll Logger::from_string(std::string str) {
+    std::transform(str.begin(), str.end(), str.begin(), ::tolower);
+    if (str == "info") {
+        return ll::info;
+    } else if (str == "warn" || str == "warning") {
+        return ll::warning;
+    } else if (str == "error") {
+        return ll::error;
+    } else if (str == "debug") {
+        return ll::debug;
+    } else if (str == "trace") {
+        return ll::trace;
+    } else if (str == "fatal") {
+        return ll::fatal;
+    }
+
+    VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(
+        ll::warning,
+        "attempted to convert log level string with unknown level "
+            << str << ". defaulting to INFO level");
+    return ll::info;
+}
+
+void Logger::init_logging(std::ostream& strm) {
+    if (inited_with_ostrm) {
+        return;
+    }
+    inited_with_ostrm = true;
+
+    // remove existing stdout/stderr logging since we're sending logs to RDK
+    logging::core::get()->remove_all_sinks();
+
+    logging::add_common_attributes();
+    init_attributes();
+
+    // The current use case for init logging
+    logging::add_console_log(strm,
+                             boost::parameter::keyword<keywords::tag::format>::get() =
+                                 (expr::stream << '[' << expr::attr<std::string>("File") << ':'
+                                               << expr::attr<int>("Line") << "]    "));
+}
+
+void Logger::init_logging() {
+    init_attributes();
+    if (inited || inited_with_ostrm) {
+        return;
+    }
+    inited = true;
+    logging::add_common_attributes();
+
+    logging::add_console_log(
+        std::clog,
+        boost::parameter::keyword<keywords::tag::format>::get() =
+            (expr::stream << expr::format_date_time<boost::posix_time::ptime>(
+                                 "TimeStamp", "%Y-%m-%d_%H:%M:%S.%f")
+                          << ": [" << boost::log::trivial::severity << "] "
+                          << expr::attr<std::string>("LoggerName") << " ["
+                          << expr::attr<std::string>("File") << ':' << expr::attr<int>("Line")
+                          << "]    " << expr::smessage));
+}
+
+void Logger::set_log_level(ll level) {
+    level_ = level;
+}
+
+Logger::Logger(std::string name)
+    : name_(std::move(name)), level_(log_level::info), impl_(std::make_unique<impl>()){};
+Logger::Logger(std::string name, log_level level)
+    : name_(std::move(name)), level_(level), impl_(std::make_unique<impl>(level)){};
+
+logging::trivial::severity_level _log_level_to_severity_level(log_level level) {
+    switch (level) {
+        case ll::error: {
+            return bll::error;
+        }
+        case ll::warning: {
+            return bll::warning;
+        }
+        case ll::debug: {
+            return bll::debug;
+        }
+        case ll::fatal: {
+            return bll::fatal;
+        }
+        case ll::trace: {
+            return bll::trace;
+        }
+        case ll::info:  // fallthrough
+        default: {
+            return bll::info;
+        }
+    }
+}
+
+std::string level_to_string(log_level level) {
+    switch (level) {
+            // "fatal" is not supported by RDK, so we send "error" instead.
+        case ll::fatal:  // fallthrough
+        case ll::error: {
+            return "error";
+        }
+        case ll::warning: {
+            return "warning";
+        }
+        case ll::debug: {
+            return "debug";
+        }
+        case ll::trace: {
+            return "trace";
+        }
+        case ll::info: {
+            return "info";
+        }
+    }
+}
+
+template <typename ValueType>
+ValueType set_get_attrib(const char* name, ValueType value) {
+    auto attr = boost::log::attribute_cast<boost::log::attributes::mutable_constant<ValueType>>(
+        boost::log::core::get()->get_thread_attributes()[name]);
+    attr.set(value);
+    return attr.get();
+}
+
+void Logger::log(const std::string& msg, log_level level, const char* filename, int line_no) const {
+    if (level < level_) {
+        return;
+    }
+    // in case logging hasn't been initialized, let's set it up.
+    // (RSDK-9172) This should be called from within an initializer object that handles all SDK
+    // initialization for us.
+    init_logging();
+
+    BOOST_LOG_STREAM_WITH_PARAMS(
+        *(impl_->logger_),
+        (set_get_attrib("LogLevel", level_to_string(level)))(
+            set_get_attrib("File", path_to_filename(filename)))(set_get_attrib("Line", line_no))(
+            set_get_attrib("LoggerName", name_))(boost::log::keywords::severity =
+                                                     _log_level_to_severity_level(level)))
+        << msg;
+}
+
+void Logger::static_log_(const std::string& msg,
+                         log_level level,
+                         const char* filename,
+                         int line_no) {
+    default_logger()->log(msg, level, filename, line_no);
+}
+
+Logger::~Logger() = default;
+
+}  // namespace sdk
+}  // namespace viam