More rcl_logging_spdlog tests (#40)

Signed-off-by: Scott K Logan <logans@cottsay.net>

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)

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 <rcpputils/filesystem_helper.hpp>
+#include <rcutils/allocator.h>
+#include <rcutils/error_handling.h>
+#include <rcutils/get_env.h>
+#include <rcutils/process.h>
+#include <rcutils/types/string_array.h>
+
+#include <limits.h>
+#include <string>
+
+#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_

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 <rcpputils/filesystem_helper.hpp>
+#include <rcpputils/get_env.hpp>
 #include <rcutils/allocator.h>
+#include <rcutils/env.h>
 #include <rcutils/error_handling.h>
 #include <rcutils/logging.h>
-#include "rcl_logging_spdlog/logging_interface.h"
+
+#include <limits.h>
+#include <fstream>
+#include <string>
+
+#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;
 }