diff --git a/src/viam/examples/modules/complex/gizmo/impl.cpp b/src/viam/examples/modules/complex/gizmo/impl.cpp index adbf8675a..e15fa66be 100644 --- a/src/viam/examples/modules/complex/gizmo/impl.cpp +++ b/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 MyGizmo::validate(ResourceConfig cfg) { +std::vector 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 diff --git a/src/viam/examples/modules/complex/gizmo/impl.hpp b/src/viam/examples/modules/complex/gizmo/impl.hpp index 1ca83a470..78e9e3225 100644 --- a/src/viam/examples/modules/complex/gizmo/impl.hpp +++ b/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 validate(ResourceConfig cfg); + static std::vector validate(const ResourceConfig& cfg); bool do_one(std::string arg1) override; bool do_one_client_stream(std::vector arg1) override; diff --git a/src/viam/examples/modules/complex/main.cpp b/src/viam/examples/modules/complex/main.cpp index 9b746bfff..7e57cbeae 100644 --- a/src/viam/examples/modules/complex/main.cpp +++ b/src/viam/examples/modules/complex/main.cpp @@ -1,7 +1,6 @@ #include #include -#include #include #include diff --git a/src/viam/examples/modules/complex/proto/buf.lock b/src/viam/examples/modules/complex/proto/buf.lock index 603482e23..3ad00f99b 100644 --- a/src/viam/examples/modules/complex/proto/buf.lock +++ b/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 diff --git a/src/viam/examples/modules/simple/main.cpp b/src/viam/examples/modules/simple/main.cpp index edc400347..fa207ecf9 100644 --- a/src/viam/examples/modules/simple/main.cpp +++ b/src/viam/examples/modules/simple/main.cpp @@ -2,7 +2,6 @@ #include #include -#include #include #include diff --git a/src/viam/sdk/CMakeLists.txt b/src/viam/sdk/CMakeLists.txt index 3ed83a7d5..cdc56a5c3 100644 --- a/src/viam/sdk/CMakeLists.txt +++ b/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 diff --git a/src/viam/sdk/common/client_helper.cpp b/src/viam/sdk/common/client_helper.cpp index 84990153d..c63960ee1 100644 --- a/src/viam/sdk/common/client_helper.cpp +++ b/src/viam/sdk/common/client_helper.cpp @@ -2,7 +2,7 @@ #include -#include +#include namespace viam { namespace sdk { @@ -10,8 +10,10 @@ 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(); } diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp new file mode 100644 index 000000000..8773d751d --- /dev/null +++ b/src/viam/sdk/common/logger.cpp @@ -0,0 +1,214 @@ +#include + +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +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>()), level_(ll::info) {} + impl(ll level) + : logger_(std::make_shared>()), level_(level) {} + + std::shared_ptr> 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 inited(false); +std::atomic inited_with_ostrm(false); +} // namespace + +std::shared_ptr default_logger() { + static const auto default_logger = [] { return std::make_shared("viam-cpp-sdk"); }(); + return default_logger; +} + +void init_attributes() { + logging::core::get()->add_thread_attribute("File", attrs::mutable_constant("")); + logging::core::get()->add_thread_attribute("LogLevel", + attrs::mutable_constant("")); + logging::core::get()->add_thread_attribute("LoggerName", + attrs::mutable_constant("")); + logging::core::get()->add_thread_attribute("Line", attrs::mutable_constant(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::get() = + (expr::stream << '[' << expr::attr("File") << ':' + << expr::attr("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::get() = + (expr::stream << expr::format_date_time( + "TimeStamp", "%Y-%m-%d_%H:%M:%S.%f") + << ": [" << boost::log::trivial::severity << "] " + << expr::attr("LoggerName") << " [" + << expr::attr("File") << ':' << expr::attr("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()){}; +Logger::Logger(std::string name, log_level level) + : name_(std::move(name)), level_(level), impl_(std::make_unique(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 +ValueType set_get_attrib(const char* name, ValueType value) { + auto attr = boost::log::attribute_cast>( + 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 diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp new file mode 100644 index 000000000..56cbf534b --- /dev/null +++ b/src/viam/sdk/common/logger.hpp @@ -0,0 +1,128 @@ +#pragma once + +#include +#include +#include +#include +#include + +// Some of the logic here has been cribbed from +// https://stackoverflow.com/questions/19415845/a-better-log-macro-using-template-metaprogramming + +// Workaround GCC 4.7.2 not recognizing noinline attribute +#ifndef NOINLINE_ATTRIBUTE +#ifdef __ICC +#define NOINLINE_ATTRIBUTE __attribute__((noinline)) +#else +#define NOINLINE_ATTRIBUTE +#endif // __ICC +#endif // NOINLINE_ATTRIBUTE + +// Set attribute and return the new value + +namespace viam { +namespace sdk { + +class ModuleService; + +enum class log_level : std::int8_t { + trace = -2, + debug = -1, + info = 0, // default value is info + warning = 1, + error = 2, + fatal = 3, +}; +class Logger { + public: + explicit Logger(std::string name); + explicit Logger(std::string name, log_level level); + + void set_log_level(log_level level); + void log(const std::string& msg, log_level level, const char* file, int line_no) const; + static log_level from_string(std::string str); + + struct None {}; + + template + struct LogData { + List list; + }; + + template + void static static_log(const LogData& data, + log_level level, + const char* file, + int line_no) { + std::ostringstream buffer; + output(buffer, std::move(data.list)); + static_log_(buffer.str(), level, file, line_no); + }; + + template + friend constexpr LogData> operator<<(LogData&& begin, + Value&& value) noexcept { + return {{std::forward(begin.list), std::forward(value)}}; + } + + template + friend constexpr LogData> operator<<( + LogData&& begin, const char (&value)[n]) noexcept { + return {{std::forward(begin.list), value}}; + } + + typedef std::ostringstream& (*PfnManipulator)(std::ostringstream&); + + template + friend constexpr LogData> operator<<( + LogData&& begin, PfnManipulator value) noexcept { + return {{std::forward(begin.list), value}}; + } + + template + friend void output(std::ostringstream& os, const std::pair& data) { + output(os, std::move(data.first)); + os << data.second; + } + + friend inline void output(std::ostringstream& os, None) {} + + template + void log(const LogData& data, log_level level, const char* file, int line_no) const { + std::ostringstream buffer; + output(buffer, std::move(data.list)); + log(buffer.str(), level, file, line_no); + } + NOINLINE_ATTRIBUTE; + + ~Logger(); + + friend class ModuleService; + + // (RSDK-9172) These (or at least the default version) should be called from within an + // initializer + // object that handles all SDK initialization for us. + void static init_logging(); + void static init_logging(std::ostream& custom_strm); + + private: + void static static_log_(const std::string& msg, log_level level, const char* file, int line_no); + struct impl; + + std::string name_; + log_level level_; + std::unique_ptr impl_; +}; + +} // namespace sdk +} // namespace viam + +// New macro that includes severity, filename and line number +#define VIAM_SDK_CUSTOM_FORMATTED_LOG(logger, sev, msg) \ + logger->log( \ + ::viam::sdk::Logger::LogData<::viam::sdk::Logger::None>() << msg, sev, __FILE__, __LINE__) + +// New macro that includes severity, filename and line number, using a default built-in logger +#define VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(sev, msg) \ + ::viam::sdk::Logger::static_log( \ + ::viam::sdk::Logger::LogData<::viam::sdk::Logger::None>() << msg, sev, __FILE__, __LINE__) diff --git a/src/viam/sdk/common/utils.cpp b/src/viam/sdk/common/utils.cpp index b3fec14c9..1f7c16c34 100644 --- a/src/viam/sdk/common/utils.cpp +++ b/src/viam/sdk/common/utils.cpp @@ -1,3 +1,4 @@ +#include #include #include @@ -5,9 +6,6 @@ #include #include -#include -#include -#include #include #include @@ -40,6 +38,17 @@ time_point timestamp_to_time_pt(const google::protobuf::Timestamp& timestamp) { nanos); } +google::protobuf::Timestamp time_pt_to_timestamp( + const std::chrono::time_point& time_pt) { + const std::chrono::seconds duration_s = + std::chrono::duration_cast(time_pt.time_since_epoch()); + const std::chrono::nanoseconds duration_ns = time_pt.time_since_epoch() - duration_s; + google::protobuf::Timestamp timestamp; + timestamp.set_seconds(duration_s.count()); + timestamp.set_nanos(static_cast(duration_ns.count())); + return timestamp; +} + google::protobuf::Timestamp time_pt_to_timestamp(const time_point& time_pt) { const std::chrono::seconds duration_s = std::chrono::duration_cast(time_pt.time_since_epoch()); @@ -91,15 +100,6 @@ google::protobuf::Duration to_proto(const std::chrono::microseconds& duration) { return proto; } -void set_logger_severity_from_args(int argc, char** argv) { - if (argc >= 3 && strcmp(argv[2], "--log-level=debug") == 0) { - boost::log::core::get()->set_filter(boost::log::trivial::severity >= - boost::log::trivial::debug); - return; - } - boost::log::core::get()->set_filter(boost::log::trivial::severity >= boost::log::trivial::info); -} - bool operator==(const response_metadata& lhs, const response_metadata& rhs) { return lhs.captured_at == rhs.captured_at; } diff --git a/src/viam/sdk/common/utils.hpp b/src/viam/sdk/common/utils.hpp index 20beca5ee..e5bebe7fe 100644 --- a/src/viam/sdk/common/utils.hpp +++ b/src/viam/sdk/common/utils.hpp @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include @@ -32,6 +33,11 @@ bool operator==(const response_metadata& lhs, const response_metadata& rhs); std::chrono::time_point timestamp_to_time_pt( const google::protobuf::Timestamp& timestamp); +/// @brief convert a std::chrono::time_point to +/// a google::protobuf::Timestamp. +google::protobuf::Timestamp time_pt_to_timestamp( + const std::chrono::time_point& time_pt); + /// @brief convert a std::chrono::time_point to /// a google::protobuf::Timestamp. google::protobuf::Timestamp time_pt_to_timestamp( @@ -84,16 +90,6 @@ ProtoStruct with_debug_entry(ProtoStruct&& map, std::string debug_key); /// @returns the new ProtoStruct ProtoStruct with_debug_entry(ProtoStruct&& map); -/// @brief Set the boost trivial logger's severity depending on args. -/// @param argc The number of args. -/// @param argv The commandline arguments to parse. -/// -/// Sets the boost trivial logger's severity to debug if "--log-level=debug" is the -/// the third argument. Sets severity to info otherwise. Useful for module -/// implementations. See LogLevel documentation in the RDK for more information on -/// how to start modules with a "log-level" commandline argument. -void set_logger_severity_from_args(int argc, char** argv); - /// @brief Used in modular filter components to get the 'fromDataManagement' value from an extra /// ProtoStruct. /// @param extra The extra ProtoStruct. diff --git a/src/viam/sdk/config/resource.cpp b/src/viam/sdk/config/resource.cpp index 758a52637..aa04581ae 100644 --- a/src/viam/sdk/config/resource.cpp +++ b/src/viam/sdk/config/resource.cpp @@ -95,6 +95,8 @@ ResourceConfig ResourceConfig::from_proto(const viam::app::v1::ComponentConfig& resource.namespace__ = proto_cfg.namespace_(); resource.type_ = proto_cfg.type(); resource.attributes_ = struct_to_map(proto_cfg.attributes()); + resource.log_level_ = Logger::from_string(proto_cfg.log_configuration().level()); + auto level = proto_cfg.log_configuration().level(); const std::string& api = proto_cfg.api(); if (api.find(':') != std::string::npos) { resource.api_ = API::from_string(api); @@ -110,6 +112,10 @@ ResourceConfig ResourceConfig::from_proto(const viam::app::v1::ComponentConfig& return resource; }; +log_level ResourceConfig::log_level() const { + return log_level_; +} + viam::app::v1::ComponentConfig ResourceConfig::to_proto() const { viam::app::v1::ComponentConfig proto_cfg; const google::protobuf::Struct s = map_to_struct(attributes_); diff --git a/src/viam/sdk/config/resource.hpp b/src/viam/sdk/config/resource.hpp index a89ff0f9e..29bbae272 100644 --- a/src/viam/sdk/config/resource.hpp +++ b/src/viam/sdk/config/resource.hpp @@ -6,6 +6,7 @@ #include #include +#include #include #include #include @@ -33,6 +34,7 @@ class ResourceConfig { const std::string& namespace_() const; const std::string& type() const; const ProtoStruct& attributes() const; + enum log_level log_level() const; private: API api_; @@ -43,6 +45,7 @@ class ResourceConfig { std::string type_; std::vector depends_on_; std::vector service_config_; + enum log_level log_level_; ProtoStruct attributes_; ProtoValue converted_attributes_; std::vector implicit_depends_on_; diff --git a/src/viam/sdk/module/handler_map.cpp b/src/viam/sdk/module/handler_map.cpp index d6e5fe0ed..74a50d456 100644 --- a/src/viam/sdk/module/handler_map.cpp +++ b/src/viam/sdk/module/handler_map.cpp @@ -1,14 +1,12 @@ #include -#include - -#include #include #include #include #include +#include #include namespace viam { @@ -56,7 +54,8 @@ const HandlerMap_ HandlerMap_::from_proto(const viam::module::v1::HandlerMap& pr const Model model = Model::from_str(mod); models.push_back(model); } catch (std::string error) { // NOLINT - BOOST_LOG_TRIVIAL(error) << "Error processing model " + mod; + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(log_level::error, + "Error processing model " + mod); } } hm.handles_.emplace(handle, models); diff --git a/src/viam/sdk/module/module.cpp b/src/viam/sdk/module/module.cpp index 3c09df767..7e18a236c 100644 --- a/src/viam/sdk/module/module.cpp +++ b/src/viam/sdk/module/module.cpp @@ -1,6 +1,5 @@ #include -#include #include #include #include diff --git a/src/viam/sdk/module/service.cpp b/src/viam/sdk/module/service.cpp index b1bad21ac..4939d3379 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -1,5 +1,6 @@ #include +#include #include #include #include @@ -7,7 +8,16 @@ #include #include +#include +#include +#include +#include +#include +#include +#include #include +#include +#include #include #include #include @@ -25,6 +35,7 @@ #include #include +#include #include #include #include @@ -42,6 +53,10 @@ namespace viam { namespace sdk { +using ll = log_level; + +namespace logging = boost::log; + Dependencies ModuleService::get_dependencies_( google::protobuf::RepeatedPtrField const& proto, std::string const& resource_name) { @@ -83,6 +98,7 @@ ::grpc::Status ModuleService::AddResource(::grpc::ServerContext*, if (reg) { try { res = reg->construct_resource(deps, cfg); + res->set_log_level(cfg.log_level()); } catch (const std::exception& exc) { return grpc::Status(::grpc::INTERNAL, exc.what()); } @@ -120,6 +136,7 @@ ::grpc::Status ModuleService::ReconfigureResource( } try { Reconfigurable::reconfigure_if_reconfigurable(res, deps, cfg); + res->set_log_level(cfg.log_level()); return grpc::Status(); } catch (const std::exception& exc) { return grpc::Status(::grpc::INTERNAL, exc.what()); @@ -129,7 +146,8 @@ ::grpc::Status ModuleService::ReconfigureResource( try { Stoppable::stop_if_stoppable(res); } catch (const std::exception& err) { - BOOST_LOG_TRIVIAL(error) << "unable to stop resource: " << err.what(); + VIAM_SDK_CUSTOM_FORMATTED_LOG( + logger_, ll::error, "unable to stop resource: " << err.what()); } const std::shared_ptr reg = Registry::lookup_model(cfg.name()); @@ -191,7 +209,8 @@ ::grpc::Status ModuleService::RemoveResource( try { Stoppable::stop_if_stoppable(res); } catch (const std::exception& err) { - BOOST_LOG_TRIVIAL(error) << "unable to stop resource: " << err.what(); + VIAM_SDK_CUSTOM_FORMATTED_LOG( + logger_, ll::error, "unable to stop resource: " << err.what()); } manager->remove(name); @@ -204,24 +223,122 @@ ::grpc::Status ModuleService::Ready(::grpc::ServerContext*, const std::lock_guard lock(lock_); const viam::module::v1::HandlerMap hm = this->module_->handles().to_proto(); *response->mutable_handlermap() = hm; - parent_addr_ = request->parent_address(); + auto new_parent_addr = request->parent_address(); + if (parent_addr_ != new_parent_addr) { + parent_addr_ = std::move(new_parent_addr); + if (!parent_) { + parent_ = RobotClient::at_local_socket(parent_addr_, {0, boost::none}); + } + init_logging_(); + } response->set_ready(module_->ready()); return grpc::Status(); }; +namespace { +// (ethan) I don't love having this logic here. Ideally we could have all the logging logic live in +// a single place (logger.xpp). However, the logging for modular resources relies on not actually +// logging to the console, but rather sending log messages over the wire to a robot client. If we +// wanted this logic to live in logger.cpp, then we'd have to expose a dependency on `RobotClient` +// in logger.hpp. this would likely create a circular dependency and imo is worse than having the +// moduleservice be aware of logging logic in a way that is confined to the implementation file. +class custom_logging_buf : public std::stringbuf { + public: + custom_logging_buf(std::shared_ptr parent) : parent_(std::move(parent)){}; + int sync() override { + if (!parent_) { + std::cerr << "Attempted to send custom gRPC log without parent address\n"; + return -1; + } + + auto name_attr = + logging::attribute_cast>( + logging::core::get()->get_thread_attributes()["LoggerName"]); + + std::string name = name_attr.get(); + auto level_attr = + logging::attribute_cast>( + logging::core::get()->get_thread_attributes()["LogLevel"]); + + std::string level = level_attr.get(); + if (name == "" || level == "") { + // logging is not being done from `Viam` logger but is still going through `Boost`. + // Because we use `Boost` as our backend and are overwriting defaults, this log will + // still go to `viam-server`. But, since the call is not made through our logger, + // we don't want to rely on a previously set level or logger name. So, we fall back + // on default values. + name = "viam-cpp-sdk"; + level = "info"; + } + + // reset name and level attribute to "" in case a subsequent logging call is made + // through a boost macro directly, without using our loggers. + name_attr.set(""); + level_attr.set(""); + + auto log = this->str(); + this->str(""); + // Boost loves to add newline chars at the end of log messages, but this causes RDK + // logs to break out over multiple lines, which isn't great. Since we break up the + // structure of our log messages into two parts for module logging purposes, we need to + // remove the final character (always a newline) and then the first occurrence of a + // newline after that if it exists. + log.pop_back(); + auto first_newline_char = log.find('\n', 0); + if (first_newline_char != std::string::npos) { + log.erase(first_newline_char, 1); + } + + parent_->log( + std::move(name), std::move(level), std::move(log), std::chrono::system_clock::now()); + return 0; + } + + private: + std::shared_ptr parent_; +}; +} // namespace + +struct ModuleService::impl { + typedef logging::sinks::synchronous_sink text_sink; + impl(const std::shared_ptr& parent) : buf(custom_logging_buf(parent)) { + auto backend = boost::make_shared(); + auto strm = boost::make_shared(&buf); + stream = strm; + backend->add_stream(strm); + backend->auto_flush(true); + sink = boost::make_shared(backend); + } + + ~impl() { + logging::core::get()->remove_sink(sink); + } + custom_logging_buf buf; + boost::shared_ptr stream; + boost::shared_ptr sink; +}; + +void ModuleService::init_logging_() { + impl_ = std::make_unique(parent_); + Logger::init_logging(*impl_->stream); + logging::core::get()->add_sink(impl_->sink); +} + ModuleService::ModuleService(std::string addr) - : module_(std::make_unique(std::move(addr))), server_(std::make_unique()) {} + : logger_(std::make_unique("viam-cpp-module-service")), + module_(std::make_unique(std::move(addr))), + server_(std::make_unique()) {} ModuleService::ModuleService(int argc, char** argv, - const std::vector>& registrations) { + const std::vector>& registrations) + : logger_(std::make_unique("viam-cpp-module-service")) { if (argc < 2) { throw Exception(ErrorCondition::k_connection, "Need socket path as command line argument"); } module_ = std::make_unique(argv[1]); server_ = std::make_unique(); signal_manager_ = SignalManager(); - set_logger_severity_from_args(argc, argv); for (auto&& mr : registrations) { Registry::register_model(mr); @@ -242,25 +359,32 @@ void ModuleService::serve() { module_->set_ready(); server_->start(); - BOOST_LOG_TRIVIAL(info) << "Module listening on " << module_->addr(); - BOOST_LOG_TRIVIAL(info) << "Module handles the following API/model pairs:\n" - << module_->handles(); + VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, ll::info, "Module listening on " << module_->addr()); + VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, + ll::info, + "Module handles the following API/model pairs:\n" + << module_->handles()); signal_manager_.wait(); } ModuleService::~ModuleService() { // TODO(RSDK-5509): Run registered cleanup functions here. - BOOST_LOG_TRIVIAL(info) << "Shutting down gracefully."; - server_->shutdown(); - - if (parent_) { - try { - parent_->close(); - } catch (const std::exception& exc) { - BOOST_LOG_TRIVIAL(error) << exc.what(); - } - } + // CR erodkin: three things of note here: + // 1) occasionally at the end of the MS destructor we crash with abort trap, but + // it's totally unclear why, what memory is unresolved, what's going on at all. seems like a + // majority of the time we successfully shut down, however. + // 2) if we manually call `reset()` on all of our smart pointer-managed resources in this + // destructor, we get the abort trap error 100% of the time. If we just let them be destroyed + // naturally, we get the abort trap error significantly less than 100% of the time + // 3) Sometimes this is called after we've removed our custom logging buf sink, (see + // ModuleService::~impl()), sometimes before. It's not clear why this happens, but when + // it does the buffer gets flushed twice (i.e., we see "Shutting down gracefullyShutting down + // gracefully" being logged). Removing the `remove_all_sinks()` call when initing ostream + // logging in `logger.cpp` anecdotally seems to fix this, but is not tenable as it results + // in all module logs getting duplicated (one version going over gRPC, the other getting + // picked up from console) + VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, ll::info, "Shutting down gracefully"); } void ModuleService::add_model_from_registry_inlock_(API api, diff --git a/src/viam/sdk/module/service.hpp b/src/viam/sdk/module/service.hpp index 4925e279c..e4e96603c 100644 --- a/src/viam/sdk/module/service.hpp +++ b/src/viam/sdk/module/service.hpp @@ -1,7 +1,5 @@ #pragma once -#include - #include #include @@ -50,6 +48,7 @@ class ModuleService : viam::module::v1::ModuleService::Service { void add_model_from_registry(API api, Model model); private: + void init_logging_(); ::grpc::Status AddResource(::grpc::ServerContext* context, const ::viam::module::v1::AddResourceRequest* request, ::viam::module::v1::AddResourceResponse* response) override; @@ -76,9 +75,12 @@ class ModuleService : viam::module::v1::ModuleService::Service { std::string const& resource_name); std::shared_ptr get_parent_resource_(const Name& name); + std::unique_ptr logger_; std::mutex lock_; - std::unique_ptr module_; + struct impl; std::shared_ptr parent_; + std::unique_ptr impl_; + std::unique_ptr module_; std::string parent_addr_; std::unique_ptr server_; SignalManager signal_manager_; diff --git a/src/viam/sdk/registry/registry.cpp b/src/viam/sdk/registry/registry.cpp index 4e0819722..a14b0ba45 100644 --- a/src/viam/sdk/registry/registry.cpp +++ b/src/viam/sdk/registry/registry.cpp @@ -5,13 +5,13 @@ #include #include -#include #include #include #include #include #include +#include #include #include #include @@ -195,8 +195,9 @@ void register_resources() { void Registry::initialize() { const std::lock_guard lock(lock_); if (initialized_) { - BOOST_LOG_TRIVIAL(warning) - << "Attempted to initialize the Registry but it was already initialized."; + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + log_level::warning, + "Attempted to initialize the Registry but it was already initialized."); return; } initialized_ = true; diff --git a/src/viam/sdk/resource/resource.cpp b/src/viam/sdk/resource/resource.cpp index 04b304679..c9d326185 100644 --- a/src/viam/sdk/resource/resource.cpp +++ b/src/viam/sdk/resource/resource.cpp @@ -13,7 +13,8 @@ namespace sdk { using common::v1::ResourceName; Resource::~Resource() = default; -Resource::Resource(std::string name) : name_(std::move(name)) {} +Resource::Resource(std::string name) + : name_(name), logger_(std::make_unique(std::move(name))) {} std::string Resource::name() const { return name_; @@ -29,5 +30,9 @@ ResourceName Resource::get_resource_name(std::string name) const { return r; } +void Resource::set_log_level(log_level level) { + logger_->set_log_level(level); +} + } // namespace sdk } // namespace viam diff --git a/src/viam/sdk/resource/resource.hpp b/src/viam/sdk/resource/resource.hpp index 0d1d55eb7..3361849cc 100644 --- a/src/viam/sdk/resource/resource.hpp +++ b/src/viam/sdk/resource/resource.hpp @@ -5,6 +5,7 @@ #include #include +#include #include #include #include @@ -28,8 +29,14 @@ class Resource { /// @brief Return the resource's name. virtual std::string name() const; + void set_log_level(log_level level); + private: std::string name_; + + protected: + // NOLINTNEXTLINE + std::unique_ptr logger_; }; template <> diff --git a/src/viam/sdk/resource/resource_manager.cpp b/src/viam/sdk/resource/resource_manager.cpp index 8f2940c5f..6ee002654 100644 --- a/src/viam/sdk/resource/resource_manager.cpp +++ b/src/viam/sdk/resource/resource_manager.cpp @@ -7,7 +7,6 @@ #include #include -#include #include #include #include @@ -15,6 +14,7 @@ #include #include +#include #include #include #include @@ -23,6 +23,8 @@ namespace viam { namespace sdk { +using ll = log_level; + std::shared_ptr ResourceManager::resource(const std::string& name) { const std::lock_guard lock(lock_); @@ -52,7 +54,8 @@ void ResourceManager::replace_all( try { do_add(resource.first, resource.second); } catch (std::exception& exc) { - BOOST_LOG_TRIVIAL(error) << "Error replacing all resources" << exc.what(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(ll::error, + "Error replacing all resources" << exc.what()); return; } } @@ -97,7 +100,8 @@ void ResourceManager::add(const Name& name, std::shared_ptr resource) try { do_add(name, std::move(resource)); } catch (std::exception& exc) { - BOOST_LOG_TRIVIAL(error) << "Error adding resource to subtype service: " << exc.what(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "Error adding resource to subtype service: " << exc.what()); } }; @@ -134,7 +138,8 @@ void ResourceManager::remove(const Name& name) { try { do_remove(name); } catch (std::exception& exc) { - BOOST_LOG_TRIVIAL(error) << "unable to remove resource: " << exc.what(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(ll::error, + "unable to remove resource: " << exc.what()); }; }; @@ -144,8 +149,8 @@ void ResourceManager::replace_one(const Name& name, std::shared_ptr re do_remove(name); do_add(name, std::move(resource)); } catch (std::exception& exc) { - BOOST_LOG_TRIVIAL(error) << "failed to replace resource " << name.to_string() << ": " - << exc.what(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "failed to replace resource " << name.to_string() << ": " << exc.what()); } } diff --git a/src/viam/sdk/robot/client.cpp b/src/viam/sdk/robot/client.cpp index 15cac8e17..7e8a73d76 100644 --- a/src/viam/sdk/robot/client.cpp +++ b/src/viam/sdk/robot/client.cpp @@ -9,7 +9,6 @@ #include #include -#include #include #include #include @@ -19,11 +18,13 @@ #include #include +#include #include #include #include #include #include +#include #include #include #include @@ -39,6 +40,7 @@ using viam::robot::v1::FrameSystemConfig; using viam::robot::v1::Operation; using viam::robot::v1::RobotService; using viam::robot::v1::Status; +using ll = log_level; // gRPC responses are frequently coming back with a spurious `Stream removed` // error, leading to unhelpful and misleading logging. We should figure out why @@ -147,20 +149,21 @@ RobotClient::~RobotClient() { try { this->close(); } catch (const std::exception& e) { - BOOST_LOG_TRIVIAL(error) << "Received err while closing RobotClient: " << e.what(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "Received err while closing RobotClient: " << e.what()); } catch (...) { - BOOST_LOG_TRIVIAL(error) << "Received unknown err while closing RobotClient"; + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(ll::error, + "Received unknown err while closing RobotClient"); } } } void RobotClient::close() { should_refresh_.store(false); - for (const std::shared_ptr& t : threads_) { + for (const auto& t : threads_) { t->~thread(); } stop_all(); - viam_channel_->close(); } bool is_error_response(const grpc::Status& response) { @@ -170,6 +173,31 @@ std::vector RobotClient::get_status() { auto resources = resource_names(); return get_status(resources); } + +void RobotClient::log( + std::string name, + std::string level, + std::string message, + const std::chrono::time_point& time) { + robot::v1::LogRequest req; + common::v1::LogEntry log; + *log.mutable_logger_name() = std::move(name); + std::transform(level.begin(), level.end(), level.begin(), ::toupper); + log.set_level(level); + *log.mutable_message() = std::move(message); + *log.mutable_time() = time_pt_to_timestamp(time); + *log.mutable_stack() = ""; + *req.mutable_logs()->Add() = std::move(log); + robot::v1::LogResponse resp; + ClientContext ctx; + const auto response = impl_->stub_->Log(ctx, req, &resp); + if (is_error_response(response)) { + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, + "Error sending log: " << response.error_message() << response.error_details()); + } +} + // gets statuses of components associated with robot. If a specific component // vector is provided, only statuses for the given Names will be // returned @@ -183,8 +211,9 @@ std::vector RobotClient::get_status(std::vector& comp const grpc::Status response = impl_->stub_->GetStatus(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error getting status: " << response.error_message() - << response.error_details(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, + "Error getting status: " << response.error_message() << response.error_details()); } const RepeatedPtrField resp_status = resp.status(); @@ -207,7 +236,8 @@ std::vector RobotClient::get_operations() { grpc::Status const response = impl_->stub_->GetOperations(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error getting operations: " << response.error_message(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "Error getting operations: " << response.error_message()); } for (int i = 0; i < resp.operations().size(); ++i) { @@ -225,7 +255,8 @@ void RobotClient::cancel_operation(std::string id) { req.set_id(id); const grpc::Status response = impl_->stub_->CancelOperation(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error canceling operation with id " << id; + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(ll::error, + "Error canceling operation with id " << id); } } @@ -238,7 +269,8 @@ void RobotClient::block_for_operation(std::string id) { const grpc::Status response = impl_->stub_->BlockForOperation(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error blocking for operation with id " << id; + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG(ll::error, + "Error blocking for operation with id " << id); } } @@ -249,7 +281,11 @@ void RobotClient::refresh() { const grpc::Status response = impl_->stub_->ResourceNames(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error getting resource names: " << response.error_message(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, + "Error getting resource names: " << response.error_message() + << response.error_details()); + return; } std::unordered_map> new_resources; @@ -272,8 +308,9 @@ void RobotClient::refresh() { const Name name_({name.namespace_(), name.type(), name.subtype()}, "", name.name()); new_resources.emplace(name_, rpc_client); } catch (const std::exception& exc) { - BOOST_LOG_TRIVIAL(debug) - << "Error registering component " << name.subtype() << ": " << exc.what(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::debug, + "Error registering component " << name.subtype() << ": " << exc.what()); } } } @@ -375,8 +412,8 @@ std::vector RobotClient::get_frame_system_conf const grpc::Status response = impl_->stub_->FrameSystemConfig(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error getting frame system config: " - << response.error_message(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "Error getting frame system config: " << response.error_message()); } const RepeatedPtrField configs = resp.frame_system_configs(); @@ -408,7 +445,8 @@ pose_in_frame RobotClient::transform_pose( const grpc::Status response = impl_->stub_->TransformPose(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error getting PoseInFrame: " << response.error_message(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "Error getting PoseInFrame: " << response.error_message()); } return pose_in_frame::from_proto(resp.pose()); @@ -428,7 +466,8 @@ std::vector RobotClient::discover_components( const grpc::Status response = impl_->stub_->DiscoverComponents(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error discovering components: " << response.error_message(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, "Error discovering components: " << response.error_message()); } std::vector components = std::vector(); @@ -469,8 +508,9 @@ void RobotClient::stop_all(const std::unordered_map& extra) { } const grpc::Status response = impl_->stub_->StopAll(ctx, req, &resp); if (is_error_response(response)) { - BOOST_LOG_TRIVIAL(error) << "Error stopping all: " << response.error_message() - << response.error_details(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, + "Error stopping all: " << response.error_message() << response.error_details()); } } diff --git a/src/viam/sdk/robot/client.hpp b/src/viam/sdk/robot/client.hpp index 948f2c9cd..142acc05e 100644 --- a/src/viam/sdk/robot/client.hpp +++ b/src/viam/sdk/robot/client.hpp @@ -3,6 +3,7 @@ /// @brief gRPC client implementation for a `robot`. #pragma once +#include #include #include @@ -14,6 +15,7 @@ #include #include #include +#include #include #include @@ -114,6 +116,12 @@ class RobotClient { /// cast to the desired type. std::shared_ptr resource_by_name(const Name& name); + void log( + std::string name, + std::string level, + std::string message, + const std::chrono::time_point& time); + template /// @brief Lookup and return a `shared_ptr` to a resource of the requested type. /// @param name The ordinary name of the resource. diff --git a/src/viam/sdk/rpc/dial.cpp b/src/viam/sdk/rpc/dial.cpp index 2f4cbaa8d..fff6a04e0 100644 --- a/src/viam/sdk/rpc/dial.cpp +++ b/src/viam/sdk/rpc/dial.cpp @@ -35,10 +35,16 @@ void ViamChannel::close() { return; } closed_ = true; + // CR erodkin: every now and again this call causes a failure. From adding log statements + // in rust-utils, I have confirmed that the failure happens within the rust code. free_string(path_); free_rust_runtime(rust_runtime_); }; +ViamChannel::~ViamChannel() { + close(); +} + const std::string& Credentials::type() const { return type_; } diff --git a/src/viam/sdk/rpc/dial.hpp b/src/viam/sdk/rpc/dial.hpp index 86fbf582a..965c1bc58 100644 --- a/src/viam/sdk/rpc/dial.hpp +++ b/src/viam/sdk/rpc/dial.hpp @@ -17,6 +17,8 @@ class ViamChannel { static std::shared_ptr dial(const char* uri, const boost::optional& options); + ~ViamChannel(); + const std::shared_ptr& channel() const; private: diff --git a/src/viam/sdk/rpc/server.cpp b/src/viam/sdk/rpc/server.cpp index 94bb72542..a76a15a15 100644 --- a/src/viam/sdk/rpc/server.cpp +++ b/src/viam/sdk/rpc/server.cpp @@ -2,7 +2,6 @@ #include -#include #include #include