Conversation
mikaelarguedas
left a comment
There was a problem hiding this comment.
Overall the level of debug information seems appropriate to me.
currently debug messages will be "compiled in" by default (and therefore their logging adds overhead),
I think that's fine, I'd expect users to be able to turn on our debug prints with the code shiped in our binaries.
We may need to reevaluate if we see more and more performance issues when adding debug prints to the rest of the stack
no subloggers are used, but we could add one for e.g. rcl.wait if we think that users will want to filter out the repetitive logging from repeated waiting. I haven't added that here: my thinking was that we can revisit this later once all debug logging is in place.
👍 I think we need to play with more complex high level code to see when/how to make this more user friendly
wjwwood and I were speaking about how we might want to have another severity level that has even more debugging output, but perhaps compiled out by default.
👍 I mentioned it a few times in recent PRs, the values we use for the severity levels and to be able to compile out some levels should allow intermediate levels so that we and/or users can extend them easily (severity levels allow it already, the macros used to compile in or out don't yet).
As a side note: DDS-Security defines 7 logging severities:
• FATAL_LEVEL – security error causing a shutdown or failure of the Domain Participant
• SEVERE_LEVEL – major security error or fault
• ERROR_LEVEL – minor security error or fault
• WARNING_LEVEL – undesirable or unexpected behavior
• NOTICE_LEVEL – important security event
• INFO_LEVEL – interesting security event
• DEBUG_LEVEL – detailed information on the flow of the security events
• TRACE_LEVEL – even more detailed information
| rcl_client_fini(rcl_client_t * client, rcl_node_t * node) | ||
| { | ||
| (void)node; | ||
| RCUTILS_LOG_DEBUG_NAMED(ROS_PACKAGE_NAME, "Finalizing client") |
There was a problem hiding this comment.
Should this add a "client finalized" like it's done in the init function? (same for node and other node entities below)
| return RCL_RET_ERROR; | ||
| } | ||
| RCUTILS_LOG_DEBUG_NAMED( | ||
| ROS_PACKAGE_NAME, "Service take request succeeded: %s", taken ? "true" : "false") |
There was a problem hiding this comment.
We could add a debug print to rcl_send_response as well (https://github.com/ros2/rcl/pull/187/files#diff-777efe6fef16afbd8f9a9877ffba1138R282)?
rcl/src/rcl/subscription.c
Outdated
| return RCL_RET_ERROR; | ||
| } | ||
| RCUTILS_LOG_DEBUG_NAMED( | ||
| ROS_PACKAGE_NAME, "Subscription take request succeeded: %s", taken ? "true" : "false") |
rcl/test/rcl/service_fixture.cpp
Outdated
| if (rcl_wait_set_clear_services(&wait_set) != RCL_RET_OK) { | ||
| RCUTILS_LOG_ERROR("Error in wait_set_clear_services: %s", rcl_get_error_string_safe()) | ||
| RCUTILS_LOG_ERROR_NAMED( | ||
| ROS_PACKAGE_NAME, "Error in wait_set_clear_services: %s", rcl_get_error_string_safe()); |
There was a problem hiding this comment.
Nit: added trailing semi-colon
rcl/test/rcl/service_fixture.cpp
Outdated
| if (rcl_wait_set_add_service(&wait_set, service) != RCL_RET_OK) { | ||
| RCUTILS_LOG_ERROR("Error in wait_set_add_service: %s", rcl_get_error_string_safe()) | ||
| RCUTILS_LOG_ERROR_NAMED( | ||
| ROS_PACKAGE_NAME, "Error in wait_set_add_service: %s", rcl_get_error_string_safe()); |
There was a problem hiding this comment.
Nit: added trailing semi-colon (same multiple times in this file)
wjwwood
left a comment
There was a problem hiding this comment.
also lgtm, though some of the messages could definitely be downgraded to "trace" or "superdebug" like we had discussed.
| rcl_client_fini(rcl_client_t * client, rcl_node_t * node) | ||
| { | ||
| (void)node; | ||
| RCUTILS_LOG_DEBUG_NAMED(ROS_PACKAGE_NAME, "Finalizing client") |
|
thanks for the reviews! I'll be happy to move some prints to a lower severity level if/when we go in that direction: this is just the first iteration. I'll do some more investigating to check if this will make the ARM jobs unstable before merging. |
|
I reran the ARM job and it came out green on the same node, so I must have gotten unlucky before..: |
…#187) * add pub/sub option structures to support rmw specific payload feature Signed-off-by: William Woodall <william@osrfoundation.org> * link to design document in TODO Signed-off-by: William Woodall <william@osrfoundation.org>
Requires ros2/ament_cmake_ros#2 because
ROS_PACKAGE_NAMEis being used for the logger name to avoid hardcoding "rcl" everywhereTo note:
rcl.waitif we think that users will want to filter out the repetitive logging from repeated waiting. I haven't added that here: my thinking was that we can revisit this later once all debug logging is in place.Example output of rclpy talker with rcl debug logging enabled (add
rclpy.logging.set_logger_severity_threshold('rcl', rclpy.logging.LoggingSeverity.DEBUG)to the script):rclcpp add_two_ints_client (add
rcutils_logging_set_logger_severity_threshold("rcl", RCUTILS_LOG_SEVERITY_DEBUG);)