diff --git a/rcl_logging_spdlog/CMakeLists.txt b/rcl_logging_spdlog/CMakeLists.txt index a4e43ab..4fdc288 100644 --- a/rcl_logging_spdlog/CMakeLists.txt +++ b/rcl_logging_spdlog/CMakeLists.txt @@ -52,9 +52,11 @@ if(BUILD_TESTING) performance_test_fixture::performance_test_fixture INTERFACE_INCLUDE_DIRECTORIES) find_package(ament_cmake_gtest REQUIRED) + find_package(rcpputils REQUIRED) ament_add_gtest(test_logging_interface test/test_logging_interface.cpp) if(TARGET test_logging_interface) target_link_libraries(test_logging_interface ${PROJECT_NAME}) + ament_target_dependencies(test_logging_interface rcpputils) endif() add_performance_test(benchmark_logging_interface test/benchmark/benchmark_logging_interface.cpp) if(TARGET benchmark_logging_interface) diff --git a/rcl_logging_spdlog/test/fixtures.hpp b/rcl_logging_spdlog/test/fixtures.hpp new file mode 100644 index 0000000..51db959 --- /dev/null +++ b/rcl_logging_spdlog/test/fixtures.hpp @@ -0,0 +1,129 @@ +// Copyright 2020 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 FIXTURES_HPP_ +#define FIXTURES_HPP_ + +#include +#include +#include +#include +#include +#include + +#include +#include + +#include "gtest/gtest.h" + +#ifdef _WIN32 +#define popen _popen +#define pclose _pclose +#define DIR_CMD "dir /B" +#else +#define DIR_CMD "ls -d" +#endif + +namespace fs = rcpputils::fs; + +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 AllocatorTest +{ +public: + LoggingTest() + : AllocatorTest() + { + } + + fs::path find_single_log() + { + fs::path log_dir = get_log_dir(); + std::stringstream dir_command; + dir_command << DIR_CMD << " " << (log_dir / get_expected_log_prefix()).string() << "*"; + + FILE * fp = popen(dir_command.str().c_str(), "r"); + if (nullptr == fp) { + throw std::runtime_error("Failed to glob for log files"); + } + +#ifdef _WIN32 + char raw_line[MAX_PATH]; +#else + char raw_line[PATH_MAX]; +#endif + char * ret = fgets(raw_line, sizeof(raw_line), fp); + pclose(fp); + if (nullptr == ret) { + throw std::runtime_error("No log files were found"); + } + + std::string line(raw_line); + fs::path line_path(line.substr(0, line.find_last_not_of(" \t\r\n") + 1)); + // This should be changed once ros2/rcpputils#68 is resolved + return line_path.is_absolute() ? line_path : log_dir / line_path; + } + +private: + std::string get_expected_log_prefix() + { + char * exe_name = rcutils_get_executable_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(); + } + + fs::path get_log_dir() + { + return fs::path(rcutils_get_home_dir()) / ".ros" / "log"; + } +}; + +#endif // FIXTURES_HPP_ diff --git a/rcl_logging_spdlog/test/test_logging_interface.cpp b/rcl_logging_spdlog/test/test_logging_interface.cpp index cfe86a2..e1e9b83 100644 --- a/rcl_logging_spdlog/test/test_logging_interface.cpp +++ b/rcl_logging_spdlog/test/test_logging_interface.cpp @@ -12,24 +12,79 @@ // See the License for the specific language governing permissions and // limitations under the License. +#include +#include #include +#include #include #include -#include "rcl_logging_spdlog/logging_interface.h" + +#include +#include +#include + +#include "fixtures.hpp" #include "gtest/gtest.h" +#include "rcl_logging_spdlog/logging_interface.h" -static void * bad_malloc(size_t, void *) +namespace fs = rcpputils::fs; + +const int logger_levels[] = { - return nullptr; -} + RCUTILS_LOG_SEVERITY_UNSET, + RCUTILS_LOG_SEVERITY_DEBUG, + RCUTILS_LOG_SEVERITY_INFO, + RCUTILS_LOG_SEVERITY_WARN, + RCUTILS_LOG_SEVERITY_ERROR, + RCUTILS_LOG_SEVERITY_FATAL, +}; + +// This is a helper class that resets an environment +// variable when leaving scope +class RestoreEnvVar +{ +public: + explicit RestoreEnvVar(const std::string & name) + : name_(name), + value_(rcpputils::get_env_var(name.c_str())) + { + } + + ~RestoreEnvVar() + { + if (!rcutils_set_env(name_.c_str(), value_.c_str())) { + std::cerr << "Failed to restore value of environment variable: " << name_ << std::endl; + } + } -TEST(logging_interface, init_invalid) +private: + const std::string name_; + const std::string value_; +}; + +// TODO(cottsay): Remove when ros2/rcpputils#63 is resolved +static fs::path current_path() { - rcutils_allocator_t allocator = rcutils_get_default_allocator(); - rcutils_allocator_t bad_allocator = rcutils_get_default_allocator(); - rcutils_allocator_t invalid_allocator = rcutils_get_zero_initialized_allocator(); - bad_allocator.allocate = bad_malloc; +#ifdef _WIN32 +#ifdef UNICODE +#error "rcpputils::fs does not support Unicode paths" +#endif + char cwd[MAX_PATH]; + if (nullptr == _getcwd(cwd, MAX_PATH)) { +#else + char cwd[PATH_MAX]; + if (nullptr == getcwd(cwd, PATH_MAX)) { +#endif + std::error_code ec{errno, std::system_category()}; + errno = 0; + throw std::system_error{ec, "cannot get current working directory"}; + } + return fs::path(cwd); +} + +TEST_F(LoggingTest, init_invalid) +{ // Config files are not supported by spdlog EXPECT_EQ(2, rcl_logging_external_initialize("anything", allocator)); rcutils_reset_error(); @@ -39,12 +94,71 @@ TEST(logging_interface, init_invalid) rcutils_reset_error(); } -TEST(logging_interface, full_cycle) +TEST_F(LoggingTest, init_failure) +{ + RestoreEnvVar home_var("HOME"); + RestoreEnvVar userprofile_var("USERPROFILE"); + + // No home directory to write log to + ASSERT_EQ(true, rcutils_set_env("HOME", nullptr)); + ASSERT_EQ(true, rcutils_set_env("USERPROFILE", nullptr)); + EXPECT_EQ(2, rcl_logging_external_initialize(nullptr, allocator)); + rcutils_reset_error(); + + // Force failure to create directories + fs::path fake_home = current_path() / "fake_home_dir"; + ASSERT_TRUE(fs::create_directories(fake_home)); + ASSERT_EQ(true, rcutils_set_env("HOME", fake_home.string().c_str())); + + // ...fail to create .ros dir + fs::path ros_dir = fake_home / ".ros"; + std::fstream(ros_dir.string(), std::ios_base::out).close(); + EXPECT_EQ(2, rcl_logging_external_initialize(nullptr, allocator)); + ASSERT_TRUE(fs::remove(ros_dir)); + + // ...fail to create .ros/log dir + ASSERT_TRUE(fs::create_directories(ros_dir)); + fs::path ros_log_dir = ros_dir / "log"; + std::fstream(ros_log_dir.string(), std::ios_base::out).close(); + EXPECT_EQ(2, rcl_logging_external_initialize(nullptr, allocator)); + ASSERT_TRUE(fs::remove(ros_log_dir)); + ASSERT_TRUE(fs::remove(ros_dir)); + + ASSERT_TRUE(fs::remove(fake_home)); +} + +TEST_F(LoggingTest, full_cycle) { - rcutils_allocator_t allocator = rcutils_get_default_allocator(); + ASSERT_EQ(0, rcl_logging_external_initialize(nullptr, allocator)); + // Make sure we can call initialize more than once ASSERT_EQ(0, rcl_logging_external_initialize(nullptr, allocator)); - EXPECT_EQ(0, rcl_logging_external_set_logger_level(nullptr, RCUTILS_LOG_SEVERITY_INFO)); - rcl_logging_external_log(RCUTILS_LOG_SEVERITY_INFO, nullptr, "Log Message"); + + std::stringstream expected_log; + for (int level : logger_levels) { + EXPECT_EQ(0, 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; + } + } + } + EXPECT_EQ(0, rcl_logging_external_shutdown()); + + std::string log_file_path = find_single_log().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; }