From ae29c87cc8f649717d49fa2d46ed6cf476cb9fcf Mon Sep 17 00:00:00 2001 From: Tomoya Fujita Date: Wed, 25 Sep 2024 13:04:29 -0700 Subject: [PATCH] support basic colcon test. (#19) * support basic colcon test. Signed-off-by: Tomoya Fujita * add logging file and contents check via rsyslog test conf. Signed-off-by: Tomoya Fujita * add test section in README. Signed-off-by: Tomoya Fujita --------- Signed-off-by: Tomoya Fujita --- CMakeLists.txt | 18 ++ README.md | 18 +- config/ros2-test.conf | 23 ++ src/rcl_logging_syslog.cpp | 69 +++--- test/test_logging_interface.cpp | 409 ++++++++++++++++++++++++++++++++ 5 files changed, 503 insertions(+), 34 deletions(-) create mode 100644 config/ros2-test.conf create mode 100644 test/test_logging_interface.cpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 6ced3ab..eed1329 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -41,6 +41,24 @@ install(TARGETS ${PROJECT_NAME} EXPORT ${PROJECT_NAME} LIBRARY DESTINATION lib RUNTIME DESTINATION bin) +if(BUILD_TESTING) + find_package(ament_lint_auto REQUIRED) + # cppcheck 1.90 doesn't understand some of the syntax in spdlog's bundled fmt + # code. Since we already have cppcheck disabled on Linux, just disable it + # completely for this package. + list(APPEND AMENT_LINT_AUTO_EXCLUDE + ament_cmake_cppcheck + ) + ament_lint_auto_find_test_dependencies() + + find_package(ament_cmake_gtest REQUIRED) + ament_add_gmock(test_logging_interface test/test_logging_interface.cpp) + if(TARGET test_logging_interface) + target_link_libraries(test_logging_interface ${PROJECT_NAME} rcpputils::rcpputils) + target_compile_definitions(test_logging_interface PUBLIC RCUTILS_ENABLE_FAULT_INJECTION) + endif() +endif() + ament_export_libraries(${PROJECT_NAME}) ament_export_targets(${PROJECT_NAME}) ament_package() diff --git a/README.md b/README.md index c3d9afc..94813eb 100644 --- a/README.md +++ b/README.md @@ -109,6 +109,22 @@ export RCL_LOGGING_IMPLEMENTATION=rcl_logging_syslog colcon build --symlink-install --cmake-clean-cache --packages-select rcl_logging_syslog rcl ``` +### Test + +Following to the previous build procedure, we need to copy [ros2-test.conf](./config/ros2-test.conf) to `/etc/rsyslog.d/`, and restart the `rsyslog`. + +```bash +sudo cp ./config/ros2-test.conf /etc/rsyslog.d/ +``` + +Then we can start the `colcon test`: + +This test creates and uses `/var/log/rcl_logging_syslog` directory in temporary for the test, and it checks the file existence and contents using `rcl_logging_syslog`. + +```bash +colcon test --event-handlers console_direct+ --packages-select rcl_logging_syslog +``` + ### Configuration [SYSLOG(3)](https://man7.org/linux/man-pages/man3/syslog.3.html) is really simple that does not have much interfaces to control on application side, it just writes the log data on `rsyslog` Unix Domain Socket. @@ -128,7 +144,7 @@ See more details for https://www.rsyslog.com/doc/index.html. #### `rsyslog` -Copy [ros-logging.conf](./config/ros2-logging.conf) to `/etc/rsyslog.d/`, and replace `` with your own IP address where `fluent-bit` listens on. +Copy [ros2-logging.conf](./config/ros2-logging.conf) to `/etc/rsyslog.d/`, and replace `` with your own IP address where `fluent-bit` listens on. ```bash sudo cp ./config/ros2-logging.conf /etc/rsyslog.d/ diff --git a/config/ros2-test.conf b/config/ros2-test.conf new file mode 100644 index 0000000..a1db22c --- /dev/null +++ b/config/ros2-test.conf @@ -0,0 +1,23 @@ +# +# ROS Test Setting +# +# This is an test configuration file for for rcl_logging_syslog. +# +# For more information install rsyslog-doc and see +# /usr/share/doc/rsyslog-doc/html/configuration/index.html +# + +# Test Message Format Template +# See more details for https://www.rsyslog.com/doc/configuration/properties.html +#$template TestFormat,"%msg:::sp-if-no-1st-sp%%msg:::drop-last-lf%\n" +$template TestFormat,"%msg:2:$%\n" + +# Directory and File Name Test Template +# See more details for https://www.rsyslog.com/doc/configuration/properties.html +### e.g) /var/log/rcl_logging_syslog/test_logging_interface_1405655_1727291103.log +$template TestFileName,"/var/log/rcl_logging_syslog/%programname%_%procid%_%$now-unixtimestamp%.log" + +# Log locally with specified templated file name. +local1.* ?TestFileName;TestFormat +local2.* ?TestFileName;TestFormat +local3.* ?TestFileName;TestFormat diff --git a/src/rcl_logging_syslog.cpp b/src/rcl_logging_syslog.cpp index 01c65b4..d37f84c 100644 --- a/src/rcl_logging_syslog.cpp +++ b/src/rcl_logging_syslog.cpp @@ -12,26 +12,26 @@ // See the License for the specific language governing permissions and // limitations under the License. +#include #include #include -#include #include #include #include -#include - -#include -#include +#include "rcpputils/env.hpp" +#include "rcpputils/scope_exit.hpp" -#include -#include +#include "rcutils/allocator.h" +#include "rcutils/logging.h" #include "rcutils/logging_macros.h" #include "rcutils/process.h" -#include -#include -#include +#include "rcutils/snprintf.h" +#include "rcutils/strdup.h" +#include "rcutils/time.h" + +#include "rcl_logging_interface/rcl_logging_interface.h" static const char * facility_env_name = "RCL_LOGGING_SYSLOG_FACILITY"; @@ -41,33 +41,35 @@ static std::shared_ptr syslog_identity; static const char *logger_name = "rcl_logging_syslog"; -typedef struct facility_index { +typedef struct facility_index +{ const char *c_name; const int c_value; } FACILITY_INDEX; const FACILITY_INDEX facility_table[] = - { - { "LOG_CRON", LOG_CRON }, - { "LOG_DAEMON", LOG_DAEMON }, - { "LOG_SYSLOG", LOG_SYSLOG }, - { "LOG_USER", LOG_USER }, - { "LOG_LOCAL0", LOG_LOCAL0 }, - { "LOG_LOCAL1", LOG_LOCAL1 }, - { "LOG_LOCAL2", LOG_LOCAL2 }, - { "LOG_LOCAL3", LOG_LOCAL3 }, - { "LOG_LOCAL4", LOG_LOCAL4 }, - { "LOG_LOCAL5", LOG_LOCAL5 }, - { "LOG_LOCAL6", LOG_LOCAL6 }, - { "LOG_LOCAL7", LOG_LOCAL7 }, - { NULL, -1 } - }; - -static const char *get_facility_name(int facility) { +{ + {"LOG_CRON", LOG_CRON}, + {"LOG_DAEMON", LOG_DAEMON}, + {"LOG_SYSLOG", LOG_SYSLOG}, + {"LOG_USER", LOG_USER}, + {"LOG_LOCAL0", LOG_LOCAL0}, + {"LOG_LOCAL1", LOG_LOCAL1}, + {"LOG_LOCAL2", LOG_LOCAL2}, + {"LOG_LOCAL3", LOG_LOCAL3}, + {"LOG_LOCAL4", LOG_LOCAL4}, + {"LOG_LOCAL5", LOG_LOCAL5}, + {"LOG_LOCAL6", LOG_LOCAL6}, + {"LOG_LOCAL7", LOG_LOCAL7}, + {NULL, -1} +}; + +static const char * get_facility_name(int facility) +{ for (auto f = facility_table; f->c_name != NULL; f++) { - if (f->c_value == facility) { - return f->c_name; - } + if (f->c_value == facility) { + return f->c_name; + } } return "Unknown facility"; } @@ -137,7 +139,8 @@ static int rcutil_to_syslog_level(int rcutil_level) return syslog_level; } -[[maybe_unused]] static void vlog_msg(int level, const char *format, ...) { +[[maybe_unused]] static void vlog_msg(int level, const char *format, ...) +{ va_list args; va_start(args, format); vsyslog(level, format, args); @@ -170,7 +173,7 @@ rcl_logging_ret_t rcl_logging_external_initialize( char * logdir = nullptr; rcl_logging_ret_t dir_ret = rcl_logging_get_logging_directory(allocator, &logdir); if (RCL_LOGGING_RET_OK != dir_ret) { - RCUTILS_SET_ERROR_MSG("Failed to get logging directory"); + RCUTILS_SET_ERROR_MSG_AND_APPEND_PREV_ERROR("Failed to get logging directory"); return dir_ret; } else { // rsyslog does not allow user to create or specify logging directory via API. diff --git a/test/test_logging_interface.cpp b/test/test_logging_interface.cpp new file mode 100644 index 0000000..a035a56 --- /dev/null +++ b/test/test_logging_interface.cpp @@ -0,0 +1,409 @@ +// Copyright 2024 Tomoya Fujita . +// +// 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 +#include +#include +#include +#include +#include +#include + +#include "gmock/gmock.h" + +#include "rcl_logging_interface/rcl_logging_interface.h" + +#include "rcpputils/env.hpp" +#include "rcpputils/filesystem_helper.hpp" +#include "rcpputils/scope_exit.hpp" + +#include "rcutils/allocator.h" +#include "rcutils/error_handling.h" +#include "rcutils/logging.h" +#include "rcutils/process.h" +#include "rcutils/strdup.h" +#include "rcutils/testing/fault_injection.h" + +static constexpr int logger_levels[] = +{ + RCUTILS_LOG_SEVERITY_UNSET, + RCUTILS_LOG_SEVERITY_DEBUG, + RCUTILS_LOG_SEVERITY_INFO, + RCUTILS_LOG_SEVERITY_WARN, + RCUTILS_LOG_SEVERITY_ERROR, + RCUTILS_LOG_SEVERITY_FATAL, +}; + +static void write_something() +{ + for (int level : logger_levels) { + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_set_logger_level(nullptr, level)); + std::stringstream ss; + ss << "Message of severity " << level << " at level " << level; + rcl_logging_external_log(level, nullptr, ss.str().c_str()); + } + + // give flush interval period for rsyslog (default 1 sec flush interval for file system) + // ref: https://www.rsyslog.com/doc/configuration/modules/omfile.html#flushinterval + std::this_thread::sleep_for(std::chrono::seconds(1)); +} + +// This is a helper class that resets an environment +// variable when leaving scope +class RestoreEnvVar final +{ +public: + explicit RestoreEnvVar(const std::string & name) + : name_(name), + value_(rcpputils::get_env_var(name.c_str())) + { + } + + ~RestoreEnvVar() + { + if (!rcpputils::set_env_var(name_.c_str(), value_.c_str())) { + std::cerr << "Failed to restore value of environment variable: " << name_ << std::endl; + } + } + +private: + const std::string name_; + const std::string value_; +}; + +class AllocatorTest : public ::testing::Test +{ +public: + AllocatorTest() + : allocator(rcutils_get_default_allocator()), + bad_allocator(get_bad_allocator()), + invalid_allocator(rcutils_get_zero_initialized_allocator()) + { + } + + rcutils_allocator_t allocator; + rcutils_allocator_t bad_allocator; + rcutils_allocator_t invalid_allocator; + +private: + static rcutils_allocator_t get_bad_allocator() + { + rcutils_allocator_t bad_allocator = rcutils_get_default_allocator(); + bad_allocator.allocate = AllocatorTest::bad_malloc; + bad_allocator.reallocate = AllocatorTest::bad_realloc; + return bad_allocator; + } + + static void * bad_malloc(size_t, void *) + { + return nullptr; + } + + static void * bad_realloc(void *, size_t, void *) + { + return nullptr; + } +}; + +class LoggingTest : public ::testing::Test +{ +public: + void SetUp() + { + // test log files will be created under /var/log/rcl_logging_syslog/xxx. + // rcl_logging_syslog folder will be created by rsyslog when it is writing. + var_log_ = std::filesystem::path("/var/log"); + ASSERT_TRUE(std::filesystem::exists(var_log_)); + test_log_dir_ = var_log_ / "rcl_logging_syslog"; + } + + void TearDown() + { + if (std::filesystem::remove_all(test_log_dir_) == 0) { + std::cerr << "Failed to remove " << test_log_dir_.string() << " directory\n"; + } + } + + bool remove_test_folder() + { + if (std::filesystem::remove_all(test_log_dir_) == 0) { + std::cerr << "Failed to remove " << test_log_dir_.string() << " directory\n"; + return false; + } + return true; + } + + std::filesystem::path find_single_log(const char * prefix) + { + std::string expected_prefix = get_expected_log_prefix(prefix); + + std::filesystem::path found; + std::filesystem::file_time_type found_last_write; + for (const std::filesystem::directory_entry & dir_entry : + std::filesystem::directory_iterator{test_log_dir_}) + { + // If the start of the filename matches the expected_prefix, and this is the newest file + // starting with that prefix, hold onto it to return later. + if (dir_entry.path().filename().string().rfind(expected_prefix, 0) == 0) { + if (found.string().empty() || dir_entry.last_write_time() > found_last_write) { + found = dir_entry.path(); + found_last_write = dir_entry.last_write_time(); + // Even though we found the file, we have to keep looking in case there + // is another file with the same prefix but a newer timestamp. + } + } + } + + return found; + } + + rcutils_allocator_t allocator; + +private: + std::string get_expected_log_prefix(const char * name) + { + char * exe_name; + if (name == nullptr || name[0] == '\0') { + exe_name = rcutils_get_executable_name(allocator); + } else { + exe_name = rcutils_strdup(name, allocator); + } + if (nullptr == exe_name) { + throw std::runtime_error("Failed to determine executable name"); + } + std::stringstream prefix; + prefix << exe_name << "_" << rcutils_get_pid() << "_"; + allocator.deallocate(exe_name, allocator.state); + return prefix.str(); + } + + std::filesystem::path test_log_dir_; + std::filesystem::path var_log_; +}; + +TEST_F(AllocatorTest, init_invalid) +{ + EXPECT_EQ( + RCL_LOGGING_RET_ERROR, + rcl_logging_external_initialize("file_name_prefix", nullptr, bad_allocator)); + rcutils_reset_error(); + EXPECT_EQ( + RCL_LOGGING_RET_INVALID_ARGUMENT, + rcl_logging_external_initialize(nullptr, nullptr, invalid_allocator)); + rcutils_reset_error(); +} + +TEST_F(AllocatorTest, init_failure) +{ + RestoreEnvVar home_var("HOME"); + RestoreEnvVar userprofile_var("USERPROFILE"); + + // No home directory to write log to + ASSERT_TRUE(rcpputils::set_env_var("HOME", nullptr)); + ASSERT_TRUE(rcpputils::set_env_var("USERPROFILE", nullptr)); + EXPECT_EQ(RCL_LOGGING_RET_ERROR, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + rcutils_reset_error(); +} + +TEST_F(AllocatorTest, init_valid) +{ + // This success test must be placed in the end after failure cases + // with test fixture class AllocatorTest. Because this succeeds, + // syslog log facility is allocated, this means init returns always success. + + // Config files are not supported, and pass through with warning. + EXPECT_EQ( + RCL_LOGGING_RET_OK, + rcl_logging_external_initialize(nullptr, "config_file", allocator)); + rcutils_reset_error(); +} + +TEST_F(LoggingTest, log_file_name_prefix) +{ + std::string log_file_path; + // executable name in default + { + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + write_something(); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + EXPECT_NO_THROW(log_file_path = find_single_log(nullptr).string()); + EXPECT_TRUE(remove_test_folder()); + } + // falls back to executable name if not nullptr, but empty + { + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize("", nullptr, allocator)); + write_something(); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + EXPECT_NO_THROW(log_file_path = find_single_log(nullptr).string()); + EXPECT_TRUE(remove_test_folder()); + } + // specified by user application + { + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize("logger", nullptr, allocator)); + write_something(); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + EXPECT_NO_THROW(log_file_path = find_single_log("logger").string()); + EXPECT_TRUE(remove_test_folder()); + } +} + +TEST_F(LoggingTest, use_different_facilities) +{ + RestoreEnvVar env_var("RCL_LOGGING_SYSLOG_FACILITY"); + + { + // default facility, LOG_LOCAL1 + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + + std::stringstream expected_log; + for (int level : logger_levels) { + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_set_logger_level(nullptr, level)); + + for (int severity : logger_levels) { + std::stringstream ss; + ss << "Message of severity " << severity << " at level " << level; + rcl_logging_external_log(severity, nullptr, ss.str().c_str()); + + if (severity >= level) { + expected_log << ss.str() << std::endl; + } else if (severity == 0 && level == 10) { + // This is a special case - not sure what the right behavior is + expected_log << ss.str() << std::endl; + } + } + } + + std::this_thread::sleep_for(std::chrono::seconds(1)); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + + std::string log_file_path = find_single_log(nullptr).string(); + std::ifstream log_file(log_file_path); + std::stringstream actual_log; + actual_log << log_file.rdbuf(); + EXPECT_EQ( + expected_log.str(), + actual_log.str()) << "Unexpected log contents in " << log_file_path; + EXPECT_TRUE(remove_test_folder()); + } + + { + // facility LOG_LOCAL2 + rcpputils::set_env_var("RCL_LOGGING_SYSLOG_FACILITY", "LOG_LOCAL2"); + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + + std::stringstream expected_log; + for (int level : logger_levels) { + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_set_logger_level(nullptr, level)); + + for (int severity : logger_levels) { + std::stringstream ss; + ss << "Message of severity " << severity << " at level " << level; + rcl_logging_external_log(severity, nullptr, ss.str().c_str()); + + if (severity >= level) { + expected_log << ss.str() << std::endl; + } else if (severity == 0 && level == 10) { + // This is a special case - not sure what the right behavior is + expected_log << ss.str() << std::endl; + } + } + } + + std::this_thread::sleep_for(std::chrono::seconds(1)); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + + std::string log_file_path = find_single_log(nullptr).string(); + std::ifstream log_file(log_file_path); + std::stringstream actual_log; + actual_log << log_file.rdbuf(); + EXPECT_EQ( + expected_log.str(), + actual_log.str()) << "Unexpected log contents in " << log_file_path; + EXPECT_TRUE(remove_test_folder()); + } + + { + // facility LOG_LOCAL3 + rcpputils::set_env_var("RCL_LOGGING_SYSLOG_FACILITY", "LOG_LOCAL3"); + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + + std::stringstream expected_log; + for (int level : logger_levels) { + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_set_logger_level(nullptr, level)); + + for (int severity : logger_levels) { + std::stringstream ss; + ss << "Message of severity " << severity << " at level " << level; + rcl_logging_external_log(severity, nullptr, ss.str().c_str()); + + if (severity >= level) { + expected_log << ss.str() << std::endl; + } else if (severity == 0 && level == 10) { + // This is a special case - not sure what the right behavior is + expected_log << ss.str() << std::endl; + } + } + } + + std::this_thread::sleep_for(std::chrono::seconds(1)); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + + std::string log_file_path = find_single_log(nullptr).string(); + std::ifstream log_file(log_file_path); + std::stringstream actual_log; + actual_log << log_file.rdbuf(); + EXPECT_EQ( + expected_log.str(), + actual_log.str()) << "Unexpected log contents in " << log_file_path; + EXPECT_TRUE(remove_test_folder()); + } +} + +TEST_F(LoggingTest, full_cycle) +{ + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + + // Make sure we can call initialize more than once + ASSERT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_initialize(nullptr, nullptr, allocator)); + + std::stringstream expected_log; + for (int level : logger_levels) { + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_set_logger_level(nullptr, level)); + + for (int severity : logger_levels) { + std::stringstream ss; + ss << "Message of severity " << severity << " at level " << level; + rcl_logging_external_log(severity, nullptr, ss.str().c_str()); + + if (severity >= level) { + expected_log << ss.str() << std::endl; + } else if (severity == 0 && level == 10) { + // This is a special case - not sure what the right behavior is + expected_log << ss.str() << std::endl; + } + } + } + + std::this_thread::sleep_for(std::chrono::seconds(1)); + EXPECT_EQ(RCL_LOGGING_RET_OK, rcl_logging_external_shutdown()); + + std::string log_file_path = find_single_log(nullptr).string(); + std::ifstream log_file(log_file_path); + std::stringstream actual_log; + actual_log << log_file.rdbuf(); + EXPECT_EQ( + expected_log.str(), + actual_log.str()) << "Unexpected log contents in " << log_file_path; + EXPECT_TRUE(remove_test_folder()); +}