Skip to content

Remove destructor logging #424

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 2 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions src/viam/sdk/log/logging.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -150,6 +150,8 @@ BOOST_LOG_ATTRIBUTE_KEYWORD_TYPE(attr_time,
/// @ingroup Log
///
/// Use this macro to generate log messages pertaining to the SDK at large.
/// @warning Using this macro outside of the lifetime of LogManager is UB and for this reason
/// logging in destructors should be done with caution or avoided entirely.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, if the rule is that an Instance must outlive ModuleService or RobotClient, how can this situation arise?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just encountered this when trying to run example_dial_api_key to do direct dialing, which was failing locally for me. After failing to list the resources, thread::join in close was throwing a resource_deadlock_would_occur (i.e., attempted to join current thread) and then logging that exception in ~RobotClient was causing a null pointer deref in Boost.Log, at which point a print statement confirmed that instance had been destructed before the dtor was called.

Now as for how this happens I'm not so sure honestly. I would expect C++ objects to be destroyed in the reverse order that they're created, which means Instance should be first in last out, but it seemed like that's not what was happening

#define VIAM_SDK_LOG(level) VIAM_SDK_LOG_IMPL(::viam::sdk::LogManager::get().global_logger(), level)

/// @brief Log macro for resource-level logs.
Expand All @@ -158,6 +160,8 @@ BOOST_LOG_ATTRIBUTE_KEYWORD_TYPE(attr_time,
/// This macro can only be called from the definition of a member function of a class inheriting
/// @ref Resource. It will log messages to the log source of that specific resource, allowing
/// resource-level log filtering.
/// @warning Using this macro outside of the lifetime of LogManager is UB and for this reason
/// logging in destructors should be done with caution or avoided entirely.
#define VIAM_RESOURCE_LOG(level) VIAM_SDK_LOG_IMPL(this->logger_, level)

} // namespace sdk
Expand Down
5 changes: 2 additions & 3 deletions src/viam/sdk/module/service.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -254,15 +254,14 @@ ModuleService::ModuleService(int argc,
}

ModuleService::~ModuleService() {
// TODO(RSDK-5509): Run registered cleanup functions here.
VIAM_SDK_LOG(info) << "Shutting down gracefully.";
std::cout << "Shutting down gracefully.\n";
server_->shutdown();

if (parent_) {
try {
parent_->close();
} catch (const std::exception& exc) {
VIAM_SDK_LOG(error) << exc.what();
std::cerr << exc.what();
}
}
}
Expand Down
4 changes: 2 additions & 2 deletions src/viam/sdk/robot/client.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -120,9 +120,9 @@ RobotClient::~RobotClient() {
try {
this->close();
} catch (const std::exception& e) {
VIAM_SDK_LOG(error) << "Received err while closing RobotClient: " << e.what();
std::cerr << "Received err while closing RobotClient: " << e.what() << "\n";
} catch (...) {
VIAM_SDK_LOG(error) << "Received unknown err while closing RobotClient";
std::cerr << "Received unknown err while closing RobotClient\n";
}
}
}
Expand Down