cleanup, minimize abort trap

src/viam/sdk/common/logger.cpp

@@ -91,14 +91,14 @@ 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
     logging::add_console_log(strm,
                              boost::parameter::keyword<keywords::tag::format>::get() =
                                  (expr::stream << '[' << expr::attr<std::string>("File") << ':'
                                                << expr::attr<int>("Line") << "]    "));
-    logging::add_common_attributes();
 }
 
 void init_logging() {
@@ -107,16 +107,17 @@ void init_logging() {
         return;
     }
     inited = true;
+    logging::add_common_attributes();
 
     logging::add_console_log(
         std::clog,
         boost::parameter::keyword<keywords::tag::format>::get() =
             (expr::stream << expr::format_date_time<boost::posix_time::ptime>(
                                  "TimeStamp", "%Y-%m-%d_%H:%M:%S.%f")
-                          << ": <" << boost::log::trivial::severity << "> " << '['
+                          << ": [" << boost::log::trivial::severity << "] "
+                          << expr::attr<std::string>("LoggerName") << " ["
                           << expr::attr<std::string>("File") << ':' << expr::attr<int>("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,16 +184,20 @@ 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.
     init_logging();
 
     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;
 }
 

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_;

src/viam/sdk/common/utils.cpp

@@ -6,9 +6,6 @@
 #include <vector>
 
 #include <boost/blank.hpp>
-#include <boost/log/core.hpp>
-#include <boost/log/expressions.hpp>
-#include <boost/log/trivial.hpp>
 #include <boost/optional/optional.hpp>
 #include <grpcpp/client_context.h>
 
@@ -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;
 }

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.

src/viam/sdk/module/service.cpp

@@ -1,7 +1,7 @@
 #include <viam/sdk/module/service.hpp>
 
-#include <exception>
 #include <chrono>
+#include <exception>
 #include <memory>
 #include <sstream>
 #include <string>
@@ -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<text_sink>(backend);
     }
 
+    ~impl() {
+        logging::core::get()->remove_sink(sink);
+    }
     custom_logging_buf buf;
-    boost::shared_ptr<text_sink> sink;
     boost::shared_ptr<std::ostream> stream;
+    boost::shared_ptr<text_sink> sink;
 };
 
 void ModuleService::init_logging_() {
@@ -322,9 +325,9 @@ void ModuleService::init_logging_() {
 }
 
 ModuleService::ModuleService(std::string addr)
-    : module_(std::make_unique<Module>(std::move(addr))),
-      server_(std::make_unique<Server>()),
-      logger_(std::make_unique<Logger>("viam-cpp-module-service")) {}
+    : logger_(std::make_unique<Logger>("viam-cpp-module-service")),
+      module_(std::make_unique<Module>(std::move(addr))),
+      server_(std::make_unique<Server>()) {}
 
 ModuleService::ModuleService(int argc,
                              char** argv,
@@ -336,7 +339,6 @@ ModuleService::ModuleService(int argc,
     module_ = std::make_unique<Module>(argv[1]);
     server_ = std::make_unique<Server>();
     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,

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<Resource> get_parent_resource_(const Name& name);
 
+    std::unique_ptr<Logger> logger_;
     std::mutex lock_;
-    std::unique_ptr<Module> module_;
-    std::shared_ptr<RobotClient> parent_;
     struct impl;
+    std::shared_ptr<RobotClient> parent_;
     std::unique_ptr<impl> impl_;
+    std::unique_ptr<Module> module_;
     std::string parent_addr_;
     std::unique_ptr<Server> server_;
     SignalManager signal_manager_;
-    std::unique_ptr<Logger> logger_;
 };
 
 }  // namespace sdk

src/viam/sdk/robot/client.cpp

@@ -160,11 +160,10 @@ RobotClient::~RobotClient() {
 
 void RobotClient::close() {
     should_refresh_.store(false);
-    for (const std::shared_ptr<std::thread>& t : threads_) {
+    for (const auto& t : threads_) {
         t->~thread();
     }
     stop_all();
-    viam_channel_->close();
 }
 
 bool is_error_response(const grpc::Status& response) {

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_;
 }

src/viam/sdk/rpc/dial.hpp

@@ -17,6 +17,8 @@ class ViamChannel {
     static std::shared_ptr<ViamChannel> dial(const char* uri,
                                              const boost::optional<DialOptions>& options);
 
+    ~ViamChannel();
+
     const std::shared_ptr<grpc::Channel>& channel() const;
 
    private: