RSDK-5986: Resource-level logging for the C++ SDK #383

lia-viam · 2025-03-14T16:18:30Z

This PR introduces resource-level logging to the C++ SDK. Building off the work in #374, the Instance class now initializes the logging machinery and handles bookkeeping for resource-level logging.

We are still using Boost.Log for the logging but there is a pretty significant overhaul which makes use of some more advanced features of the library. The distinction between Boost.Log's concept of source and sink is helpful. There is a single logging source in the SDK, namely the source of message generated by user code (or the SDK) using the VIAM_LOG or VIAM_RESOURCE_LOG macros. Precisely one of two sinks may be active.

Console logging, initialized by default on application startup
RDK logging via RobotClient.
Starting up a ModuleService will automatically switch from 1. to 2.

Currently there is a lot of header/ABI leakage of Boost.Log components. Unfortunately this may be nontrivial to work around, given that Boost.Log uses ostream-style streaming of log messages, but I do think it is doable. That said, we currently have other Boost components in headers/APIs, so I think this is lower priority for now.

Possible bikeshed: the class currently called Logger might more accurately be called something like LogManager, given that it manages the SDK's log source and handles setup of the logging core and the console sink.

The unit tests now feature tests of console logging at the SDK level and the resource level, with tests of global filtering and resource-level filtering as well. Note that these are only console logging tests, but reviewers please advise if it may be possible to connect a RobotClient to MockRobot or similar in the tests, and override the gRPC Log method so we can inspect logs getting sent via the non-console log sink.

On recommendation from @stuqdog here are some sample log outputs:

Client-side logging, general SDK:

2025--03--17 14:27:57: [Viam C++ SDK] <info> [tests/test_log.cpp:35] info1
2025--03--17 14:27:57: [Viam C++ SDK] <error> [tests/test_log.cpp:36] error1
2025--03--17 14:27:57: [Viam C++ SDK] <trace> [tests/test_log.cpp:45] trace2

Client-side, resource-level:

2025--03--17 14:27:57: [DefaultSensor] <info> [tests/test_log.cpp:76] sensor info
2025--03--17 14:27:57: [DefaultSensor] <error> [tests/test_log.cpp:77] sensor error
2025--03--17 14:27:57: [ErrorSensor] <error> [tests/test_log.cpp:77] sensor error

Sample RDK output:

2025-03-17T18:42:21.057Z	INFO	rdk.modmanager.my-module.my-module.StdOut	pexec/managed_process.go:294	
\_ 2025--03--17 14:42:21: [Viam C++ SDK] <info> [log/logger.cpp:134] Initialized console logging
2025-03-17T18:42:21.059Z	INFO	rdk.modmanager.my-module.my-module.StdOut	pexec/managed_process.go:294	
\_ 2025--03--17 14:42:21: [Viam C++ SDK] <info> [module/service.cpp:275] Module listening on /var/folders/ <snip>

...

2025-03-17T18:42:21.071Z	INFO	rdk.modmanager.my-module.my-module.StdOut	pexec/managed_process.go:294	
\_ 2025--03--17 14:42:21: [Viam C++ SDK] <info> [log/logger.cpp:138] Disabling console logging

...

2025-03-17T18:42:21.073Z	INFO	mysensor	######### CONFIGURING MY SENSOR ########	{"log_ts":"2025-03-17T14:42:21.073Z"}

…stry-member

Co-authored-by: Ethan <[email protected]>

stuqdog

Nice, thanks so much for putting this together! I have some minor general comments but overall super happy with how this looks.

stuqdog · 2025-03-17T15:06:52Z

src/viam/sdk/log/logger.cpp

+void Logger::set_global_log_level(int argc, char** argv) {
+    if (argc >= 3 && strcmp(argv[2], "--log-level=debug") == 0) {
+        set_global_log_level(log_level::debug);
+    }
+}


Almost certainly out of scope for this PR (and probably questionable to do at all, given the occurrence of this pattern in RDK as well), but looking at this now makes me pretty sad. This is really brittle and I just imagine having to explain to someone that --log-level=error does nothing and also --log-level debug does nothing but --log-level=debug does do something and it's just, sigh.

I dunno if it's even worth filing a ticket for this, it's a pretty specific case and people will likely be starting things with the --debug flag on viam-server if they're trying to set debug at all. But. Had to get this out there.

this bugs me too...definitely fixable if there's will to do so, would probably just involve making boost program_options a first order SDK depedency and parsing the flag into level_from_string

Probably out of scope here, maybe we just file a ticket so the thought isn't totally lost forever?

stuqdog · 2025-03-17T15:11:32Z

src/viam/sdk/config/resource.cpp

@@ -154,7 +161,8 @@ ResourceConfig from_proto_impl<app::v1::ComponentConfig>::operator()(
                          from_proto(proto->attributes()),
                          proto->api(),
                          Model::from_str(proto->model()),
-                          proto->has_frame() ? from_proto(proto->frame()) : LinkConfig{});
+                          proto->has_frame() ? from_proto(proto->frame()) : LinkConfig{},
+                          level_from_string(proto->log_configuration().level()));


(minor) maybe a little paranoid, but proto exposes a has_log_configuration() method which makes me worry that there might be cases where this isn't set, or where that could become the case going forward. Might be better to use the ternary like in the frame setting, and default to info

edit: I see you updated here already, disregard!

Actually ended up fixing this due to your suggestion to paste some sample logs because I saw an error that kept firing! But it's helpful to know about has_log_configuration, I will use that

src/viam/sdk/log/logger.hpp

stuqdog · 2025-03-17T18:17:32Z

src/viam/sdk/log/logger.hpp

+#include <boost/log/attributes/clock.hpp>
+#include <boost/log/expressions/keyword.hpp>
+#include <boost/log/sinks/sync_frontend.hpp>
+#include <boost/log/sinks/text_ostream_backend.hpp>
+#include <boost/log/sources/severity_channel_logger.hpp>
+#include <boost/log/utility/manipulators/add_value.hpp>


I definitely understand that the architecture we have largely locks us into boost, but I'm curious how (if at all) this PR affects invocations of the standard BOOST_LOG/BOOST_LOG_TRIVIAL macros? If those would see changes in formatting then we should probably at a minimum be kinda loud about that fact in a README or docstrings or something

In theory BOOST_LOG would still work but the user would have to manually attach a log_level attribute to it or the messages would never pass filtering. BOOST_LOG_TRIVIAL should be avoided entirely.

I think we probably want to tell people (knowing full well some will ignore us) not to use the boost macros at all and not to rely on any implementation of the logger which yes probably good to document.

src/viam/sdk/log/logger.cpp

stuqdog · 2025-03-17T20:07:45Z

src/viam/sdk/log/logger.cpp

+boost::string_view trim_filename(const char* file) {
+    boost::string_view result(file);
+    const std::size_t second_last = result  //
+                                        .substr(0, result.find_last_of('/'))
+                                        .find_last_of('/');
+
+    if (second_last != boost::string_view::npos) {
+        return result.substr(second_last + 1, result.size() - second_last);
+    }
+
+    return result;
+}


Can we unit test this?

stuqdog · 2025-03-17T20:13:56Z

src/viam/sdk/log/private/log_backend.cpp

+time_pt ptime_convert(const boost::posix_time::ptime& from) {
+    namespace posix_time = boost::posix_time;
+
+    posix_time::time_duration const time_since_epoch = from - posix_time::from_time_t(0);
+    const time_pt t = std::chrono::system_clock::from_time_t(time_since_epoch.total_seconds());
+    const long nsec = time_since_epoch.fractional_seconds() *
+                      (1000000000 / posix_time::time_duration::ticks_per_second());
+    return t + std::chrono::nanoseconds(nsec);
+}


(minor) This is hard for me to have any confidence in the correctness of. It also looks like a helper function that isn't doing anything that needs to be private. Can we move this to somewhere more public and unit test it?

oh right I meant to add an explanatory comment but this is copy-pasted from a stack overflow answer

src/viam/sdk/module/service.cpp

stuqdog · 2025-03-17T20:28:35Z

src/viam/sdk/robot/client.cpp

+    robot::v1::LogResponse resp;
+    ClientContext ctx;
+    const auto response = impl_->stub_->Log(ctx, req, &resp);
+    (void)response;


(q) just for my own curiosity, what is this doing? I've not seen this syntax before.

oh wait hmm this might have been placeholder code that I wanted to revisit to have something like this:
https://github.com/viamrobotics/viam-cpp-sdk/pull/312/files#diff-adfc91deaac9ff292c555bb21738544cfcc72ab2c228d7815172054db653f1caR194

I guess the question is if we should just be ignoring errors here? Or logging to console? Doable but kind of annoying

as to your question though, this is a C-style cast to void which will silence unused variable errors

Hmm... I think ideally we'd want to log an error. But it's definitely awkward given that the error would be a "we failed to log" error...

I'd say if it's not too hard to log to console, let's do that. If it's annoying then we could probably just cerr a message (it'll get picked up by the module and logged to RDK, just in bad formatting), with explanatory comment as to why cerr.

this is handled as of a recent commit. the approach is similar to this answer from the author of boost.log https://stackoverflow.com/a/67181442

disable_console_logging now installs a reject-all filter on console_sink_, unless a force override flag is passed. added some explanatory comments, but for now this is an implementation detail. I could see users maybe wanting an option to fall back to console logging, but I think the macro naming and usage might get nasty

src/viam/sdk/tests/test_utils.hpp

benjirewis

Looks awesome! Any plans on adding to the simple or complex module examples to show how to use the new VIAM_LOG?

benjirewis · 2025-03-19T15:03:52Z

src/viam/sdk/robot/client.cpp

+    const auto response = impl_->stub_->Log(ctx, req, &resp);
+    if (is_error_response(response)) {
+        // Manually override to force this to get logged to console so we don't set off an infinite
+        // loop


A classic; had to do something like this in go, too, I think.

lia-viam · 2025-03-19T17:14:40Z

Per @benjirewis suggestion just added some logging to the simple and complex module examples, although now I'm wondering if I should just replace all the use of cout and cerr in the examples directory with logging? cc @stuqdog

acmorrow

I was interested so had a quick look through. Just some high level thoughts and comments. No need to wait on me to move forward with this.

acmorrow · 2025-03-20T13:45:03Z

src/viam/sdk/log/logging.hpp

+#include <boost/log/attributes/clock.hpp>
+#include <boost/log/expressions/keyword.hpp>
+#include <boost/log/sinks/sync_frontend.hpp>
+#include <boost/log/sinks/text_ostream_backend.hpp>
+#include <boost/log/sources/severity_channel_logger.hpp>
+#include <boost/log/utility/manipulators/add_value.hpp>
+#include <boost/utility/string_view.hpp>


Does the long term plan still include going boost free in the API? Should there be a level of indirection about what logging backend is in use?

Yes definitely. The situation with Boost.Log's stream operator-based approach makes this difficult but I suspect it is still doable.

which is to say hopefully in a subsequent boost-insulating PR

acmorrow · 2025-03-20T13:54:07Z

src/viam/sdk/log/logging.hpp

+#define VIAM_LOG_IMPL(lg, level)                                                     \
+    BOOST_LOG_SEV((lg), ::viam::sdk::log_level::level)                               \
+        << ::boost::log::add_value(::viam::sdk::attr_file_type{},                    \
+                                   ::viam::sdk::log_detail::trim_filename(__FILE__)) \
+        << ::boost::log::add_value(::viam::sdk::attr_line_type{}, __LINE__)
+
+/// @brief Log macro for general SDK logs.
+/// @ingroup Log
+///
+/// Use this macro to generate log messages pertaining to the SDK at large.
+#define VIAM_LOG(level) VIAM_LOG_IMPL(::viam::sdk::LogManager::get().global_logger(), level)
+
+/// @brief Log macro for resource-level logs.
+/// @ingroup Log
+///
+/// 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.
+#define VIAM_RESOURCE_LOG(level) VIAM_LOG_IMPL(this->logger_, level)


Do these macros form part of the library API? Or, if we had the machinery (prelude/postlude headers with push/pop, etc.) would they not be visible to consumers of the library? I think they probably are intended for user consumption (the former case), for instance in the case of writing a module.

I wonder then if they should be in a dedicated header, logging_macros.hpp or similar, so that the Viam C++ SDK can prevent them from leaking into client code by way of its own usage of the logging macros in headers, but consumers can opt in to visibility by consuming the header directly.

I would say they are part of the API yes. Pursuant to eventually insulating Boost entirely (touching on another of your comments) I'm inclined to present the macros to users as a black box and not have them call any Boost.Log functions on their own.

I'm aware of other logging libraries that are more amenable to non-macro use but unfortunately the operator<< approach of this one makes it fairly unusable for practical purposes without a logging macro.

acmorrow · 2025-03-20T13:55:23Z

src/viam/sdk/log/logging.hpp

+
+}  // namespace log_detail
+
+BOOST_LOG_ATTRIBUTE_KEYWORD_TYPE(attr_channel, "Channel", std::string);


I have some worries about what the implications are for when we want to do symbol visibility.

This was bugging me a bit as well. There is a slight subtlety that BOOST_LOG_ATTRIBUTE_KEYWORD_TYPE just defines something like struct attr_channel_type whereas BOOST_LOG_ATTRIBUTE_KEYWORD defines struct attr_channel_type as well as const attr_channel_type attr_channel. We are using the former--is that still an issue?

In any case I'm going to hack away and see if I can't figure out a way to hide those because I don't like exposing them in a header either.

acmorrow · 2025-03-20T13:57:06Z

src/viam/sdk/log/logging.hpp

+                                 "TimeStamp",
+                                 boost::log::attributes::local_clock::value_type);
+
+#define VIAM_LOG_IMPL(lg, level)                                                     \


Maybe VIAM_SDK_LOG... to keep it VIAM_SDK as the macro prefix and viam::sdk as the namespace prefix.

acmorrow · 2025-03-20T13:59:10Z

src/viam/sdk/log/logging.hpp

+/// @brief Severity levels for the logger.
+/// @ingroup Log
+enum class log_level : std::int8_t {
+    trace = -2,


I think elsewhere for enum constants we do k_x:

viam-cpp-sdk/src/viam/sdk/services/mlmodel.hpp

Line 125 in 1cdb1e9

k_int8 = 0,

That's true although I wonder about this from a usability perspective, it feels weird for users to have to type VIAM_LOG(k_warn) rather than VIAM_LOG(warn) ... maybe this should be an exception to the rule? I've seen other libraries do macros-per-severity (eg VIAM_LOG_INFO) but this starts to get combinatorial since we already have the general- and resource-flavored log macros

I'm willing for it to be an exception. Maybe throw a comment on there indicating that it is.

lia-viam and others added 30 commits February 18, 2025 11:02

initial commit of instance object

31437c3

wip: initial commit to get sdk building with instance

932ebaa

add missing implementation

04d0158

update examples to use instance

a105cef

only instance can construct registry

403f316

make tests work with registry member approach

27eeb13

pimpl registry and update examples

ce2aa8c

add instance management infra

e5cf6d0

Merge branch 'main' of github.com:viamrobotics/viam-cpp-sdk into regi…

85194da

…stry-member

update tflite module

5024d3a

silence spurious const warning

ef8ec8e

make method static

16113fd

Merge branch 'main' of github.com:viamrobotics/viam-cpp-sdk into regi…

216e5e2

…stry-member

update cml boost links

dbf1647

add logger to resource

d1dffb8

use static current to populate registry member

4771390

revert and adapt examples

18d26c9

make instance more of a black box

6018323

Merge branch 'registry-member' into logger

d4aeb86

add impl instance to git

5535616

Merge branch 'registry-member' into logger

4d2582c

Add instance comment boilerplate

eeac195

Co-authored-by: Ethan <[email protected]>

Add instance comment boilerplate

7560f6d

Co-authored-by: Ethan <[email protected]>

connect robot client logging when parent of module service

af08403

remove old ctor arg

4e25d35

prohibit multi instance

55baa6c

remove initialized flag

10cd711

meyers singleton registry

c745422

remove registry member and fix member spacing/ordering

75ab450

remove unused include

fc21c35

lia-viam added 3 commits March 17, 2025 14:47

Merge branch 'main' of github.com:viamrobotics/viam-cpp-sdk into logger

6755cd6

linter warnings...........

8c372cc

linter.....

1744939

stuqdog requested changes Mar 17, 2025

View reviewed changes

lia-viam added 11 commits March 17, 2025 17:11

add log_setup

d7842c1

remove sdk::

9829e44

global resource is const char*

e10df01

log log as debug

192b29f

fix out of date comment

2de9f40

rename to log manager and global logger

d681f6f

rename files to logging

3b8d7dc

use has_log_configuration

82eb403

unit test trim filename

ad079c8

handle fallback console logging for grpc log failures

6b83aed

Merge branch 'main' of github.com:viamrobotics/viam-cpp-sdk into logger

f9f39a1

benjirewis reviewed Mar 19, 2025

View reviewed changes

lia-viam added 3 commits March 19, 2025 13:07

add logging to simple module example

4eb8643

add logging to complex module example

418f882

Merge branch 'main' of github.com:viamrobotics/viam-cpp-sdk into logger

ee85b28

acmorrow reviewed Mar 20, 2025

View reviewed changes

lia-viam added 9 commits March 20, 2025 11:48

use VIAM_SDK macro prefix

40b5400

disable fail-fast

22d29e3

Merge branch 'main' of github.com:viamrobotics/viam-cpp-sdk into logger

ba154d1

link boost log and log_setup in public libs

2e9d015

set boost log dyn link in test script

b8dcf7c

clean up example camera and use logging instead of cout

f6c21ff

update example code to use logging

ac25b4e

add test and use set_global_resource_name

04c92ce

silence const warnings

9297062

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

RSDK-5986: Resource-level logging for the C++ SDK #383

RSDK-5986: Resource-level logging for the C++ SDK #383

lia-viam commented Mar 14, 2025 •

edited

Loading

stuqdog left a comment

stuqdog Mar 17, 2025

lia-viam Mar 17, 2025

stuqdog Mar 18, 2025

stuqdog Mar 17, 2025

lia-viam Mar 18, 2025

stuqdog Mar 17, 2025

lia-viam Mar 17, 2025

stuqdog Mar 17, 2025

stuqdog Mar 17, 2025

lia-viam Mar 17, 2025

stuqdog Mar 17, 2025

lia-viam Mar 17, 2025

lia-viam Mar 17, 2025

stuqdog Mar 18, 2025

lia-viam Mar 18, 2025

benjirewis left a comment

benjirewis Mar 19, 2025

lia-viam commented Mar 19, 2025

acmorrow left a comment

acmorrow Mar 20, 2025

lia-viam Mar 20, 2025

lia-viam Mar 20, 2025

acmorrow Mar 20, 2025

lia-viam Mar 20, 2025

acmorrow Mar 20, 2025

lia-viam Mar 20, 2025

acmorrow Mar 20, 2025

acmorrow Mar 20, 2025

lia-viam Mar 20, 2025

acmorrow Mar 20, 2025


		} // namespace log_detail

		BOOST_LOG_ATTRIBUTE_KEYWORD_TYPE(attr_channel, "Channel", std::string);

RSDK-5986: Resource-level logging for the C++ SDK #383

Are you sure you want to change the base?

RSDK-5986: Resource-level logging for the C++ SDK #383

Conversation

lia-viam commented Mar 14, 2025 • edited Loading

stuqdog left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benjirewis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lia-viam commented Mar 19, 2025

acmorrow left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lia-viam commented Mar 14, 2025 •

edited

Loading