Add {short_file_name} as log format option (#541)

* Add short_file_name

Signed-off-by: Tony Najjar <tony.najjar@dexory.com>

* PR comments

Signed-off-by: Tony Najjar <tony.najjar@dexory.com>

* fix windows set_env

Signed-off-by: Tony Najjar <tony.najjar@dexory.com>

---------

Signed-off-by: Tony Najjar <tony.najjar@dexory.com>

Author: tonynajjar

include/rcutils/logging.h

@@ -85,6 +85,7 @@ rcutils_ret_t rcutils_logging_allocator_initialize(
  * the output format of messages logged to the console.
  * Available tokens are:
  *   - `file_name`, the full file name of the caller including the path
+ *   - `short_file_name`, the file name of the caller without the path (basename only)
  *   - `function_name`, the function name of the caller
  *   - `line_number`, the line number of the caller
  *   - `message`, the message string after it has been formatted

src/logging.c

@@ -343,7 +343,7 @@ static const char * expand_function_name(
   (void)start_offset;
   (void)end_offset;
 
-  if (logging_input->location) {
+  if (logging_input->location && logging_input->location->function_name) {
     if (rcutils_char_array_strcat(
         logging_output,
         logging_input->location->function_name) != RCUTILS_RET_OK)
@@ -366,7 +366,7 @@ static const char * expand_file_name(
   (void)start_offset;
   (void)end_offset;
 
-  if (logging_input->location) {
+  if (logging_input->location && logging_input->location->file_name) {
     if (rcutils_char_array_strcat(
         logging_output,
         logging_input->location->file_name) != RCUTILS_RET_OK)
@@ -381,6 +381,41 @@ static const char * expand_file_name(
   return logging_output->buffer;
 }
 
+static const char * expand_short_file_name(
+  const logging_input_t * logging_input,
+  rcutils_char_array_t * logging_output,
+  size_t start_offset, size_t end_offset)
+{
+  (void)start_offset;
+  (void)end_offset;
+
+  if (logging_input->location && logging_input->location->file_name) {
+    const char * file_name = logging_input->location->file_name;
+    const char * basename = file_name;
+    const char * last_sep = strrchr(file_name, '/');
+    if (last_sep != NULL) {
+      basename = last_sep + 1;
+    }
+#ifdef _WIN32
+    const char * last_backslash = strrchr(file_name, '\\');
+    if (last_backslash != NULL && (last_sep == NULL || last_backslash > last_sep)) {
+      basename = last_backslash + 1;
+    }
+#endif
+    if (rcutils_char_array_strcat(
+        logging_output,
+        basename) != RCUTILS_RET_OK)
+    {
+      RCUTILS_SAFE_FWRITE_TO_STDERR(rcutils_get_error_string().str);
+      rcutils_reset_error();
+      RCUTILS_SAFE_FWRITE_TO_STDERR("\n");
+      return NULL;
+    }
+  }
+
+  return logging_output->buffer;
+}
+
 typedef struct token_map_entry_s
 {
   const char * token;
@@ -392,6 +427,7 @@ static const token_map_entry_t tokens[] = {
   {.token = "name", .handler = expand_name},
   {.token = "message", .handler = expand_message},
   {.token = "function_name", .handler = expand_function_name},
+  {.token = "short_file_name", .handler = expand_short_file_name},
   {.token = "file_name", .handler = expand_file_name},
   {.token = "time", .handler = expand_time_as_seconds},
   {.token = "date_time_with_ms", .handler = expand_time_as_date},

test/test_logging_console_output_handler.cpp

@@ -14,11 +14,21 @@
 
 #include <gtest/gtest.h>
 
+#include <cstdlib>
 #include <string>
 #include <vector>
 
 #include "osrf_testing_tools_cpp/scope_exit.hpp"
 #include "rcutils/logging.h"
+#include "rcutils/types/char_array.h"
+
+#ifdef _WIN32
+#define test_setenv(name, value) _putenv_s(name, value)
+#define test_unsetenv(name) _putenv_s(name, "")
+#else
+#define test_setenv(name, value) setenv(name, value, 1)
+#define test_unsetenv(name) unsetenv(name)
+#endif
 
 static void call_handler(
   const rcutils_log_location_t * location,
@@ -95,3 +105,82 @@ TEST(TestLoggingConsoleOutputHandler, bad_inputs) {
   call_handler(
     &log_location, RCUTILS_LOG_SEVERITY_INFO, log_name, timestamp, "bad format", "part1", "part2");
 }
+
+TEST(TestLoggingConsoleOutputHandler, short_file_name_extracts_basename) {
+  // Set the output format to use {short_file_name} before initializing
+  test_setenv("RCUTILS_CONSOLE_OUTPUT_FORMAT", "{short_file_name}");
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    test_unsetenv("RCUTILS_CONSOLE_OUTPUT_FORMAT");
+  });
+
+  ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize());
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown());
+  });
+
+  rcutils_allocator_t allocator = rcutils_get_default_allocator();
+  rcutils_char_array_t output_buf;
+  ASSERT_EQ(RCUTILS_RET_OK, rcutils_char_array_init(&output_buf, 1024, &allocator));
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    EXPECT_EQ(RCUTILS_RET_OK, rcutils_char_array_fini(&output_buf));
+  });
+
+  rcutils_log_location_t location = {
+    "test_function",
+    "/some/long/path/to/my_source_file.cpp",
+    42,
+  };
+
+  ASSERT_EQ(
+    RCUTILS_RET_OK,
+    rcutils_logging_format_message(
+      &location, RCUTILS_LOG_SEVERITY_INFO, "test_logger", 0,
+      "hello", &output_buf));
+
+  std::string output(output_buf.buffer);
+  EXPECT_NE(std::string::npos, output.find("my_source_file.cpp"))
+    << "Expected basename in output: " << output;
+  EXPECT_EQ(std::string::npos, output.find("/some/long/path/to/"))
+    << "Full path should not appear in output: " << output;
+}
+
+TEST(TestLoggingConsoleOutputHandler, short_file_name_without_path_unchanged) {
+  test_setenv("RCUTILS_CONSOLE_OUTPUT_FORMAT", "{short_file_name}");
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    test_unsetenv("RCUTILS_CONSOLE_OUTPUT_FORMAT");
+  });
+
+  ASSERT_EQ(RCUTILS_RET_OK, rcutils_logging_initialize());
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown());
+  });
+
+  rcutils_allocator_t allocator = rcutils_get_default_allocator();
+  rcutils_char_array_t output_buf;
+  ASSERT_EQ(RCUTILS_RET_OK, rcutils_char_array_init(&output_buf, 1024, &allocator));
+  OSRF_TESTING_TOOLS_CPP_SCOPE_EXIT(
+  {
+    EXPECT_EQ(RCUTILS_RET_OK, rcutils_char_array_fini(&output_buf));
+  });
+
+  rcutils_log_location_t location = {
+    "test_function",
+    "bare_file.cpp",
+    10,
+  };
+
+  ASSERT_EQ(
+    RCUTILS_RET_OK,
+    rcutils_logging_format_message(
+      &location, RCUTILS_LOG_SEVERITY_INFO, "test_logger", 0,
+      "test", &output_buf));
+
+  std::string output(output_buf.buffer);
+  EXPECT_NE(std::string::npos, output.find("bare_file.cpp"))
+    << "Expected bare filename in output: " << output;
+}

test/test_logging_output_format.py

@@ -101,6 +101,16 @@ def generate_test_description():
     ))
     processes_to_test.append(name)
 
+    env_short_file_name = dict(os.environ)
+    # This custom output is to check that {short_file_name} outputs the basename of the file.
+    env_short_file_name['RCUTILS_CONSOLE_OUTPUT_FORMAT'] = '{short_file_name}:{line_number}'
+    env_short_file_name['RCUTILS_COLORIZED_OUTPUT'] = '0'
+    name = 'test_logging_output_format_short_file_name'
+    launch_description.add_action(ExecuteProcess(
+        cmd=[executable], env=env_short_file_name, name=name, output='screen'
+    ))
+    processes_to_test.append(name)
+
     launch_description.add_action(
         launch_testing.actions.ReadyToTest()
     )

test/test_logging_output_format_short_file_name.txt

@@ -0,0 +1,2 @@
+file:42
+file:42