-
Notifications
You must be signed in to change notification settings - Fork 412
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
Implement rclcpp-specific logging macros [taking name not object] #389
Merged
Merged
Changes from all commits
Commits
Show all changes
20 commits
Select commit
Hold shift + click to select a range
eccce57
Hardcoded for ROS_INFO
dhood 26b23df
Template for all known macro combinations
dhood 7e0b4ed
Update for rcutils logging indexing by tuple
dhood 92c90dc
Min severity so macros can be compiled out
dhood a668901
Named rcutils macros have the name as the last feature param
dhood edcac7d
Name must always be specified
dhood c845c93
remove default name
dhood eb3eab4
WIP add test
dhood c057536
fixup cmakelists indentation
dhood 0cc6ee6
Part test fixup
dhood d85af53
rclcpp-specific min severity for compiling out
dhood 213793e
Excluded features in a list
dhood be11dd8
Continue updating tests
dhood 1e3232a
Exclude throttle because it will need a custom implementation
dhood 42f8769
Remove old RCLCPP_INFO macro
dhood c6b025e
ROS_INFO -> RCLCPP_INFO
dhood 3768f07
Reference new file in doxygen
dhood 2c1e957
Document name argument
dhood 4929dab
Add todos clarifying out-of-scope work
dhood 2ab4562
Clarify purpose of second once test
dhood File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,101 @@ | ||
// generated from rclcpp/resource/logging.hpp.em | ||
|
||
// Copyright 2017 Open Source Robotics Foundation, Inc. | ||
// | ||
// Licensed under the Apache License, Version 2.0 (the "License"); | ||
// you may not use this file except in compliance with the License. | ||
// You may obtain a copy of the License at | ||
// | ||
// http://www.apache.org/licenses/LICENSE-2.0 | ||
// | ||
// Unless required by applicable law or agreed to in writing, software | ||
// distributed under the License is distributed on an "AS IS" BASIS, | ||
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
// See the License for the specific language governing permissions and | ||
// limitations under the License. | ||
|
||
#ifndef RCLCPP__LOGGING_HPP_ | ||
#define RCLCPP__LOGGING_HPP_ | ||
|
||
#include "rcutils/logging_macros.h" | ||
|
||
// These are used for compiling out logging macros lower than a minimum severity. | ||
#define RCLCPP_LOG_MIN_SEVERITY_DEBUG 0 | ||
#define RCLCPP_LOG_MIN_SEVERITY_INFO 1 | ||
#define RCLCPP_LOG_MIN_SEVERITY_WARN 2 | ||
#define RCLCPP_LOG_MIN_SEVERITY_ERROR 3 | ||
#define RCLCPP_LOG_MIN_SEVERITY_FATAL 4 | ||
#define RCLCPP_LOG_MIN_SEVERITY_NONE 5 | ||
|
||
/** | ||
* \def RCLCPP_LOG_MIN_SEVERITY | ||
* Define RCLCPP_LOG_MIN_SEVERITY=RCLCPP_LOG_MIN_SEVERITY_[DEBUG|INFO|WARN|ERROR|FATAL] | ||
* in your build options to compile out anything below that severity. | ||
* Use RCUTILS_LOG_MIN_SEVERITY_NONE to compile out all macros. | ||
*/ | ||
#ifndef RCLCPP_LOG_MIN_SEVERITY | ||
#define RCLCPP_LOG_MIN_SEVERITY RCLCPP_LOG_MIN_SEVERITY_DEBUG | ||
#endif | ||
|
||
|
||
@{ | ||
from rcutils.logging import feature_combinations | ||
from rcutils.logging import get_macro_parameters | ||
from rcutils.logging import get_suffix_from_features | ||
from rcutils.logging import severities | ||
|
||
# TODO(dhood): Implement the throttle macro using time sources available in rclcpp | ||
excluded_features = ['named', 'throttle'] | ||
def is_supported_feature_combination(feature_combination): | ||
is_excluded = any([ef in feature_combination for ef in excluded_features]) | ||
return not is_excluded | ||
}@ | ||
@[for severity in severities]@ | ||
/** @@name Logging macros for severity @(severity). | ||
*/ | ||
///@@{ | ||
#if (RCLCPP_LOG_MIN_SEVERITY > RCLCPP_LOG_MIN_SEVERITY_@(severity)) | ||
// empty logging macros for severity @(severity) when being disabled at compile time | ||
@[ for feature_combination in [fc for fc in feature_combinations if is_supported_feature_combination(fc)]]@ | ||
@{suffix = get_suffix_from_features(feature_combination)}@ | ||
/// Empty logging macro due to the preprocessor definition of RCLCPP_LOG_MIN_SEVERITY. | ||
#define RCLCPP_@(severity)@(suffix)(...) | ||
@[ end for]@ | ||
|
||
#else | ||
@[ for feature_combination in [fc for fc in feature_combinations if is_supported_feature_combination(fc)]]@ | ||
@{suffix = get_suffix_from_features(feature_combination)}@ | ||
/** | ||
* \def RCLCPP_@(severity)@(suffix) | ||
* Log a message with severity @(severity)@ | ||
@[ if feature_combinations[feature_combination].doc_lines]@ | ||
with the following conditions: | ||
@[ else]@ | ||
. | ||
@[ end if]@ | ||
@[ for doc_line in feature_combinations[feature_combination].doc_lines]@ | ||
* @(doc_line) | ||
@[ end for]@ | ||
* \param name The name of the logger | ||
@[ for param_name, doc_line in feature_combinations[feature_combination].params.items()]@ | ||
* \param @(param_name) @(doc_line) | ||
@[ end for]@ | ||
* \param ... The format string, followed by the variable arguments for the format string | ||
*/ | ||
// TODO(dhood): Replace the name argument with a logger object. | ||
#define RCLCPP_@(severity)@(suffix)(name, @(''.join([p + ', ' for p in get_macro_parameters(feature_combination).keys()]))...) \ | ||
RCUTILS_LOG_@(severity)@(suffix)_NAMED( \ | ||
@{params = get_macro_parameters(feature_combination).keys()}@ | ||
@[ if params]@ | ||
@(''.join([' ' + p + ', \\\n' for p in params]))@ | ||
@[ end if]@ | ||
std::string(name).c_str(), \ | ||
__VA_ARGS__) | ||
|
||
@[ end for]@ | ||
#endif | ||
///@@} | ||
|
||
@[end for]@ | ||
|
||
#endif // RCLCPP__LOGGING_HPP_ |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,158 @@ | ||
// Copyright 2017 Open Source Robotics Foundation, Inc. | ||
// | ||
// Licensed under the Apache License, Version 2.0 (the "License"); | ||
// you may not use this file except in compliance with the License. | ||
// You may obtain a copy of the License at | ||
// | ||
// http://www.apache.org/licenses/LICENSE-2.0 | ||
// | ||
// Unless required by applicable law or agreed to in writing, software | ||
// distributed under the License is distributed on an "AS IS" BASIS, | ||
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
// See the License for the specific language governing permissions and | ||
// limitations under the License. | ||
|
||
#include <gmock/gmock.h> | ||
|
||
#include <chrono> | ||
#include <string> | ||
#include <thread> | ||
#include <vector> | ||
|
||
#include "rclcpp/logging.hpp" | ||
#include "rcutils/logging.h" | ||
#include "rcutils/time.h" | ||
|
||
#define RCLCPP_TEST_LOGGING_MACRO_NAME "name" // Used in testing below | ||
|
||
using ::testing::EndsWith; | ||
|
||
size_t g_log_calls = 0; | ||
|
||
struct LogEvent | ||
{ | ||
rcutils_log_location_t * location; | ||
int level; | ||
std::string name; | ||
std::string message; | ||
}; | ||
LogEvent g_last_log_event; | ||
|
||
class TestLoggingMacros : public ::testing::Test | ||
{ | ||
public: | ||
rcutils_logging_output_handler_t previous_output_handler; | ||
void SetUp() | ||
{ | ||
g_log_calls = 0; | ||
ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize()); | ||
rcutils_logging_set_default_severity_threshold(RCUTILS_LOG_SEVERITY_DEBUG); | ||
|
||
auto rcutils_logging_console_output_handler = []( | ||
rcutils_log_location_t * location, | ||
int level, const char * name, const char * format, va_list * args) -> void | ||
{ | ||
g_log_calls += 1; | ||
g_last_log_event.location = location; | ||
g_last_log_event.level = level; | ||
g_last_log_event.name = name ? name : ""; | ||
char buffer[1024]; | ||
vsnprintf(buffer, sizeof(buffer), format, *args); | ||
g_last_log_event.message = buffer; | ||
}; | ||
|
||
this->previous_output_handler = rcutils_logging_get_output_handler(); | ||
rcutils_logging_set_output_handler(rcutils_logging_console_output_handler); | ||
} | ||
|
||
void TearDown() | ||
{ | ||
rcutils_logging_set_output_handler(this->previous_output_handler); | ||
g_rcutils_logging_initialized = false; | ||
EXPECT_FALSE(g_rcutils_logging_initialized); | ||
} | ||
}; | ||
|
||
TEST_F(TestLoggingMacros, test_logging_named) { | ||
for (int i : {1, 2, 3}) { | ||
RCLCPP_DEBUG("name", "message %d", i); | ||
} | ||
EXPECT_EQ(3u, g_log_calls); | ||
EXPECT_TRUE(g_last_log_event.location != NULL); | ||
if (g_last_log_event.location) { | ||
EXPECT_STREQ("TestBody", g_last_log_event.location->function_name); | ||
EXPECT_THAT(g_last_log_event.location->file_name, EndsWith("test_logging.cpp")); | ||
EXPECT_EQ(78u, g_last_log_event.location->line_number); | ||
} | ||
EXPECT_EQ(RCUTILS_LOG_SEVERITY_DEBUG, g_last_log_event.level); | ||
EXPECT_EQ("name", g_last_log_event.name); | ||
EXPECT_EQ("message 3", g_last_log_event.message); | ||
|
||
// Test different name inputs | ||
std::string std_string_name = "name"; | ||
RCLCPP_DEBUG(std_string_name, "message"); | ||
EXPECT_EQ("name", g_last_log_event.name); | ||
|
||
const char * c_string_name = "name"; | ||
RCLCPP_DEBUG(c_string_name, "message"); | ||
EXPECT_EQ("name", g_last_log_event.name); | ||
|
||
RCLCPP_DEBUG(std_string_name + c_string_name, "message"); | ||
EXPECT_EQ("namename", g_last_log_event.name); | ||
|
||
RCLCPP_DEBUG(RCLCPP_TEST_LOGGING_MACRO_NAME, "message"); | ||
EXPECT_EQ(RCLCPP_TEST_LOGGING_MACRO_NAME, g_last_log_event.name); | ||
RCLCPP_DEBUG(std::string(RCLCPP_TEST_LOGGING_MACRO_NAME) + std_string_name, "message"); | ||
EXPECT_EQ("namename", g_last_log_event.name); | ||
} | ||
|
||
TEST_F(TestLoggingMacros, test_logging_once) { | ||
for (int i : {1, 2, 3}) { | ||
RCLCPP_INFO_ONCE("name", "message %d", i); | ||
} | ||
EXPECT_EQ(1u, g_log_calls); | ||
EXPECT_EQ(RCUTILS_LOG_SEVERITY_INFO, g_last_log_event.level); | ||
EXPECT_EQ("name", g_last_log_event.name); | ||
EXPECT_EQ("message 1", g_last_log_event.message); | ||
|
||
// Check that another instance has a context that's independent to the call above's | ||
g_log_calls = 0; | ||
for (int i : {1, 2, 3}) { | ||
RCLCPP_INFO_ONCE("name", "second message %d", i); | ||
} | ||
EXPECT_EQ(1u, g_log_calls); | ||
EXPECT_EQ(RCUTILS_LOG_SEVERITY_INFO, g_last_log_event.level); | ||
EXPECT_EQ("name", g_last_log_event.name); | ||
EXPECT_EQ("second message 1", g_last_log_event.message); | ||
} | ||
|
||
TEST_F(TestLoggingMacros, test_logging_expression) { | ||
for (int i : {1, 2, 3, 4, 5, 6}) { | ||
RCLCPP_INFO_EXPRESSION("name", i % 3, "message %d", i); | ||
} | ||
EXPECT_EQ(4u, g_log_calls); | ||
EXPECT_EQ("message 5", g_last_log_event.message); | ||
} | ||
|
||
int g_counter = 0; | ||
|
||
bool mod3() | ||
{ | ||
return (g_counter % 3) != 0; | ||
} | ||
|
||
TEST_F(TestLoggingMacros, test_logging_function) { | ||
for (int i : {1, 2, 3, 4, 5, 6}) { | ||
g_counter = i; | ||
RCLCPP_INFO_FUNCTION("name", &mod3, "message %d", i); | ||
} | ||
EXPECT_EQ(4u, g_log_calls); | ||
EXPECT_EQ("message 5", g_last_log_event.message); | ||
} | ||
|
||
TEST_F(TestLoggingMacros, test_logging_skipfirst) { | ||
for (uint32_t i : {1, 2, 3, 4, 5}) { | ||
RCLCPP_WARN_SKIPFIRST("name", "message %u", i); | ||
EXPECT_EQ(i - 1, g_log_calls); | ||
} | ||
} |
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Are the tests in this PR covering this ?
I'm surprised that these levels don't match the severity enums defined in rcutils, (https://github.com/ros2/rcutils/blob/a2f722530c5e39eecfeb62b8c40db99bf9ae2a5e/include/rcutils/logging.h#L123-L128) is it on purpose ?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think you've misinterpreted their purpose, they're for compiling out macros, not setting severity level of messages/loggers. My comment above is relevant here: "I have created RCLCPP-specific versions of e.g.
RCUTILS_LOG_MIN_SEVERITY_DEBUG
so that rclcpp macros can be compiled out independently to rcutils macros being compiled out (and can be completely compiled out once they do more work than just forwarding to rcutils)."Because of the compile-time nature there are no tests for them, but I've tested it manually (that was how I discovered the need for ros2/rcutils#60)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I understood the purpose, the fact that we define different enums values for them still puzzles me though (and yeah I indeed missed ros2/rcutils#60 which introduce the same "error" at the rcutils level IMO).
If a user want to add a custom severity, (let's say between debug and info for example), he can do it thanks to the values of rcutils:
RCUTILS_LOG_SEVERITY_VERBOSE_MYSEVERITY = 15
.but cannot compile only those out because these enums don't leave any room between the levels. But now he cannot just compile out by using the same level he defined in rcutils, he has to find something between
RCLCPP_LOG_MIN_SEVERITY_DEBUG
andRCLCPP_LOG_MIN_SEVERITY_INFO
.How do we expect users to do this ? by defining:
or with hardcoded floating point values ?
It seems more user friendly to allow them to use the same values rather than a different one at each level, but maybe there is a technical constraint I missed here
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The reasoning was that, while a user can add their own severity level and call to the log functions with their custom level, it's not straightforward for them to extend the logging macros to have ones for their severity (even with the values matching the enum values). Since we need the min severity to be a preprocessor directive, we can't directly use the enum values (i.e.
#define RCLCPP_LOG_MIN_SEVERITY_MYSEVERITY RCUTILS_LOG_SEVERITY_MYSEVERITY
would not work for the purpose of compiling out the macros, which is what prompted ros2/rcutils#60). So, simply to avoid the need for factoring out the values used by the severity enum (10, 20, etc) into preprocessor directives, the values for the min severities are independent to the severity values themselves because there are other limiting factors on users creating custom severity macros anyway.It could be done though, definitely.