Skip to content
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

Add Logger class and give one to nodes #411

Merged
merged 25 commits into from
Dec 5, 2017
Merged

Add Logger class and give one to nodes #411

merged 25 commits into from
Dec 5, 2017

Conversation

dhood
Copy link
Member

@dhood dhood commented Nov 30, 2017

This code change is one step in the higher-level Logging feature, see: ros2/ros2#425 for others

This adds a Logger class, the node->get_logger() method, and the rclcpp::get_logger(name) free function for non-node loggers.

Logging macros must now have a logger object passed as the first argument (instead of a name as previously accepted). I added

/// Helper function to give useful compiler errors in logging macros.
to give something more useful than a wall of macro errors if users try to pass a string: open to other implementation suggestions.

The Logger class is based off a rough implementation initially by @wjwwood. The node's logger is implemented as an interface on @Karsten1987's suggestion to support the use case of composing a lightweight Node that does not include or "pay for" the logger interface. Additionally, even if using the logger interface, logging functionality can be minimised with the preprocessor directive RCLCPP_LOGGING_ENABLED set to false.

Todo before merge:

Other todos listed in the code are planned as follow-up PRs.

ci windows Build Status

@dhood dhood added the in progress Actively being worked on (Kanban column) label Nov 30, 2017
@dhood dhood self-assigned this Nov 30, 2017
* \return a dummy logger if logging is disabled.
*/
RCLCPP_PUBLIC
Logger get_logger(const std::string & name);
Copy link
Contributor

Choose a reason for hiding this comment

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

Did you make up your mind whether you want to put that as a static member function? As discussed this would prevent you from friend/forward declaring it. However, I remember you mentioned it may be problematic for future developments.

Copy link
Member Author

Choose a reason for hiding this comment

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

yeah, the usability was what I had in mind: I wanted it to be just rclcpp::get_logger. After we spoke I did try making it a static function but in the end I wasn't able to promote just that one method to the rclcpp namespace like I thought I could. So for usability I left it as a free function

* disabled).
*/
RCLCPP_PUBLIC
const char * get_name() const
Copy link
Contributor

Choose a reason for hiding this comment

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

style nitpick: new line between return type and function name

@@ -0,0 +1,61 @@
// Copyright 2016 Open Source Robotics Foundation, Inc.
Copy link
Contributor

Choose a reason for hiding this comment

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

year

class NodeLogger;
}

namespace logger
Copy link
Contributor

Choose a reason for hiding this comment

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

given the discussion #410 (comment) you may want to remove the namespace logger.

Copy link
Member Author

Choose a reason for hiding this comment

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

yeah that's what I had listed above as a todo 👍

Copy link
Contributor

@Karsten1987 Karsten1987 Nov 30, 2017

Choose a reason for hiding this comment

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

sorry, my fault. Only quickly looked over the code :)

Copy link
Member Author

Choose a reason for hiding this comment

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

nw, at least we had the same point ;)

@@ -0,0 +1,205 @@
// Copyright 2015 Open Source Robotics Foundation, Inc.
Copy link
Member Author

Choose a reason for hiding this comment

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

Note to reviewers: I wanted to add and use a TestLifecycleNode test fixture. I moved the default_state_machine tests to another file because having two different test fixtures in one file was causing rclcpp::init to be called twice.

Copy link
Contributor

Choose a reason for hiding this comment

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

do you mind changing this year here as well?

Copy link
Member Author

Choose a reason for hiding this comment

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

mmm this file was just renamed... I didn't think we updated copyright in that situation (but I'm not 100% sure about these things)

Copy link
Contributor

Choose a reason for hiding this comment

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

It was my initial fault. It just have been 2016 in the first place :/

Copy link
Member Author

Choose a reason for hiding this comment

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

I removed the test changes completely, it was bloating the diff unnecessarily

@dhood
Copy link
Member Author

dhood commented Nov 30, 2017

This is good to review now.

The usage of rclcpp logging macros has been updated in ros2/demos#200, including usage for lifecycle nodes which also have a logger since a9c0ef7

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

@dhood dhood mentioned this pull request Nov 30, 2017
14 tasks
@dhood dhood added in review Waiting for review (Kanban column) and removed in progress Actively being worked on (Kanban column) labels Dec 1, 2017
@dhood
Copy link
Member Author

dhood commented Dec 1, 2017

This is an example error with gcc if you try to pass a string instead of a logger to a macro. Still not great user experience but the top and bottom lines mention the Logger class at least.

In file included from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:21:0,
                 from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/rclcpp.hpp:142,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/include/logging_demo/logger_usage_component.hpp:21,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:15:
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp: In member function ‘void logging_demo::LoggerUsage::on_timer()’:
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:28: error: invalid initialization of reference of type ‘const rclcpp::Logger&’ from expression of type ‘const char*’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
                            ^
/home/dhood/ros2_ws/install_isolated/rcutils/include/rcutils/logging_macros.h:67:47: note: in definition of macro ‘RCUTILS_LOG_COND_NAMED’
     if (rcutils_logging_logger_is_enabled_for(name, severity)) { \
                                               ^
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:186:3: note: in expansion of macro ‘RCUTILS_LOG_INFO_ONCE_NAMED’
   RCUTILS_LOG_INFO_ONCE_NAMED( \
   ^
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:3: note: in expansion of macro ‘RCLCPP_INFO_ONCE’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
   ^
In file included from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/rclcpp.hpp:142:0,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/include/logging_demo/logger_usage_component.hpp:21,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:15:
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:58:21: note: in passing argument 1 of ‘const char* rclcpp::logging_macro_utilities::_get_logger_name(const rclcpp::Logger&)’
 inline const char * _get_logger_name(const rclcpp::Logger & logger)
                     ^
In file included from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:21:0,
                 from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/rclcpp.hpp:142,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/include/logging_demo/logger_usage_component.hpp:21,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:15:
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:28: error: invalid initialization of reference of type ‘const rclcpp::Logger&’ from expression of type ‘const char*’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
                            ^
/home/dhood/ros2_ws/install_isolated/rcutils/include/rcutils/logging_macros.h:69:58: note: in definition of macro ‘RCUTILS_LOG_COND_NAMED’
       rcutils_log(&__rcutils_logging_location, severity, name, __VA_ARGS__); \
                                                          ^
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:186:3: note: in expansion of macro ‘RCUTILS_LOG_INFO_ONCE_NAMED’
   RCUTILS_LOG_INFO_ONCE_NAMED( \
   ^
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:3: note: in expansion of macro ‘RCLCPP_INFO_ONCE’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
   ^
In file included from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/rclcpp.hpp:142:0,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/include/logging_demo/logger_usage_component.hpp:21,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:15:
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:58:21: note: in passing argument 1 of ‘const char* rclcpp::logging_macro_utilities::_get_logger_name(const rclcpp::Logger&)’
 inline const char * _get_logger_name(const rclcpp::Logger & logger)
CMakeFiles/logger_usage_component.dir/build.make:62: recipe for target 'CMakeFiles/logger_usage_component.dir/src/logger_usage_component.cpp.o' failed

@wjwwood
Copy link
Member

wjwwood commented Dec 1, 2017

@dhood you could use a static_assert in the macro to make a better message, something like:

  static_assert(std::is_same<decltype(logger), Logger>::value, "Must use Logger class"); \

See: https://stackoverflow.com/a/4029310

@dhood
Copy link
Member Author

dhood commented Dec 1, 2017

Gah, that was the first thing I tried but I gave up on it and figured it could only be used with standard types... actually the problem was whitespace in my macros..!! I shouldn't have given up so quickly.

Here's the error output with a519b72

In file included from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/rclcpp.hpp:142:0,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/include/logging_demo/logger_usage_component.hpp:21,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:15:
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp: In member function ‘void logging_demo::LoggerUsage::on_timer()’:
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:168:3: error: static assertion failed: First argument to logging macros must be an rclcpp::Logger
   static_assert(std::is_same<decltype(logger), rclcpp::Logger>::value, "First argument to logging macros must be an rclcpp::Logger"); \
   ^
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:3: note: in expansion of macro ‘RCLCPP_INFO_ONCE’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
   ^
In file included from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:23:0,
                 from /home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/rclcpp.hpp:142,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/include/logging_demo/logger_usage_component.hpp:21,
                 from /home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:15:
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:170:12: error: request for member ‘get_name’ in ‘((logging_demo::LoggerUsage*)this)->logging_demo::LoggerUsage::<anonymous>.rclcpp::node::Node::get_name()’, which is of non-class type ‘const char*’
     logger.get_name(), \
            ^
/home/dhood/ros2_ws/install_isolated/rcutils/include/rcutils/logging_macros.h:67:47: note: in definition of macro ‘RCUTILS_LOG_COND_NAMED’
     if (rcutils_logging_logger_is_enabled_for(name, severity)) { \
                                               ^
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:169:3: note: in expansion of macro ‘RCUTILS_LOG_INFO_ONCE_NAMED’
   RCUTILS_LOG_INFO_ONCE_NAMED( \
   ^
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:3: note: in expansion of macro ‘RCLCPP_INFO_ONCE’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
   ^
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:170:12: error: request for member ‘get_name’ in ‘((logging_demo::LoggerUsage*)this)->logging_demo::LoggerUsage::<anonymous>.rclcpp::node::Node::get_name()’, which is of non-class type ‘const char*’
     logger.get_name(), \
            ^
/home/dhood/ros2_ws/install_isolated/rcutils/include/rcutils/logging_macros.h:69:58: note: in definition of macro ‘RCUTILS_LOG_COND_NAMED’
       rcutils_log(&__rcutils_logging_location, severity, name, __VA_ARGS__); \
                                                          ^
/home/dhood/ros2_ws/install_isolated/rclcpp/include/rclcpp/logging.hpp:169:3: note: in expansion of macro ‘RCUTILS_LOG_INFO_ONCE_NAMED’
   RCUTILS_LOG_INFO_ONCE_NAMED( \
   ^
/home/dhood/ros2_ws/src/ros2/demos/logging_demo/src/logger_usage_component.cpp:50:3: note: in expansion of macro ‘RCLCPP_INFO_ONCE’
   RCLCPP_INFO_ONCE(get_name(), "Timer callback called (this will only log once)")
   ^
CMakeFiles/logger_usage_component.dir/build.make:62: recipe for target 'CMakeFiles/logger_usage_component.dir/src/logger_usage_component.cpp.o' failed

*/
RCLCPP_PUBLIC
Logger
get_logger(const std::string & name);
Copy link
Member Author

Choose a reason for hiding this comment

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

do we think this should return a shared ptr as log4cxx does or leave it up to callers to call make_shared or similar?

Copy link
Contributor

Choose a reason for hiding this comment

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

In our discussion it sounded like it might make sense to return a shared_ptr here. In particular this would allow us to implement the actual Logger with a specialized subclass that potentially overrides the get_name or other capabilities and keeps a weak backlink to the node and can output a warning if node goes out of scope and the backlink is broken. And although the current logger is trivially copyable right now we wouldn't need to keep it that way looking forward if we return the pointer instead of an instance.

Copy link
Member

Choose a reason for hiding this comment

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

We talked about this off-line (@dhood and I) and I pointed out that if we want to do what you describe @tfoote we don't have swap the return type to a shared pointer, instead we could have the Logger class store a shared pointer and forward all methods calls to the shared pointer. Basically we could accomplish the same thing without inheritance.

That being said, if @dhood wanted to switch this to a pointer, that's fine by me too.

Also, if we really want to return a shared pointer we can do that in the future with an API break.

Copy link
Contributor

@tfoote tfoote left a comment

Choose a reason for hiding this comment

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

Generally it lgtm, however I do think the shared ptr interface might make more sense for passing the logger to the user.

*/
RCLCPP_PUBLIC
Logger
get_logger(const std::string & name);
Copy link
Contributor

Choose a reason for hiding this comment

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

In our discussion it sounded like it might make sense to return a shared_ptr here. In particular this would allow us to implement the actual Logger with a specialized subclass that potentially overrides the get_name or other capabilities and keeps a weak backlink to the node and can output a warning if node goes out of scope and the backlink is broken. And although the current logger is trivially copyable right now we wouldn't need to keep it that way looking forward if we return the pointer instead of an instance.

@dhood dhood added in progress Actively being worked on (Kanban column) and removed in review Waiting for review (Kanban column) labels Dec 4, 2017
@dhood
Copy link
Member Author

dhood commented Dec 4, 2017

@ros2/team This is good to review if anyone has time; at the moment this is targeted for release but if it is off-base and doesn't make it in nothing breaks. The usage updates are in ros2/demos#200

As @tfoote mentioned in https://github.com/ros2/rclcpp/pull/411/files#r154480879 there may be changes to how the logger is stored/accessed by the Node class, but we can do them at a later date.

@dhood dhood added in review Waiting for review (Kanban column) and removed in progress Actively being worked on (Kanban column) labels Dec 4, 2017
Copy link
Member

@wjwwood wjwwood left a comment

Choose a reason for hiding this comment

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

I had some comments, but overall I think it's an improvement to merge as-is too.

*/
RCLCPP_PUBLIC
Logger
get_logger(const std::string & name);
Copy link
Member

Choose a reason for hiding this comment

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

We talked about this off-line (@dhood and I) and I pointed out that if we want to do what you describe @tfoote we don't have swap the return type to a shared pointer, instead we could have the Logger class store a shared pointer and forward all methods calls to the shared pointer. Basically we could accomplish the same thing without inheritance.

That being said, if @dhood wanted to switch this to a pointer, that's fine by me too.

Also, if we really want to return a shared pointer we can do that in the future with an API break.

/**
* The child logger's full name will include any hierarchy conventions that
* indicate it is a descendant of this logger.
* For example, ```get_logger('abc').get_child('def')``` will return a logger
Copy link
Member

Choose a reason for hiding this comment

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

nitpick: which use triple back tick here but single elsewhere?

Copy link
Member Author

Choose a reason for hiding this comment

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

it wasn't rendering the full expression without the triple (the others are simpler)

{

/// Implementation of the NodeLogger part of the Node API.
class NodeLogger : public NodeLoggerInterface
Copy link
Member

Choose a reason for hiding this comment

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

I have a small concern here that NodeLogger sounds to much like a thing that logs for a node (which is not really what it is). What about NodeLogging and NodeLoggingInterface instead? I had a similar dilemma with NodeTopic versus NodeTopics, but I ended up going with NodeTopics because NodeTopicsInterface sounded better. For the same logic I think decided to suggest NodeLogging here, but I'll leave it to your discretion.

Copy link
Member Author

Choose a reason for hiding this comment

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

Yeah, the NodeLogger attribute of the Node/LifecycleNode class is not a logger but a way to access the logger. will switch to NodeLogging as proposed

NodeLogger::NodeLogger(rclcpp::node_interfaces::NodeBaseInterface * node_base)
: node_base_(node_base)
{
// TODO(dhood): use the namespace (slashes converted to dots)
Copy link
Member

Choose a reason for hiding this comment

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

This would be nice to have in too, since that's part of the point of having the node logger right? So users don't have to do something like convert_slash_to_dot(node->get_namespace()) + node->get_name() for every logging call? (but still get the benefit of better namespaces in logging by default)

I understand this is higher risk to merge though...

Copy link
Member Author

Choose a reason for hiding this comment

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

It's definitely planned, I agree that it is the main point of the node logger. My thinking was to put the "logger name from node name/namespace" in rcl and then wrap it with python as well. Because of the reach of that change and the fact that things at the user level shouldn't change once we make the swap under the hood though, I consider it a separate "step" and so scoped it out of this PR for time reasons. It'll be the very next step though 😄

Copy link
Member Author

Choose a reason for hiding this comment

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

Following up: #433

@dhood
Copy link
Member Author

dhood commented Dec 5, 2017

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

those are all an unrelated linter failure that's been fixed

@dhood dhood merged commit 2e4e85f into master Dec 5, 2017
@dhood dhood deleted the node_loggers branch December 5, 2017 00:07
@dhood dhood removed the in review Waiting for review (Kanban column) label Dec 5, 2017
nnmm pushed a commit to ApexAI/rclcpp that referenced this pull request Jul 9, 2022
* Add action graph API

Builds on top of the rcl graph API.
A list of action names associated with action clients can be constructed by
looking for subscriber topic names that have the suffix "/_action/feedback".
Likewise, action servers are associated with publisher topic names with the same suffix.

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Enable multiple rmw action graph API tests

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Use ament_target_dependencies for osrf_testing_tools_cpp

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Fix lint errors

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Refactor

* Move graph API common implementation to local function
* Refactor tests

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Disable graph tests with OpenSplice

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Include graph.h in rcl_action.h

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Remove duplicate test

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Prefix increment operators

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Rename 'suffix' -> 'identifier'

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Add missing finalize calls and remove redundant branch

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Finalize names and types struct on error

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Fix bugs in tests

Pass valid names and types struct and update expected error code.

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Add zero allocator tests

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Fix indentation

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Check if action identifiers are the suffix

Signed-off-by: Jacob Perron <jacob@openrobotics.org>
DensoADAS pushed a commit to DensoADAS/rclcpp that referenced this pull request Aug 5, 2022
New in Python 3.8, we should call os.add_dll_directory for directories
containing the DLLs we intend to import as well as their recursive
dependencies.

Signed-off-by: Jacob Perron <jacob@openrobotics.org>

* Move logic to common package rpyutils

Signed-off-by: Jacob Perron <jacob@openrobotics.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants