From 395b39db015cdd6452dae394bebb6c80ffc7aa3b Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 25 Oct 2024 10:32:52 -0400 Subject: [PATCH 01/10] get grpc logging working --- src/viam/examples/modules/complex/client.cpp | 23 +++-- .../examples/modules/complex/gizmo/api.cpp | 36 ++++++-- .../examples/modules/complex/gizmo/impl.cpp | 16 +++- .../examples/modules/complex/gizmo/impl.hpp | 4 +- src/viam/examples/modules/complex/main.cpp | 3 + src/viam/sdk/CMakeLists.txt | 2 + src/viam/sdk/common/client_helper.hpp | 6 ++ src/viam/sdk/common/logger.cpp | 86 +++++++++++++++++++ src/viam/sdk/common/logger.hpp | 49 +++++++++++ src/viam/sdk/common/utils.cpp | 12 +++ src/viam/sdk/common/utils.hpp | 6 ++ src/viam/sdk/components/component.cpp | 4 +- src/viam/sdk/module/module.cpp | 25 +++++- src/viam/sdk/module/module.hpp | 6 ++ src/viam/sdk/module/service.cpp | 76 +++++++++++++++- src/viam/sdk/module/service.hpp | 6 ++ src/viam/sdk/resource/resource.cpp | 2 +- src/viam/sdk/resource/resource.hpp | 5 ++ src/viam/sdk/robot/client.cpp | 31 ++++++- src/viam/sdk/robot/client.hpp | 8 ++ 20 files changed, 379 insertions(+), 27 deletions(-) create mode 100644 src/viam/sdk/common/logger.cpp create mode 100644 src/viam/sdk/common/logger.hpp diff --git a/src/viam/examples/modules/complex/client.cpp b/src/viam/examples/modules/complex/client.cpp index 894fd5c11..03a51b83b 100644 --- a/src/viam/examples/modules/complex/client.cpp +++ b/src/viam/examples/modules/complex/client.cpp @@ -27,9 +27,9 @@ using namespace viam::sdk; int main() { - const char* uri = "http://localhost:8080/"; // replace with your URI if connecting securely - DialOptions dial_options; - dial_options.set_allow_insecure_downgrade(true); // set to false if connecting securely + // const char* uri = "http://localhost:8080/"; // replace with your URI if connecting securely + // DialOptions dial_options; + // dial_options.set_allow_insecure_downgrade(true); // set to false if connecting securely // Uncomment and fill out your credentials details if connecting securely // std::string type = ""; @@ -37,17 +37,26 @@ int main() { // Credentials credentials(type, payload); // dial_options.set_credentials(credentials); - boost::optional opts(dial_options); - std::string address(uri); - Options options(1, opts); + std::string host("webrtc-test-main.jkek76kqnh.viam.cloud"); + DialOptions dial_opts; + dial_opts.set_entity(std::string("a9dcf212-3397-4318-bb1e-f5c36b3cafc1")); + Credentials credentials("api-key", "2ml60ys1j4i9v0pecpxahe654yxpc1dz"); + dial_opts.set_credentials(credentials); + boost::optional opts(dial_opts); + Options options(0, opts); + + // boost::optional opts(dial_options); + // std::string address(uri); + // Options options(1, opts); // Register custom gizmo and summation clients so robot client can access resources // of that type from the server. Registry::register_resource_client(); Registry::register_resource_client(); + std::cout << "We are here!!!!\n\n\n" << std::flush; // Connect to robot. - std::shared_ptr robot = RobotClient::at_address(address, options); + std::shared_ptr robot = RobotClient::at_address(host, options); // Print resources. std::cout << "Resources" << std::endl; std::vector resource_names = robot->resource_names(); diff --git a/src/viam/examples/modules/complex/gizmo/api.cpp b/src/viam/examples/modules/complex/gizmo/api.cpp index 4059c9034..d9746c983 100644 --- a/src/viam/examples/modules/complex/gizmo/api.cpp +++ b/src/viam/examples/modules/complex/gizmo/api.cpp @@ -4,6 +4,9 @@ #include +#include +#include +#include #include #include #include @@ -24,12 +27,22 @@ API API::traits::api() { return {"viam", "component", "gizmo"}; } -Gizmo::Gizmo(std::string name) : Component(std::move(name)){}; +Gizmo::Gizmo(std::string name) + : Component(std::move(name)) { + // boost::log::sources::severity_logger 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 server methods */ GizmoServer::GizmoServer(std::shared_ptr manager) - : ResourceServer(std::move(manager)){}; + : ResourceServer(std::move(manager)) {}; grpc::Status GizmoServer::DoOne(grpc::ServerContext* context, const DoOneRequest* request, @@ -170,12 +183,25 @@ grpc::Status GizmoServer::DoTwo(::grpc::ServerContext* context, /* Gizmo client methods */ GizmoClient::GizmoClient(std::string name, std::shared_ptr channel) - : Gizmo(std::move(name)), stub_(GizmoService::NewStub(channel)), channel_(std::move(channel)){}; + : Gizmo(std::move(name)), + stub_(GizmoService::NewStub(channel)), + 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"); return make_client_helper(this, *stub_, &StubType::DoOne) - .with([&](auto& request) { request.set_arg1(arg1); }) - .invoke([](auto& response) { return response.ret1(); }); + .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(); + }); } bool GizmoClient::do_one_client_stream(std::vector arg1) { diff --git a/src/viam/examples/modules/complex/gizmo/impl.cpp b/src/viam/examples/modules/complex/gizmo/impl.cpp index adbf8675a..998042c80 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 @@ -50,6 +50,14 @@ std::vector MyGizmo::validate(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"); return arg1_ == arg1; } diff --git a/src/viam/examples/modules/complex/gizmo/impl.hpp b/src/viam/examples/modules/complex/gizmo/impl.hpp index 1ca83a470..e937d62f4 100644 --- a/src/viam/examples/modules/complex/gizmo/impl.hpp +++ b/src/viam/examples/modules/complex/gizmo/impl.hpp @@ -14,12 +14,12 @@ using namespace viam::sdk; // `validate` method that checks config validity. class MyGizmo : public Gizmo, public Reconfigurable { public: - MyGizmo(std::string name, std::string arg1) : Gizmo(std::move(name)), arg1_(std::move(arg1)){}; + MyGizmo(std::string name, std::string arg1) : Gizmo(std::move(name)), arg1_(std::move(arg1)) {}; MyGizmo(const Dependencies& deps, const ResourceConfig& cfg) : Gizmo(cfg.name()) { 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..64e532ac4 100644 --- a/src/viam/examples/modules/complex/main.cpp +++ b/src/viam/examples/modules/complex/main.cpp @@ -30,6 +30,8 @@ using namespace viam::sdk; int main(int argc, char** argv) { Model mybase_model("viam", "base", "mybase"); + std::cout << "registering resource servers\n" << std::flush; + // Make sure to explicity register resources with custom APIs. Registry::register_resource_server(); Registry::register_resource_server(); @@ -56,6 +58,7 @@ int main(int argc, char** argv) { std::vector> mrs = {mybase_mr, mygizmo_mr, mysummation_mr}; auto my_mod = std::make_shared(argc, argv, mrs); + std::cout << "we have created the module and gotten ready to serve\n" << std::flush; my_mod->serve(); return EXIT_SUCCESS; diff --git a/src/viam/sdk/CMakeLists.txt b/src/viam/sdk/CMakeLists.txt index 04077c991..644c90d38 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.hpp b/src/viam/sdk/common/client_helper.hpp index d8db1f338..1848586b4 100644 --- a/src/viam/sdk/common/client_helper.hpp +++ b/src/viam/sdk/common/client_helper.hpp @@ -35,6 +35,9 @@ class ClientHelper { static void default_rsc_(RequestType&) {} static void default_rhc_(const ResponseType&) {} static void default_ehc_(const ::grpc::Status& status) { + std::cout << "error is " << status.error_details() << " " << status.error_code() << " " + << status.error_message() << "\n" + << std::flush; throw GRPCException(status); } @@ -76,8 +79,11 @@ 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(rhc)( const_cast(response_)); } diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp new file mode 100644 index 000000000..e39f79239 --- /dev/null +++ b/src/viam/sdk/common/logger.cpp @@ -0,0 +1,86 @@ +#include + +#include + +#include +#include + +namespace viam { +namespace sdk { + +namespace logging = boost::log; +using ll = Logger::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_; +}; + +std::shared_ptr> Logger::underlying() { + return impl_->logger_; +} + +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(Logger::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; + } + } +} + +void Logger::log(const std::string& log, log_level level) const { + if (impl_->level_ > level) { + return; + } + 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); +} +void Logger::warning(const std::string& log) const { + this->log(log, ll::warning); +} + +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..4a7036d71 --- /dev/null +++ b/src/viam/sdk/common/logger.hpp @@ -0,0 +1,49 @@ +#pragma once + +#include +#include +#include +#include + +namespace viam { +namespace sdk { + +class Resource; + +class Logger { + public: + ~Logger(); + enum class log_level : std::int8_t { + trace = -2, + debug = -1, + info = 0, // default value is info + warning = 1, + error = 2, + fatal = 3, + }; + + explicit Logger(std::string name); + explicit Logger(std::string name, log_level level); + + void log(const std::string& log, log_level level) const; + void debug(const std::string& log) const; + void error(const std::string& log) const; + void fatal(const std::string& log) const; + void info(const std::string& log) const; + void trace(const std::string& log) const; + void warning(const std::string& log) const; + + void set_log_level(log_level level); + + std::shared_ptr> + underlying(); + + private: + std::string name_; + log_level level_; + struct impl; + std::unique_ptr impl_; +}; + +} // namespace sdk +} // namespace viam diff --git a/src/viam/sdk/common/utils.cpp b/src/viam/sdk/common/utils.cpp index b3fec14c9..84ecc9c35 100644 --- a/src/viam/sdk/common/utils.cpp +++ b/src/viam/sdk/common/utils.cpp @@ -1,3 +1,4 @@ +#include #include #include @@ -40,6 +41,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()); diff --git a/src/viam/sdk/common/utils.hpp b/src/viam/sdk/common/utils.hpp index 20beca5ee..34ed89559 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( diff --git a/src/viam/sdk/components/component.cpp b/src/viam/sdk/components/component.cpp index c44bd91e9..1dbcddafd 100644 --- a/src/viam/sdk/components/component.cpp +++ b/src/viam/sdk/components/component.cpp @@ -14,9 +14,9 @@ namespace sdk { using viam::common::v1::ResourceName; -Component::Component() : Resource("component"){}; +Component::Component() : Resource("component") {}; -Component::Component(std::string name) : Resource(std::move(name)){}; +Component::Component(std::string name) : Resource(std::move(name)) {}; ResourceName Component::get_resource_name(std::string name) const { auto r = this->Resource::get_resource_name(name); diff --git a/src/viam/sdk/module/module.cpp b/src/viam/sdk/module/module.cpp index 3c09df767..45460945b 100644 --- a/src/viam/sdk/module/module.cpp +++ b/src/viam/sdk/module/module.cpp @@ -1,5 +1,6 @@ #include +#include #include #include #include @@ -10,12 +11,34 @@ namespace viam { namespace sdk { -Module::Module(std::string addr) : addr_(std::move(addr)){}; +namespace logging = boost::log; + +Module::Module(std::string addr) : addr_(std::move(addr)) {}; void Module::set_ready() { ready_ = true; } +// namespace impl { +// class my_buf_ : public std::stringbuf { +// public: +// virtual int sync() { +// auto msg = this->str(); +// parent_->return 0; +//} + +// private: +// std::unique_ptr parent_; +//}; +//} // namespace impl + +// void Module::init_logging(const std::shared_ptr& parent) { +// typedef logging::sinks::synchronous_sink text_sink; +// auto sink = boost::make_shared(); +// sink->locked_backend()->add_stream(); +// logging::core::get()->add_sink(sink); +//} + const std::string& Module::name() const { return name_; }; diff --git a/src/viam/sdk/module/module.hpp b/src/viam/sdk/module/module.hpp index 18c7a0b82..394132340 100644 --- a/src/viam/sdk/module/module.hpp +++ b/src/viam/sdk/module/module.hpp @@ -9,6 +9,8 @@ namespace viam { namespace sdk { +// class ModuleService; + class Module { public: void set_ready(); @@ -21,11 +23,15 @@ class Module { const std::shared_ptr& channel() const; private: + // friend class ModuleService; std::string name_; std::string addr_; bool ready_; HandlerMap_ handles_; std::shared_ptr channel_; + + // protected: + // void init_logging(const std::shared_ptr& parent); }; } // namespace sdk diff --git a/src/viam/sdk/module/service.cpp b/src/viam/sdk/module/service.cpp index b1bad21ac..203c34015 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -1,3 +1,4 @@ +#include #include #include @@ -7,6 +8,10 @@ #include #include +#include +#include +#include +#include #include #include #include @@ -42,6 +47,8 @@ namespace viam { namespace sdk { +namespace logging = boost::log; + Dependencies ModuleService::get_dependencies_( google::protobuf::RepeatedPtrField const& proto, std::string const& resource_name) { @@ -201,14 +208,67 @@ ::grpc::Status ModuleService::RemoveResource( ::grpc::Status ModuleService::Ready(::grpc::ServerContext*, const ::viam::module::v1::ReadyRequest* request, ::viam::module::v1::ReadyResponse* response) { + std::cout << "Got ready request!!!!\n\n\n" << std::flush; 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); + std::cout << "setting parent at " << parent_addr_ << "\n" << std::flush; + if (!parent_) { + parent_ = RobotClient::at_local_socket(parent_addr_, {0, boost::none}); + } + parent_->log("foo", "info", "baz", std::chrono::system_clock::now(), "None"); + // parent_->log("foo", "error", "baz error", std::chrono::system_clock::now(), "None"); + init_logging_(); + parent_->log("foo2", "error", "baz2", std::chrono::system_clock::now(), "None2"); + } response->set_ready(module_->ready()); return grpc::Status(); }; +namespace impl { +class custom_logging_buf : public std::stringbuf { + public: + custom_logging_buf(std::shared_ptr parent) : parent_(std::move(parent)) {}; + int sync() override { + std::cout << "in sync"; + if (!parent_) { + std::cerr << "Attempted to send custom gRPC log without parent address\n"; + return -1; + } + auto log = this->str(); + std::cout << " and the log is " << log << "\n" << std::flush; + parent_->log("s", "error", std::move(log), std::chrono::system_clock::now(), "None"); + return 0; + } + + private: + std::shared_ptr parent_; +}; +} // namespace impl + +struct ModuleService::impl { + typedef logging::sinks::synchronous_sink text_sink; + impl(std::shared_ptr parent) + : buf(::viam::sdk::impl::custom_logging_buf(std::move(parent))) { + auto backend = boost::make_shared(); + auto strm = boost::make_shared(&buf); + backend->add_stream(strm); + backend->auto_flush(true); + sink = boost::make_shared(backend); + } + + ::viam::sdk::impl::custom_logging_buf buf; + boost::shared_ptr sink; +}; + +void ModuleService::init_logging_() { + impl_ = std::make_unique(parent_); + logging::core::get()->add_sink(impl_->sink); +} + ModuleService::ModuleService(std::string addr) : module_(std::make_unique(std::move(addr))), server_(std::make_unique()) {} @@ -238,27 +298,35 @@ void ModuleService::serve() { server_->register_service(this); const std::string address = "unix://" + module_->addr(); server_->add_listening_port(address); + // std::cout << "setting parent at " << parent_addr_ << "\n" << std::flush; + // parent_ = RobotClient::at_local_socket(parent_addr_, {0, boost::none}); + std::cout << "initialize logging\n" << std::flush; + std::cout << "initialized logging\n" << std::flush; module_->set_ready(); + std::cout << "starting\n" << std::flush; server_->start(); - + std::cout << "started\n" << std::flush; BOOST_LOG_TRIVIAL(info) << "Module listening on " << module_->addr(); BOOST_LOG_TRIVIAL(info) << "Module handles the following API/model pairs:\n" << module_->handles(); + // init_logging_(); + + std::cout << "added some logs surely that's fine\n" << std::flush; signal_manager_.wait(); } ModuleService::~ModuleService() { // TODO(RSDK-5509): Run registered cleanup functions here. - BOOST_LOG_TRIVIAL(info) << "Shutting down gracefully."; + // 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(); + // BOOST_LOG_TRIVIAL(error) << exc.what(); } } } diff --git a/src/viam/sdk/module/service.hpp b/src/viam/sdk/module/service.hpp index 4925e279c..bd1d01de8 100644 --- a/src/viam/sdk/module/service.hpp +++ b/src/viam/sdk/module/service.hpp @@ -5,6 +5,9 @@ #include #include +#include +#include + #include #include #include @@ -50,6 +53,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; @@ -79,6 +83,8 @@ class ModuleService : viam::module::v1::ModuleService::Service { std::mutex lock_; std::unique_ptr module_; std::shared_ptr parent_; + struct impl; + std::unique_ptr impl_; std::string parent_addr_; std::unique_ptr server_; SignalManager signal_manager_; diff --git a/src/viam/sdk/resource/resource.cpp b/src/viam/sdk/resource/resource.cpp index 04b304679..59085e0d2 100644 --- a/src/viam/sdk/resource/resource.cpp +++ b/src/viam/sdk/resource/resource.cpp @@ -13,7 +13,7 @@ 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_(Logger(std::move(name))) {} std::string Resource::name() const { return name_; diff --git a/src/viam/sdk/resource/resource.hpp b/src/viam/sdk/resource/resource.hpp index 0d1d55eb7..286638843 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 @@ -30,6 +31,10 @@ class Resource { private: std::string name_; + + protected: + // NOLINTNEXTLINE + Logger logger_; }; template <> diff --git a/src/viam/sdk/robot/client.cpp b/src/viam/sdk/robot/client.cpp index 15cac8e17..e2f13d720 100644 --- a/src/viam/sdk/robot/client.cpp +++ b/src/viam/sdk/robot/client.cpp @@ -1,3 +1,4 @@ +#include #include #include @@ -170,6 +171,32 @@ 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, + std::string stack) { + robot::v1::LogRequest req; + common::v1::LogEntry log; + std::cout << "calling log\n" << std::endl; + *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() = std::move(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)) { + BOOST_LOG_TRIVIAL(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 @@ -249,7 +276,9 @@ 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(); + BOOST_LOG_TRIVIAL(error) << "Error getting resource names: " << response.error_message() + << response.error_details(); + return; } std::unordered_map> new_resources; diff --git a/src/viam/sdk/robot/client.hpp b/src/viam/sdk/robot/client.hpp index 948f2c9cd..5ac889962 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 @@ -114,6 +115,13 @@ 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, + std::string stack); + template /// @brief Lookup and return a `shared_ptr` to a resource of the requested type. /// @param name The ordinary name of the resource. From 2c19f5168865de613c0eb5bb9d7b37ab624f975b Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Mon, 28 Oct 2024 13:46:58 -0400 Subject: [PATCH 02/10] it's working, needs cleanup --- src/viam/examples/modules/complex/client.cpp | 1 - .../examples/modules/complex/gizmo/api.cpp | 30 +--- .../examples/modules/complex/gizmo/impl.cpp | 14 +- src/viam/sdk/common/client_helper.hpp | 3 - src/viam/sdk/common/logger.cpp | 146 +++++++++++++++--- src/viam/sdk/common/logger.hpp | 105 ++++++++++--- src/viam/sdk/module/module.cpp | 22 --- src/viam/sdk/module/module.hpp | 6 - src/viam/sdk/module/service.cpp | 73 ++++++--- src/viam/sdk/module/service.hpp | 5 - src/viam/sdk/resource/resource.cpp | 3 +- src/viam/sdk/resource/resource.hpp | 2 +- src/viam/sdk/robot/client.cpp | 1 - 13 files changed, 276 insertions(+), 135 deletions(-) diff --git a/src/viam/examples/modules/complex/client.cpp b/src/viam/examples/modules/complex/client.cpp index 03a51b83b..6c960d7be 100644 --- a/src/viam/examples/modules/complex/client.cpp +++ b/src/viam/examples/modules/complex/client.cpp @@ -53,7 +53,6 @@ int main() { // of that type from the server. Registry::register_resource_client(); Registry::register_resource_client(); - std::cout << "We are here!!!!\n\n\n" << std::flush; // Connect to robot. std::shared_ptr robot = RobotClient::at_address(host, options); diff --git a/src/viam/examples/modules/complex/gizmo/api.cpp b/src/viam/examples/modules/complex/gizmo/api.cpp index d9746c983..4533e38fc 100644 --- a/src/viam/examples/modules/complex/gizmo/api.cpp +++ b/src/viam/examples/modules/complex/gizmo/api.cpp @@ -8,6 +8,7 @@ #include #include #include +#include #include #include #include @@ -27,17 +28,7 @@ API API::traits::api() { return {"viam", "component", "gizmo"}; } -Gizmo::Gizmo(std::string name) - : Component(std::move(name)) { - // boost::log::sources::severity_logger 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 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 arg1) { diff --git a/src/viam/examples/modules/complex/gizmo/impl.cpp b/src/viam/examples/modules/complex/gizmo/impl.cpp index 998042c80..fc68b8787 100644 --- a/src/viam/examples/modules/complex/gizmo/impl.cpp +++ b/src/viam/examples/modules/complex/gizmo/impl.cpp @@ -5,8 +5,11 @@ #include #include +#include +#include #include +#include #include #include #include @@ -50,14 +53,9 @@ std::vector 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; } diff --git a/src/viam/sdk/common/client_helper.hpp b/src/viam/sdk/common/client_helper.hpp index 1848586b4..b6aca1251 100644 --- a/src/viam/sdk/common/client_helper.hpp +++ b/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(rhc)( const_cast(response_)); } diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp index e39f79239..40a39fc29 100644 --- a/src/viam/sdk/common/logger.cpp +++ b/src/viam/sdk/common/logger.cpp @@ -1,15 +1,28 @@ #include +#include #include +#include +#include #include +#include +#include +#include #include +#include +#include +#include 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,8 +35,59 @@ struct Logger::impl { ll level_; }; -std::shared_ptr> 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 inited = false; +} + +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)); +} + +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::get() = + (expr::stream << '[' << expr::attr("File") << ':' + << expr::attr("Line") << "] ")); + logging::add_common_attributes(); +} + +void init_logging() { + if (inited) { + return; + } + inited = true; + + init_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("File") << ':' << expr::attr("Line") + << "] " << expr::smessage)); + logging::add_common_attributes(); } Logger::Logger(std::string name) @@ -31,7 +95,7 @@ Logger::Logger(std::string name) 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(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 +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::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; diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index 4a7036d71..e5b2d70c9 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -1,49 +1,112 @@ #pragma once -#include -#include #include +#include +#include #include +#include +#include +#include + +// 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 Resource; +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: - ~Logger(); - enum class log_level : std::int8_t { - trace = -2, - debug = -1, - info = 0, // default value is info - warning = 1, - error = 2, - fatal = 3, + struct None {}; + + template + struct LogData { + List list; }; + 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; + + void log(const std::string& msg, log_level level, const char* file, int line_no) const; + + ~Logger(); + explicit Logger(std::string name); explicit Logger(std::string name, log_level level); - void log(const std::string& log, log_level level) const; - void debug(const std::string& log) const; - void error(const std::string& log) const; - void fatal(const std::string& log) const; - void info(const std::string& log) const; - void trace(const std::string& log) const; - void warning(const std::string& log) const; - void set_log_level(log_level level); - std::shared_ptr> - underlying(); + static std::string log_delineator(); + + struct impl; private: std::string name_; log_level level_; - struct impl; std::unique_ptr impl_; }; +// CR erodkin: these can probably be hidden entirely? or maybe not +void init_logging(); +void init_logging(std::ostream& strm); + } // 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__) + diff --git a/src/viam/sdk/module/module.cpp b/src/viam/sdk/module/module.cpp index 45460945b..a6a58dc90 100644 --- a/src/viam/sdk/module/module.cpp +++ b/src/viam/sdk/module/module.cpp @@ -11,34 +11,12 @@ namespace viam { namespace sdk { -namespace logging = boost::log; - Module::Module(std::string addr) : addr_(std::move(addr)) {}; void Module::set_ready() { ready_ = true; } -// namespace impl { -// class my_buf_ : public std::stringbuf { -// public: -// virtual int sync() { -// auto msg = this->str(); -// parent_->return 0; -//} - -// private: -// std::unique_ptr parent_; -//}; -//} // namespace impl - -// void Module::init_logging(const std::shared_ptr& parent) { -// typedef logging::sinks::synchronous_sink text_sink; -// auto sink = boost::make_shared(); -// sink->locked_backend()->add_stream(); -// logging::core::get()->add_sink(sink); -//} - const std::string& Module::name() const { return name_; }; diff --git a/src/viam/sdk/module/module.hpp b/src/viam/sdk/module/module.hpp index 394132340..18c7a0b82 100644 --- a/src/viam/sdk/module/module.hpp +++ b/src/viam/sdk/module/module.hpp @@ -9,8 +9,6 @@ namespace viam { namespace sdk { -// class ModuleService; - class Module { public: void set_ready(); @@ -23,15 +21,11 @@ class Module { const std::shared_ptr& channel() const; private: - // friend class ModuleService; std::string name_; std::string addr_; bool ready_; HandlerMap_ handles_; std::shared_ptr channel_; - - // protected: - // void init_logging(const std::shared_ptr& parent); }; } // namespace sdk diff --git a/src/viam/sdk/module/service.cpp b/src/viam/sdk/module/service.cpp index 203c34015..48abe14f5 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -10,9 +10,14 @@ #include #include +#include +#include #include #include +#include #include +#include +#include #include #include #include @@ -30,6 +35,7 @@ #include #include +#include #include #include #include @@ -208,21 +214,16 @@ ::grpc::Status ModuleService::RemoveResource( ::grpc::Status ModuleService::Ready(::grpc::ServerContext*, const ::viam::module::v1::ReadyRequest* request, ::viam::module::v1::ReadyResponse* response) { - std::cout << "Got ready request!!!!\n\n\n" << std::flush; const std::lock_guard lock(lock_); const viam::module::v1::HandlerMap hm = this->module_->handles().to_proto(); *response->mutable_handlermap() = hm; auto new_parent_addr = request->parent_address(); if (parent_addr_ != new_parent_addr) { parent_addr_ = std::move(new_parent_addr); - std::cout << "setting parent at " << parent_addr_ << "\n" << std::flush; if (!parent_) { parent_ = RobotClient::at_local_socket(parent_addr_, {0, boost::none}); } - parent_->log("foo", "info", "baz", std::chrono::system_clock::now(), "None"); - // parent_->log("foo", "error", "baz error", std::chrono::system_clock::now(), "None"); init_logging_(); - parent_->log("foo2", "error", "baz2", std::chrono::system_clock::now(), "None2"); } response->set_ready(module_->ready()); return grpc::Status(); @@ -233,14 +234,54 @@ class custom_logging_buf : public std::stringbuf { public: custom_logging_buf(std::shared_ptr parent) : parent_(std::move(parent)) {}; int sync() override { - std::cout << "in sync"; if (!parent_) { std::cerr << "Attempted to send custom gRPC log without parent address\n"; return -1; } + + std::cout << "here!"; + auto name_attr = + boost::log::attribute_cast>( + boost::log::core::get()->get_thread_attributes()["LoggerName"]); + + std::string name = name_attr.get(); + auto level_attr = + boost::log::attribute_cast>( + boost::log::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 = "module_service"; + 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(); - std::cout << " and the log is " << log << "\n" << std::flush; - parent_->log("s", "error", std::move(log), std::chrono::system_clock::now(), "None"); + // 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(), + "None"); return 0; } @@ -255,6 +296,7 @@ struct ModuleService::impl { : buf(::viam::sdk::impl::custom_logging_buf(std::move(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); @@ -262,10 +304,13 @@ struct ModuleService::impl { ::viam::sdk::impl::custom_logging_buf buf; boost::shared_ptr sink; + boost::shared_ptr stream; }; void ModuleService::init_logging_() { + BOOST_LOG_TRIVIAL(error) << "error log the old way"; impl_ = std::make_unique(parent_); + init_logging(*impl_->stream); logging::core::get()->add_sink(impl_->sink); } @@ -298,27 +343,19 @@ void ModuleService::serve() { server_->register_service(this); const std::string address = "unix://" + module_->addr(); server_->add_listening_port(address); - // std::cout << "setting parent at " << parent_addr_ << "\n" << std::flush; - // parent_ = RobotClient::at_local_socket(parent_addr_, {0, boost::none}); - std::cout << "initialize logging\n" << std::flush; - std::cout << "initialized logging\n" << std::flush; module_->set_ready(); - std::cout << "starting\n" << std::flush; server_->start(); - std::cout << "started\n" << std::flush; BOOST_LOG_TRIVIAL(info) << "Module listening on " << module_->addr(); BOOST_LOG_TRIVIAL(info) << "Module handles the following API/model pairs:\n" << module_->handles(); - // init_logging_(); - - std::cout << "added some logs surely that's fine\n" << std::flush; signal_manager_.wait(); } ModuleService::~ModuleService() { // TODO(RSDK-5509): Run registered cleanup functions here. + // CR erodkin: this is breaking because of level parsing, fix that // BOOST_LOG_TRIVIAL(info) << "Shutting down gracefully."; server_->shutdown(); @@ -326,7 +363,7 @@ ModuleService::~ModuleService() { try { parent_->close(); } catch (const std::exception& exc) { - // BOOST_LOG_TRIVIAL(error) << exc.what(); + BOOST_LOG_TRIVIAL(error) << exc.what(); } } } diff --git a/src/viam/sdk/module/service.hpp b/src/viam/sdk/module/service.hpp index bd1d01de8..511d7b64e 100644 --- a/src/viam/sdk/module/service.hpp +++ b/src/viam/sdk/module/service.hpp @@ -1,13 +1,8 @@ #pragma once -#include - #include #include -#include -#include - #include #include #include diff --git a/src/viam/sdk/resource/resource.cpp b/src/viam/sdk/resource/resource.cpp index 59085e0d2..a4faadc50 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_(name), logger_(Logger(std::move(name))) {} +Resource::Resource(std::string name) + : name_(name), logger_(std::make_unique(std::move(name))) {} std::string Resource::name() const { return name_; diff --git a/src/viam/sdk/resource/resource.hpp b/src/viam/sdk/resource/resource.hpp index 286638843..2b8450a28 100644 --- a/src/viam/sdk/resource/resource.hpp +++ b/src/viam/sdk/resource/resource.hpp @@ -34,7 +34,7 @@ class Resource { protected: // NOLINTNEXTLINE - Logger logger_; + std::unique_ptr logger_; }; template <> diff --git a/src/viam/sdk/robot/client.cpp b/src/viam/sdk/robot/client.cpp index e2f13d720..dac77a166 100644 --- a/src/viam/sdk/robot/client.cpp +++ b/src/viam/sdk/robot/client.cpp @@ -180,7 +180,6 @@ void RobotClient::log( std::string stack) { robot::v1::LogRequest req; common::v1::LogEntry log; - std::cout << "calling log\n" << std::endl; *log.mutable_logger_name() = std::move(name); std::transform(level.begin(), level.end(), level.begin(), ::toupper); log.set_level(level); From b1186c4fb1956e1e6aad747525a5f338c862d313 Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Wed, 30 Oct 2024 09:47:58 -0400 Subject: [PATCH 03/10] working, cleaned, comments explaining iffiness --- src/viam/examples/modules/complex/client.cpp | 30 +++---- .../examples/modules/complex/gizmo/api.cpp | 6 -- .../examples/modules/complex/gizmo/impl.cpp | 6 -- src/viam/examples/modules/complex/main.cpp | 1 - .../examples/modules/complex/proto/buf.lock | 4 +- src/viam/examples/modules/simple/main.cpp | 1 - src/viam/sdk/common/client_helper.cpp | 8 +- src/viam/sdk/common/logger.cpp | 78 ++++++++++++------- src/viam/sdk/common/logger.hpp | 47 +++++++---- src/viam/sdk/config/resource.cpp | 9 ++- src/viam/sdk/config/resource.hpp | 3 + src/viam/sdk/module/handler_map.cpp | 9 +-- src/viam/sdk/module/module.cpp | 2 - src/viam/sdk/module/service.cpp | 70 ++++++++++------- src/viam/sdk/module/service.hpp | 1 + src/viam/sdk/registry/registry.cpp | 7 +- src/viam/sdk/resource/resource.cpp | 4 + src/viam/sdk/resource/resource.hpp | 2 + src/viam/sdk/resource/resource_manager.cpp | 17 ++-- src/viam/sdk/robot/client.cpp | 61 +++++++++------ src/viam/sdk/robot/client.hpp | 4 +- src/viam/sdk/rpc/server.cpp | 1 - 22 files changed, 218 insertions(+), 153 deletions(-) diff --git a/src/viam/examples/modules/complex/client.cpp b/src/viam/examples/modules/complex/client.cpp index 6c960d7be..274314326 100644 --- a/src/viam/examples/modules/complex/client.cpp +++ b/src/viam/examples/modules/complex/client.cpp @@ -27,27 +27,19 @@ using namespace viam::sdk; int main() { - // const char* uri = "http://localhost:8080/"; // replace with your URI if connecting securely - // DialOptions dial_options; - // dial_options.set_allow_insecure_downgrade(true); // set to false if connecting securely + const char* uri = "http://localhost:8080/"; // replace with your URI if connecting securely + DialOptions dial_options; + dial_options.set_allow_insecure_downgrade(true); // set to false if connecting securely // Uncomment and fill out your credentials details if connecting securely - // std::string type = ""; - // std::string payload = ""; - // Credentials credentials(type, payload); - // dial_options.set_credentials(credentials); + std::string type = ""; + std::string payload = ""; + Credentials credentials(type, payload); + dial_options.set_credentials(credentials); - std::string host("webrtc-test-main.jkek76kqnh.viam.cloud"); - DialOptions dial_opts; - dial_opts.set_entity(std::string("a9dcf212-3397-4318-bb1e-f5c36b3cafc1")); - Credentials credentials("api-key", "2ml60ys1j4i9v0pecpxahe654yxpc1dz"); - dial_opts.set_credentials(credentials); - boost::optional opts(dial_opts); - Options options(0, opts); - - // boost::optional opts(dial_options); - // std::string address(uri); - // Options options(1, opts); + boost::optional opts(dial_options); + std::string address(uri); + Options options(1, opts); // Register custom gizmo and summation clients so robot client can access resources // of that type from the server. @@ -55,7 +47,7 @@ int main() { Registry::register_resource_client(); // Connect to robot. - std::shared_ptr robot = RobotClient::at_address(host, options); + std::shared_ptr robot = RobotClient::at_address(address, options); // Print resources. std::cout << "Resources" << std::endl; std::vector resource_names = robot->resource_names(); diff --git a/src/viam/examples/modules/complex/gizmo/api.cpp b/src/viam/examples/modules/complex/gizmo/api.cpp index 4533e38fc..49663226a 100644 --- a/src/viam/examples/modules/complex/gizmo/api.cpp +++ b/src/viam/examples/modules/complex/gizmo/api.cpp @@ -4,11 +4,7 @@ #include -#include -#include -#include #include -#include #include #include #include @@ -179,8 +175,6 @@ GizmoClient::GizmoClient(std::string name, std::shared_ptr channe channel_(std::move(channel)) {}; bool GizmoClient::do_one(std::string arg1) { - 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) { request.set_arg1(arg1); }) .invoke([](auto& response) { return response.ret1(); }); diff --git a/src/viam/examples/modules/complex/gizmo/impl.cpp b/src/viam/examples/modules/complex/gizmo/impl.cpp index fc68b8787..e15fa66be 100644 --- a/src/viam/examples/modules/complex/gizmo/impl.cpp +++ b/src/viam/examples/modules/complex/gizmo/impl.cpp @@ -5,11 +5,8 @@ #include #include -#include -#include #include -#include #include #include #include @@ -53,9 +50,6 @@ std::vector MyGizmo::validate(const ResourceConfig& cfg) { } bool MyGizmo::do_one(std::string arg1) { - // 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; } diff --git a/src/viam/examples/modules/complex/main.cpp b/src/viam/examples/modules/complex/main.cpp index 64e532ac4..4a83cd563 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/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 index 40a39fc29..40f0f9ff2 100644 --- a/src/viam/sdk/common/logger.cpp +++ b/src/viam/sdk/common/logger.cpp @@ -42,6 +42,12 @@ std::string path_to_filename(const std::string& path) { 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() { @@ -53,17 +59,41 @@ void init_attributes() { 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 init_logging(std::ostream& strm) { - if (inited) { + if (inited_with_ostrm) { return; } - inited = true; - - init_attributes(); + inited_with_ostrm = true; // remove existing stdout/stderr logging since we're sending logs to RDK - boost::log::core::get()->remove_all_sinks(); + logging::core::get()->remove_all_sinks(); + + init_attributes(); + // The current use case for init logging logging::add_console_log(strm, boost::parameter::keyword::get() = (expr::stream << '[' << expr::attr("File") << ':' @@ -72,13 +102,12 @@ void init_logging(std::ostream& strm) { } void init_logging() { - if (inited) { + init_attributes(); + if (inited || inited_with_ostrm) { return; } inited = true; - init_attributes(); - logging::add_console_log( std::clog, boost::parameter::keyword::get() = @@ -90,6 +119,10 @@ void init_logging() { logging::add_common_attributes(); } +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) @@ -150,34 +183,25 @@ ValueType set_get_attrib(const char* name, ValueType value) { return attr.get(); } -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( + (set_get_attrib("LogLevel", level_to_string(level)))(set_get_attrib("LoggerName", name_))( + 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; } +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 diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index e5b2d70c9..569d3df77 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -5,9 +5,8 @@ #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 @@ -23,7 +22,7 @@ namespace viam { namespace sdk { -class Resource; +class ModuleService; enum class log_level : std::int8_t { trace = -2, @@ -35,6 +34,13 @@ enum class log_level : std::int8_t { }; class Logger { public: + static log_level from_string(std::string str); + 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; + struct None {}; template @@ -42,6 +48,16 @@ class Logger { 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 { @@ -78,28 +94,24 @@ class Logger { } NOINLINE_ATTRIBUTE; - void log(const std::string& msg, log_level level, const char* file, int line_no) const; - ~Logger(); - explicit Logger(std::string name); - explicit Logger(std::string name, log_level level); - - void set_log_level(log_level level); - - static std::string log_delineator(); + friend class ModuleService; + private: + void static static_log_(const std::string& msg, log_level level, const char* file, int line_no); struct impl; + struct module_logging_impl; - private: std::string name_; log_level level_; std::unique_ptr impl_; }; -// CR erodkin: these can probably be hidden entirely? or maybe not +// (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 init_logging(); -void init_logging(std::ostream& strm); +void init_logging(std::ostream& custom_strm); } // namespace sdk } // namespace viam @@ -110,3 +122,8 @@ void init_logging(std::ostream& strm); 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/config/resource.cpp b/src/viam/sdk/config/resource.cpp index 758a52637..0e9bc2db2 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_); @@ -138,7 +144,8 @@ viam::app::v1::ComponentConfig ResourceConfig::to_proto() const { return proto_cfg; } -ResourceConfig::ResourceConfig(std::string type) : api_({kRDK, type, ""}), type_(std::move(type)){}; +ResourceConfig::ResourceConfig(std::string type) + : api_({kRDK, type, ""}), type_(std::move(type)) {}; } // namespace sdk } // namespace viam diff --git a/src/viam/sdk/config/resource.hpp b/src/viam/sdk/config/resource.hpp index a89ff0f9e..8ea430c9d 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; + 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..646f1127b 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 { @@ -34,7 +32,7 @@ viam::module::v1::HandlerMap HandlerMap_::to_proto() const { return proto; }; -HandlerMap_::HandlerMap_(){}; +HandlerMap_::HandlerMap_() {}; // NOLINTNEXTLINE(readability-const-return-type) const HandlerMap_ HandlerMap_::from_proto(const viam::module::v1::HandlerMap& proto) { @@ -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 a6a58dc90..6ccc4b62c 100644 --- a/src/viam/sdk/module/module.cpp +++ b/src/viam/sdk/module/module.cpp @@ -1,7 +1,5 @@ #include -#include -#include #include #include #include diff --git a/src/viam/sdk/module/service.cpp b/src/viam/sdk/module/service.cpp index 48abe14f5..e307c5de9 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -53,6 +53,8 @@ namespace viam { namespace sdk { +using ll = log_level; + namespace logging = boost::log; Dependencies ModuleService::get_dependencies_( @@ -96,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()); } @@ -133,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()); @@ -142,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()); @@ -204,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); @@ -229,7 +235,13 @@ ::grpc::Status ModuleService::Ready(::grpc::ServerContext*, return grpc::Status(); }; -namespace impl { +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)) {}; @@ -239,15 +251,14 @@ class custom_logging_buf : public std::stringbuf { return -1; } - std::cout << "here!"; auto name_attr = - boost::log::attribute_cast>( - boost::log::core::get()->get_thread_attributes()["LoggerName"]); + logging::attribute_cast>( + logging::core::get()->get_thread_attributes()["LoggerName"]); std::string name = name_attr.get(); auto level_attr = - boost::log::attribute_cast>( - boost::log::core::get()->get_thread_attributes()["LogLevel"]); + logging::attribute_cast>( + logging::core::get()->get_thread_attributes()["LogLevel"]); std::string level = level_attr.get(); if (name == "" || level == "") { @@ -256,16 +267,17 @@ class custom_logging_buf : public std::stringbuf { // 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 = "module_service"; + 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(""); + // 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 @@ -277,24 +289,20 @@ class custom_logging_buf : public std::stringbuf { log.erase(first_newline_char, 1); } - parent_->log(std::move(name), - std::move(level), - std::move(log), - std::chrono::system_clock::now(), - "None"); + parent_->log( + std::move(name), std::move(level), std::move(log), std::chrono::system_clock::now()); return 0; } private: std::shared_ptr parent_; }; -} // namespace impl +} // namespace struct ModuleService::impl { typedef logging::sinks::synchronous_sink text_sink; - impl(std::shared_ptr parent) - : buf(::viam::sdk::impl::custom_logging_buf(std::move(parent))) { - auto backend = boost::make_shared(); + 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); @@ -302,24 +310,26 @@ struct ModuleService::impl { sink = boost::make_shared(backend); } - ::viam::sdk::impl::custom_logging_buf buf; + custom_logging_buf buf; boost::shared_ptr sink; boost::shared_ptr stream; }; void ModuleService::init_logging_() { - BOOST_LOG_TRIVIAL(error) << "error log the old way"; impl_ = std::make_unique(parent_); 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()) {} + : module_(std::make_unique(std::move(addr))), + server_(std::make_unique()), + logger_(std::make_unique("viam-cpp-module-service")) {} 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"); } @@ -346,24 +356,26 @@ 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. - // CR erodkin: this is breaking because of level parsing, fix that - // BOOST_LOG_TRIVIAL(info) << "Shutting down gracefully."; + VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, ll::info, "Shutting down gracefully"); server_->shutdown(); if (parent_) { try { parent_->close(); } catch (const std::exception& exc) { - BOOST_LOG_TRIVIAL(error) << exc.what(); + VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, ll::error, exc.what()); } } } diff --git a/src/viam/sdk/module/service.hpp b/src/viam/sdk/module/service.hpp index 511d7b64e..01613848d 100644 --- a/src/viam/sdk/module/service.hpp +++ b/src/viam/sdk/module/service.hpp @@ -83,6 +83,7 @@ class ModuleService : viam::module::v1::ModuleService::Service { std::string parent_addr_; std::unique_ptr server_; SignalManager signal_manager_; + std::unique_ptr logger_; }; } // namespace sdk 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 a4faadc50..c9d326185 100644 --- a/src/viam/sdk/resource/resource.cpp +++ b/src/viam/sdk/resource/resource.cpp @@ -30,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 2b8450a28..3361849cc 100644 --- a/src/viam/sdk/resource/resource.hpp +++ b/src/viam/sdk/resource/resource.hpp @@ -29,6 +29,8 @@ class Resource { /// @brief Return the resource's name. virtual std::string name() const; + void set_log_level(log_level level); + private: std::string name_; 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 dac77a166..454b2576c 100644 --- a/src/viam/sdk/robot/client.cpp +++ b/src/viam/sdk/robot/client.cpp @@ -1,4 +1,3 @@ -#include #include #include @@ -10,7 +9,6 @@ #include #include -#include #include #include #include @@ -20,11 +18,13 @@ #include #include +#include #include #include #include #include #include +#include #include #include #include @@ -40,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 @@ -148,9 +149,11 @@ 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"); } } } @@ -176,8 +179,7 @@ void RobotClient::log( std::string name, std::string level, std::string message, - const std::chrono::time_point& time, - std::string stack) { + const std::chrono::time_point& time) { robot::v1::LogRequest req; common::v1::LogEntry log; *log.mutable_logger_name() = std::move(name); @@ -185,14 +187,15 @@ void RobotClient::log( log.set_level(level); *log.mutable_message() = std::move(message); *log.mutable_time() = time_pt_to_timestamp(time); - *log.mutable_stack() = std::move(stack); + *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)) { - BOOST_LOG_TRIVIAL(error) << "Error sending log: " << response.error_message() - << response.error_details(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, + "Error sending log: " << response.error_message() << response.error_details()); } } @@ -209,8 +212,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(); @@ -233,7 +237,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) { @@ -251,7 +256,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); } } @@ -264,7 +270,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); } } @@ -275,8 +282,10 @@ 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() - << response.error_details(); + VIAM_SDK_TRIVIAL_CUSTOM_FORMATTED_LOG( + ll::error, + "Error getting resource names: " << response.error_message() + << response.error_details()); return; } @@ -300,8 +309,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()); } } } @@ -403,8 +413,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(); @@ -436,7 +446,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()); @@ -456,7 +467,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(); @@ -497,8 +509,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 5ac889962..142acc05e 100644 --- a/src/viam/sdk/robot/client.hpp +++ b/src/viam/sdk/robot/client.hpp @@ -15,6 +15,7 @@ #include #include #include +#include #include #include @@ -119,8 +120,7 @@ class RobotClient { std::string name, std::string level, std::string message, - const std::chrono::time_point& time, - std::string stack); + const std::chrono::time_point& time); template /// @brief Lookup and return a `shared_ptr` to a resource of the requested type. 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 From dbd32dad09bfee43990e431663db5bdfc01f53fa Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Wed, 30 Oct 2024 10:02:12 -0400 Subject: [PATCH 04/10] cleanup --- src/viam/examples/modules/complex/client.cpp | 8 ++++---- src/viam/examples/modules/complex/gizmo/api.cpp | 8 +++----- src/viam/examples/modules/complex/gizmo/impl.hpp | 2 +- src/viam/examples/modules/complex/main.cpp | 3 --- src/viam/sdk/common/client_helper.hpp | 3 --- src/viam/sdk/common/logger.cpp | 2 ++ src/viam/sdk/common/logger.hpp | 1 - src/viam/sdk/components/component.cpp | 4 ++-- src/viam/sdk/config/resource.cpp | 3 +-- src/viam/sdk/module/handler_map.cpp | 2 +- src/viam/sdk/module/module.cpp | 2 +- src/viam/sdk/module/service.cpp | 4 ++-- 12 files changed, 17 insertions(+), 25 deletions(-) diff --git a/src/viam/examples/modules/complex/client.cpp b/src/viam/examples/modules/complex/client.cpp index 274314326..894fd5c11 100644 --- a/src/viam/examples/modules/complex/client.cpp +++ b/src/viam/examples/modules/complex/client.cpp @@ -32,10 +32,10 @@ int main() { dial_options.set_allow_insecure_downgrade(true); // set to false if connecting securely // Uncomment and fill out your credentials details if connecting securely - std::string type = ""; - std::string payload = ""; - Credentials credentials(type, payload); - dial_options.set_credentials(credentials); + // std::string type = ""; + // std::string payload = ""; + // Credentials credentials(type, payload); + // dial_options.set_credentials(credentials); boost::optional opts(dial_options); std::string address(uri); diff --git a/src/viam/examples/modules/complex/gizmo/api.cpp b/src/viam/examples/modules/complex/gizmo/api.cpp index 49663226a..4059c9034 100644 --- a/src/viam/examples/modules/complex/gizmo/api.cpp +++ b/src/viam/examples/modules/complex/gizmo/api.cpp @@ -24,12 +24,12 @@ API API::traits::api() { return {"viam", "component", "gizmo"}; } -Gizmo::Gizmo(std::string name) : Component(std::move(name)) {}; +Gizmo::Gizmo(std::string name) : Component(std::move(name)){}; /* Gizmo server methods */ GizmoServer::GizmoServer(std::shared_ptr manager) - : ResourceServer(std::move(manager)) {}; + : ResourceServer(std::move(manager)){}; grpc::Status GizmoServer::DoOne(grpc::ServerContext* context, const DoOneRequest* request, @@ -170,9 +170,7 @@ grpc::Status GizmoServer::DoTwo(::grpc::ServerContext* context, /* Gizmo client methods */ GizmoClient::GizmoClient(std::string name, std::shared_ptr channel) - : Gizmo(std::move(name)), - stub_(GizmoService::NewStub(channel)), - channel_(std::move(channel)) {}; + : Gizmo(std::move(name)), stub_(GizmoService::NewStub(channel)), channel_(std::move(channel)){}; bool GizmoClient::do_one(std::string arg1) { return make_client_helper(this, *stub_, &StubType::DoOne) diff --git a/src/viam/examples/modules/complex/gizmo/impl.hpp b/src/viam/examples/modules/complex/gizmo/impl.hpp index e937d62f4..78e9e3225 100644 --- a/src/viam/examples/modules/complex/gizmo/impl.hpp +++ b/src/viam/examples/modules/complex/gizmo/impl.hpp @@ -14,7 +14,7 @@ using namespace viam::sdk; // `validate` method that checks config validity. class MyGizmo : public Gizmo, public Reconfigurable { public: - MyGizmo(std::string name, std::string arg1) : Gizmo(std::move(name)), arg1_(std::move(arg1)) {}; + MyGizmo(std::string name, std::string arg1) : Gizmo(std::move(name)), arg1_(std::move(arg1)){}; MyGizmo(const Dependencies& deps, const ResourceConfig& cfg) : Gizmo(cfg.name()) { this->reconfigure(deps, cfg); }; diff --git a/src/viam/examples/modules/complex/main.cpp b/src/viam/examples/modules/complex/main.cpp index 4a83cd563..7e57cbeae 100644 --- a/src/viam/examples/modules/complex/main.cpp +++ b/src/viam/examples/modules/complex/main.cpp @@ -29,8 +29,6 @@ using namespace viam::sdk; int main(int argc, char** argv) { Model mybase_model("viam", "base", "mybase"); - std::cout << "registering resource servers\n" << std::flush; - // Make sure to explicity register resources with custom APIs. Registry::register_resource_server(); Registry::register_resource_server(); @@ -57,7 +55,6 @@ int main(int argc, char** argv) { std::vector> mrs = {mybase_mr, mygizmo_mr, mysummation_mr}; auto my_mod = std::make_shared(argc, argv, mrs); - std::cout << "we have created the module and gotten ready to serve\n" << std::flush; my_mod->serve(); return EXIT_SUCCESS; diff --git a/src/viam/sdk/common/client_helper.hpp b/src/viam/sdk/common/client_helper.hpp index b6aca1251..d8db1f338 100644 --- a/src/viam/sdk/common/client_helper.hpp +++ b/src/viam/sdk/common/client_helper.hpp @@ -35,9 +35,6 @@ class ClientHelper { static void default_rsc_(RequestType&) {} static void default_rhc_(const ResponseType&) {} static void default_ehc_(const ::grpc::Status& status) { - std::cout << "error is " << status.error_details() << " " << status.error_code() << " " - << status.error_message() << "\n" - << std::flush; throw GRPCException(status); } diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp index 40f0f9ff2..665855df0 100644 --- a/src/viam/sdk/common/logger.cpp +++ b/src/viam/sdk/common/logger.cpp @@ -185,6 +185,8 @@ ValueType set_get_attrib(const char* name, ValueType value) { void Logger::log(const std::string& msg, log_level level, const char* filename, int line_no) const { // 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( diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index 569d3df77..7dc035c4c 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -115,7 +115,6 @@ void init_logging(std::ostream& custom_strm); } // namespace sdk } // namespace viam - // // New macro that includes severity, filename and line number #define VIAM_SDK_CUSTOM_FORMATTED_LOG(logger, sev, msg) \ diff --git a/src/viam/sdk/components/component.cpp b/src/viam/sdk/components/component.cpp index 1dbcddafd..c44bd91e9 100644 --- a/src/viam/sdk/components/component.cpp +++ b/src/viam/sdk/components/component.cpp @@ -14,9 +14,9 @@ namespace sdk { using viam::common::v1::ResourceName; -Component::Component() : Resource("component") {}; +Component::Component() : Resource("component"){}; -Component::Component(std::string name) : Resource(std::move(name)) {}; +Component::Component(std::string name) : Resource(std::move(name)){}; ResourceName Component::get_resource_name(std::string name) const { auto r = this->Resource::get_resource_name(name); diff --git a/src/viam/sdk/config/resource.cpp b/src/viam/sdk/config/resource.cpp index 0e9bc2db2..aa04581ae 100644 --- a/src/viam/sdk/config/resource.cpp +++ b/src/viam/sdk/config/resource.cpp @@ -144,8 +144,7 @@ viam::app::v1::ComponentConfig ResourceConfig::to_proto() const { return proto_cfg; } -ResourceConfig::ResourceConfig(std::string type) - : api_({kRDK, type, ""}), type_(std::move(type)) {}; +ResourceConfig::ResourceConfig(std::string type) : api_({kRDK, type, ""}), type_(std::move(type)){}; } // namespace sdk } // namespace viam diff --git a/src/viam/sdk/module/handler_map.cpp b/src/viam/sdk/module/handler_map.cpp index 646f1127b..74a50d456 100644 --- a/src/viam/sdk/module/handler_map.cpp +++ b/src/viam/sdk/module/handler_map.cpp @@ -32,7 +32,7 @@ viam::module::v1::HandlerMap HandlerMap_::to_proto() const { return proto; }; -HandlerMap_::HandlerMap_() {}; +HandlerMap_::HandlerMap_(){}; // NOLINTNEXTLINE(readability-const-return-type) const HandlerMap_ HandlerMap_::from_proto(const viam::module::v1::HandlerMap& proto) { diff --git a/src/viam/sdk/module/module.cpp b/src/viam/sdk/module/module.cpp index 6ccc4b62c..7e18a236c 100644 --- a/src/viam/sdk/module/module.cpp +++ b/src/viam/sdk/module/module.cpp @@ -9,7 +9,7 @@ namespace viam { namespace sdk { -Module::Module(std::string addr) : addr_(std::move(addr)) {}; +Module::Module(std::string addr) : addr_(std::move(addr)){}; void Module::set_ready() { ready_ = true; diff --git a/src/viam/sdk/module/service.cpp b/src/viam/sdk/module/service.cpp index e307c5de9..477303eae 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -1,7 +1,7 @@ -#include #include #include +#include #include #include #include @@ -274,7 +274,7 @@ class custom_logging_buf : public std::stringbuf { // 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(""); + level_attr.set(""); auto log = this->str(); this->str(""); From 27ecd9b3f5676f777f94a64c2c79f30be3dd085d Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 1 Nov 2024 10:40:35 -0400 Subject: [PATCH 05/10] cleanup, minimize abort trap --- src/viam/sdk/common/logger.cpp | 24 +++++++++------- src/viam/sdk/common/logger.hpp | 3 +- src/viam/sdk/common/utils.cpp | 12 -------- src/viam/sdk/common/utils.hpp | 10 ------- src/viam/sdk/module/service.cpp | 51 +++++++++++++++++++-------------- src/viam/sdk/module/service.hpp | 6 ++-- src/viam/sdk/robot/client.cpp | 3 +- src/viam/sdk/rpc/dial.cpp | 6 ++++ src/viam/sdk/rpc/dial.hpp | 2 ++ 9 files changed, 56 insertions(+), 61 deletions(-) diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp index 665855df0..ca7bae680 100644 --- a/src/viam/sdk/common/logger.cpp +++ b/src/viam/sdk/common/logger.cpp @@ -91,6 +91,7 @@ void init_logging(std::ostream& strm) { // 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 @@ -98,7 +99,6 @@ void init_logging(std::ostream& strm) { boost::parameter::keyword::get() = (expr::stream << '[' << expr::attr("File") << ':' << expr::attr("Line") << "] ")); - logging::add_common_attributes(); } void init_logging() { @@ -107,16 +107,17 @@ void init_logging() { 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 << "> " << '[' + << ": [" << boost::log::trivial::severity << "] " + << expr::attr("LoggerName") << " [" << expr::attr("File") << ':' << expr::attr("Line") - << "] " << expr::smessage)); - logging::add_common_attributes(); + << "] " << expr::smessage)); } void Logger::set_log_level(ll level) { @@ -154,6 +155,8 @@ logging::trivial::severity_level _log_level_to_severity_level(log_level level) { 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"; } @@ -163,9 +166,6 @@ std::string level_to_string(log_level level) { case ll::debug: { return "debug"; } - case ll::fatal: { - return "fatal"; - } case ll::trace: { return "trace"; } @@ -184,6 +184,9 @@ ValueType set_get_attrib(const char* name, ValueType value) { } 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. @@ -191,9 +194,10 @@ void Logger::log(const std::string& msg, log_level level, const char* filename, BOOST_LOG_STREAM_WITH_PARAMS( *(impl_->logger_), - (set_get_attrib("LogLevel", level_to_string(level)))(set_get_attrib("LoggerName", name_))( - 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))) + (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; } diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index 7dc035c4c..b69c52ab5 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -34,12 +34,12 @@ enum class log_level : std::int8_t { }; class Logger { public: - static log_level from_string(std::string str); 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 {}; @@ -101,7 +101,6 @@ class Logger { private: void static static_log_(const std::string& msg, log_level level, const char* file, int line_no); struct impl; - struct module_logging_impl; std::string name_; log_level level_; diff --git a/src/viam/sdk/common/utils.cpp b/src/viam/sdk/common/utils.cpp index 84ecc9c35..1f7c16c34 100644 --- a/src/viam/sdk/common/utils.cpp +++ b/src/viam/sdk/common/utils.cpp @@ -6,9 +6,6 @@ #include #include -#include -#include -#include #include #include @@ -103,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 34ed89559..e5bebe7fe 100644 --- a/src/viam/sdk/common/utils.hpp +++ b/src/viam/sdk/common/utils.hpp @@ -90,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/module/service.cpp b/src/viam/sdk/module/service.cpp index 477303eae..50baca40f 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -1,7 +1,7 @@ #include -#include #include +#include #include #include #include @@ -271,18 +271,18 @@ class custom_logging_buf : public std::stringbuf { 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. + // 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(""); + 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. + // 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) { @@ -310,9 +310,12 @@ struct ModuleService::impl { sink = boost::make_shared(backend); } + ~impl() { + logging::core::get()->remove_sink(sink); + } custom_logging_buf buf; - boost::shared_ptr sink; boost::shared_ptr stream; + boost::shared_ptr sink; }; void ModuleService::init_logging_() { @@ -322,9 +325,9 @@ void ModuleService::init_logging_() { } ModuleService::ModuleService(std::string addr) - : module_(std::make_unique(std::move(addr))), - server_(std::make_unique()), - logger_(std::make_unique("viam-cpp-module-service")) {} + : 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, @@ -336,7 +339,6 @@ ModuleService::ModuleService(int argc, 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); @@ -368,16 +370,21 @@ void ModuleService::serve() { ModuleService::~ModuleService() { // TODO(RSDK-5509): Run registered cleanup functions here. + // 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"); - server_->shutdown(); - - if (parent_) { - try { - parent_->close(); - } catch (const std::exception& exc) { - VIAM_SDK_CUSTOM_FORMATTED_LOG(logger_, ll::error, exc.what()); - } - } } 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 01613848d..e4e96603c 100644 --- a/src/viam/sdk/module/service.hpp +++ b/src/viam/sdk/module/service.hpp @@ -75,15 +75,15 @@ 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_; - std::shared_ptr parent_; 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_; - std::unique_ptr logger_; }; } // namespace sdk diff --git a/src/viam/sdk/robot/client.cpp b/src/viam/sdk/robot/client.cpp index 454b2576c..7e8a73d76 100644 --- a/src/viam/sdk/robot/client.cpp +++ b/src/viam/sdk/robot/client.cpp @@ -160,11 +160,10 @@ RobotClient::~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) { 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: From d34f995ca6ab9293d8d84f1386cb861be610afe3 Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 1 Nov 2024 10:49:25 -0400 Subject: [PATCH 06/10] clang tidy --- src/viam/sdk/common/logger.cpp | 4 ++-- src/viam/sdk/common/logger.hpp | 1 - src/viam/sdk/module/service.cpp | 2 +- 3 files changed, 3 insertions(+), 4 deletions(-) diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp index ca7bae680..426751448 100644 --- a/src/viam/sdk/common/logger.cpp +++ b/src/viam/sdk/common/logger.cpp @@ -125,9 +125,9 @@ void Logger::set_log_level(ll level) { } Logger::Logger(std::string name) - : name_(std::move(name)), level_(log_level::info), impl_(std::make_unique()) {}; + : 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)) {}; + : 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) { diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index b69c52ab5..ac4ad967a 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -124,4 +124,3 @@ void init_logging(std::ostream& custom_strm); #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/module/service.cpp b/src/viam/sdk/module/service.cpp index 50baca40f..753b27b28 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -244,7 +244,7 @@ namespace { // 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)) {}; + 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"; From 6ef47542a0b77cb3c4f8c2932e64422a8a620c94 Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 1 Nov 2024 11:10:24 -0400 Subject: [PATCH 07/10] qualify enum return --- src/viam/sdk/config/resource.hpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/viam/sdk/config/resource.hpp b/src/viam/sdk/config/resource.hpp index 8ea430c9d..29bbae272 100644 --- a/src/viam/sdk/config/resource.hpp +++ b/src/viam/sdk/config/resource.hpp @@ -34,7 +34,7 @@ class ResourceConfig { const std::string& namespace_() const; const std::string& type() const; const ProtoStruct& attributes() const; - log_level log_level() const; + enum log_level log_level() const; private: API api_; From 7a0d5897980cd62c5b5c3f0838180b9e828e9540 Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 1 Nov 2024 14:20:22 -0400 Subject: [PATCH 08/10] avoid atomic bool copy constructor --- src/viam/sdk/common/logger.cpp | 8 ++++---- src/viam/sdk/common/logger.hpp | 11 ++++++----- src/viam/sdk/module/service.cpp | 2 +- 3 files changed, 11 insertions(+), 10 deletions(-) diff --git a/src/viam/sdk/common/logger.cpp b/src/viam/sdk/common/logger.cpp index 426751448..8773d751d 100644 --- a/src/viam/sdk/common/logger.cpp +++ b/src/viam/sdk/common/logger.cpp @@ -41,8 +41,8 @@ std::string path_to_filename(const std::string& path) { } namespace { -std::atomic inited = false; -std::atomic inited_with_ostrm = false; +std::atomic inited(false); +std::atomic inited_with_ostrm(false); } // namespace std::shared_ptr default_logger() { @@ -82,7 +82,7 @@ ll Logger::from_string(std::string str) { return ll::info; } -void init_logging(std::ostream& strm) { +void Logger::init_logging(std::ostream& strm) { if (inited_with_ostrm) { return; } @@ -101,7 +101,7 @@ void init_logging(std::ostream& strm) { << expr::attr("Line") << "] ")); } -void init_logging() { +void Logger::init_logging() { init_attributes(); if (inited || inited_with_ostrm) { return; diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index ac4ad967a..805c87b54 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -98,6 +98,12 @@ class 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; @@ -107,11 +113,6 @@ class Logger { std::unique_ptr impl_; }; -// (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 init_logging(); -void init_logging(std::ostream& custom_strm); - } // namespace sdk } // namespace viam diff --git a/src/viam/sdk/module/service.cpp b/src/viam/sdk/module/service.cpp index 753b27b28..4939d3379 100644 --- a/src/viam/sdk/module/service.cpp +++ b/src/viam/sdk/module/service.cpp @@ -320,7 +320,7 @@ struct ModuleService::impl { void ModuleService::init_logging_() { impl_ = std::make_unique(parent_); - init_logging(*impl_->stream); + Logger::init_logging(*impl_->stream); logging::core::get()->add_sink(impl_->sink); } From 635999f3c271c13ec49e473c21a7494ec3371613 Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 1 Nov 2024 14:30:51 -0400 Subject: [PATCH 09/10] include memory for unique_ptr --- src/viam/sdk/common/logger.hpp | 1 + 1 file changed, 1 insertion(+) diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index 805c87b54..abc60f7ec 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -3,6 +3,7 @@ #include #include #include +#include #include // Some of the logic here has been cribbed from From 026e5f6411c7ba441199f7a6118537025f24ca94 Mon Sep 17 00:00:00 2001 From: Ethan Rodkin Date: Fri, 1 Nov 2024 14:31:13 -0400 Subject: [PATCH 10/10] include memory for unique_ptr2 --- src/viam/sdk/common/logger.hpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/viam/sdk/common/logger.hpp b/src/viam/sdk/common/logger.hpp index abc60f7ec..56cbf534b 100644 --- a/src/viam/sdk/common/logger.hpp +++ b/src/viam/sdk/common/logger.hpp @@ -2,8 +2,8 @@ #include #include -#include #include +#include #include // Some of the logic here has been cribbed from