it's working, needs cleanup

Author: stuqdog

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

@@ -53,7 +53,6 @@ int main() {
     // of that type from the server.
     Registry::register_resource_client<GizmoClient>();
     Registry::register_resource_client<SummationClient>();
-    std::cout << "We are here!!!!\n\n\n" << std::flush;
 
     // Connect to robot.
     std::shared_ptr<RobotClient> robot = RobotClient::at_address(host, options);

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

@@ -8,6 +8,7 @@
 #include <boost/log/sources/logger.hpp>
 #include <boost/log/trivial.hpp>
 #include <viam/sdk/common/client_helper.hpp>
+#include <viam/sdk/common/logger.hpp>
 #include <viam/sdk/common/utils.hpp>
 #include <viam/sdk/registry/registry.hpp>
 #include <viam/sdk/resource/resource.hpp>
@@ -27,17 +28,7 @@ API API::traits<Gizmo>::api() {
     return {"viam", "component", "gizmo"};
 }
 
-Gizmo::Gizmo(std::string name)
-    : Component(std::move(name)) {
-          // boost::log::sources::severity_logger<boost::log::trivial::severity_level> lg;
-          // BOOST_LOG_SEV(lg, boost::log::trivial::severity_level::debug) << "debug test";
-          // BOOST_LOG_SEV(lg, boost::log::trivial::severity_level::info) << "info test";
-          // BOOST_LOG_SEV(lg, boost::log::trivial::severity_level::warning) << "warning test";
-          // BOOST_LOG_SEV(lg, boost::log::trivial::severity_level::error) << "error test";
-          // BOOST_LOG_TRIVIAL(error) << "gizmo created error\n";
-          // BOOST_LOG_TRIVIAL(info) << "gizmo created info\n";
-          // BOOST_LOG_TRIVIAL(debug) << "gizmo created debug\n";
-      };
+Gizmo::Gizmo(std::string name) : Component(std::move(name)) {};
 
 /* Gizmo server methods */
 
@@ -188,20 +179,11 @@ GizmoClient::GizmoClient(std::string name, std::shared_ptr<grpc::Channel> channe
       channel_(std::move(channel)) {};
 
 bool GizmoClient::do_one(std::string arg1) {
-    BOOST_LOG_SEV(*(logger_.underlying()), boost::log::trivial::severity_level::error)
-        << "some other new error log";
-    logger_.info("new info log");
-    logger_.debug("new debug log");
-    logger_.error("new error log");
+    BOOST_LOG_TRIVIAL(error) << "log in client the old way";
+    VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, log_level::error, "log in client the new way");
     return make_client_helper(this, *stub_, &StubType::DoOne)
-        .with([&](auto& request) {
-            std::cout << "in with\n" << std::flush;
-            request.set_arg1(arg1);
-        })
-        .invoke([](auto& response) {
-            std::cout << "in invoke\n" << std::flush;
-            return response.ret1();
-        });
+        .with([&](auto& request) { request.set_arg1(arg1); })
+        .invoke([](auto& response) { return response.ret1(); });
 }
 
 bool GizmoClient::do_one_client_stream(std::vector<std::string> arg1) {

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

@@ -5,8 +5,11 @@
 #include <sstream>
 #include <vector>
 
+#include <boost/log/core.hpp>
+#include <boost/log/trivial.hpp>
 #include <grpcpp/support/status.h>
 
+#include <viam/sdk/common/logger.hpp>
 #include <viam/sdk/components/component.hpp>
 #include <viam/sdk/config/resource.hpp>
 #include <viam/sdk/resource/resource.hpp>
@@ -50,14 +53,9 @@ std::vector<std::string> MyGizmo::validate(const ResourceConfig& cfg) {
 }
 
 bool MyGizmo::do_one(std::string arg1) {
-    std::cout << "it's a myGizmo!";
-    // CR erodkin: these logs break things when init_logging_() is called. figure out why!
-    // also we're now getting an error when stopping the viam-server that the mod manager didn't
-    // close properly so probably we should figure that out too
-    // logger_.error("new error log in do_one");
-    logger_.debug("new debug log in do_one");
-    std::cout << "did a debug log now let's try an info one \n" << std::flush;
-    logger_.info("new info log in do_one");
+    // CR erodkin: delete this, and places where we've added boost dependencies in headers
+    VIAM_SDK_CUSTOM_FORMATTED_LOG(
+        logger_, log_level::error, "error log from impl the new way with " << 2 << " stream calls");
     return arg1_ == arg1;
 }
 

src/viam/sdk/common/client_helper.hpp

@@ -79,11 +79,8 @@ class ClientHelper {
         if (debug_key_ != "") {
             ctx.set_debug_key(debug_key_);
         }
-        std::cout << "getting result\n" << std::flush;
         const auto result = (stub_->*pfn_)(ctx, request_, &response_);
-        std::cout << "got result\n" << std::flush;
         if (result.ok()) {
-            std::cout << "got bad result\n" << std::flush;
             return std::forward<ResponseHandlerCallable>(rhc)(
                 const_cast<const ResponseType&>(response_));
         }

src/viam/sdk/common/logger.cpp

@@ -1,15 +1,28 @@
 #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;
-using ll = Logger::log_level;
+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 {
@@ -22,16 +35,67 @@ struct Logger::impl {
     ll level_;
 };
 
-std::shared_ptr<logging::sources::severity_logger<bll>> Logger::underlying() {
-    return impl_->logger_;
+// 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;
+}
+
+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));
+}
+
+void init_logging(std::ostream& strm) {
+    if (inited) {
+        return;
+    }
+    inited = true;
+
+    init_attributes();
+
+    // remove existing stdout/stderr logging since we're sending logs to RDK
+    boost::log::core::get()->remove_all_sinks();
+
+    logging::add_console_log(strm,
+                             boost::parameter::keyword<keywords::tag::format>::get() =
+                                 (expr::stream << '[' << expr::attr<std::string>("File") << ':'
+                                               << expr::attr<int>("Line") << "]    "));
+    logging::add_common_attributes();
+}
+
+void init_logging() {
+    if (inited) {
+        return;
+    }
+    inited = true;
+
+    init_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>("File") << ':' << expr::attr<int>("Line")
+                          << "] " << expr::smessage));
+    logging::add_common_attributes();
 }
 
 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(Logger::log_level level) {
+logging::trivial::severity_level _log_level_to_severity_level(log_level level) {
     switch (level) {
         case ll::error: {
             return bll::error;
@@ -55,29 +119,63 @@ logging::trivial::severity_level _log_level_to_severity_level(Logger::log_level
     }
 }
 
-void Logger::log(const std::string& log, log_level level) const {
-    if (impl_->level_ > level) {
-        return;
+std::string level_to_string(log_level level) {
+    switch (level) {
+        case ll::error: {
+            return "error";
+        }
+        case ll::warning: {
+            return "warning";
+        }
+        case ll::debug: {
+            return "debug";
+        }
+        case ll::fatal: {
+            return "fatal";
+        }
+        case ll::trace: {
+            return "trace";
+        }
+        case ll::info: {
+            return "info";
+        }
     }
-    BOOST_LOG_SEV(*(impl_->logger_), _log_level_to_severity_level(level)) << log;
-}
-void Logger::debug(const std::string& log) const {
-    this->log(log, ll::debug);
-}
-void Logger::error(const std::string& log) const {
-    this->log(log, ll::error);
-}
-void Logger::fatal(const std::string& log) const {
-    this->log(log, ll::fatal);
-}
-void Logger::info(const std::string& log) const {
-    this->log(log, ll::info);
 }
-void Logger::trace(const std::string& log) const {
-    this->log(log, ll::trace);
+
+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::warning(const std::string& log) const {
-    this->log(log, ll::warning);
+
+std::string Logger::log_delineator() {
+    // a bit hacky, the problem is we need some way of including log level and logger name
+    // information that can be passed to a `robot_client.log(...)` call. Storing this information
+    // as a boost keyword attribute (the way we do for `File` and `Line`) isn't sufficient because,
+    // while there's always a file and line no that's being called from, there isn't always a named
+    // logger or an established log level being used (e.g., a client could be calling a `BOOST_LOG`
+    // macro that doesn't support severity level directly, without using one of our named loggers).
+    // In such a case, we'd be passing along whatever logger name and level were previously set,
+    // which isn't great. So, we use the delineator as a sentinel string to split up our actual log
+    // message, our level, and our logger name that is qualified enough to (hopefully) never see
+    // collisions.
+    static std::string delineator("  __VIAM_IMPL_LOG_DELINEATOR__  ");
+    return delineator;
+}  // namespace sdk
+
+void Logger::log(const std::string& msg, log_level level, const char* filename, int line_no) const {
+    std::cout << "in the implementation log call!\n" << std::flush;
+    // in case logging hasn't been initialized, let's set it up.
+    init_logging();
+    set_get_attrib("LogLevel", level_to_string(level));
+    set_get_attrib("LoggerName", name_);
+    BOOST_LOG_STREAM_WITH_PARAMS(
+        *(impl_->logger_),
+        (set_get_attrib("File", viam::sdk::path_to_filename(filename)))(set_get_attrib(
+            "Line", line_no))(boost::log::keywords::severity = _log_level_to_severity_level(level)))
+        << msg;
 }
 
 Logger::~Logger() = default;