make escape characters work (ros2#426)

* make escape characters work

Signed-off-by: Chen Lihui <lihui.chen@sony.com>

* remove \\ and \0 cases as it seems unnecessary

add the extra one position only if an expected char found

* use a different name for variables and address flake8

* decode once at the beginning

* reduce the times of memcpy

* update test to make the escape characters parsered by rcutils not by python itself

* not to process the \f and \v escaped characters

Signed-off-by: Chen Lihui <lihui.chen@sony.com>
Co-authored-by: Tomoya Fujita <Tomoya.Fujita@sony.com>
Co-authored-by: Chris Lalancette <clalancette@gmail.com>

src/logging.c

@@ -50,6 +50,7 @@
 #include "rcutils/types/hash_map.h"
 
 
+#define RCUTILS_LOGGING_BACKSLASH_CHAR '\\'
 #define RCUTILS_LOGGING_SEPARATOR_CHAR '.'
 
 #define RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN (2048)
@@ -414,6 +415,67 @@ static const char * copy_from_orig(
   return logging_output->buffer;
 }
 
+// copy buffers and decode escape characters if they exist
+static void create_format_string(
+  const char * logging_output_format_string)
+{
+  size_t dest_buffer_index = 0;
+  size_t start_offset = 0;
+  size_t start_offset_previous_not_copy = 0;
+  size_t back_slash_index = 0;
+
+  size_t length = strlen(logging_output_format_string);
+  if (length > RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN - 1) {
+    length = RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN - 1;
+  }
+
+  for (size_t i = 0; i < length; ) {
+    back_slash_index = rcutils_findn(
+      logging_output_format_string + i, RCUTILS_LOGGING_BACKSLASH_CHAR, length - i);
+    if (back_slash_index == SIZE_MAX) {
+      memcpy(
+        g_rcutils_logging_output_format_string + dest_buffer_index,
+        logging_output_format_string + start_offset - start_offset_previous_not_copy,
+        length - start_offset + start_offset_previous_not_copy);
+      break;
+    } else {
+      const char * expected_char = NULL;
+      switch (logging_output_format_string[i + back_slash_index + 1]) {
+        case 'a':  expected_char = "\a"; break;  // alert
+        case 'b':  expected_char = "\b"; break;  // backspace
+        case 'n':  expected_char = "\n"; break;  // new line
+        case 'r':  expected_char = "\r"; break;  // carriage return
+        case 't':  expected_char = "\t"; break;  // horizontal tab
+        default:
+          break;
+      }
+
+      if (expected_char) {
+        if (back_slash_index > 0) {
+          // copy previous buffer first
+          size_t len = back_slash_index + start_offset_previous_not_copy;
+          memcpy(
+            g_rcutils_logging_output_format_string + dest_buffer_index,
+            logging_output_format_string + start_offset,
+            len);
+          dest_buffer_index += len;
+          start_offset += len;
+          start_offset_previous_not_copy = 0;
+        }
+
+        // copy the decoded character
+        g_rcutils_logging_output_format_string[dest_buffer_index] = expected_char[0];
+        dest_buffer_index += 1;
+        start_offset += 2;
+      } else {
+        start_offset_previous_not_copy += (back_slash_index + 2);
+      }
+
+      i += (back_slash_index + 2);
+    }
+  }
+}
+
 static bool add_handler(token_handler handler, size_t start_offset, size_t end_offset)
 {
   if (g_num_log_msg_handlers >= (sizeof(g_handlers) / sizeof(g_handlers[0]))) {
@@ -625,12 +687,7 @@ rcutils_ret_t rcutils_logging_initialize_with_allocator(rcutils_allocator_t allo
     }
   }
 
-  size_t chars_to_copy = strlen(output_format);
-  if (chars_to_copy > RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN - 1) {
-    chars_to_copy = RCUTILS_LOGGING_MAX_OUTPUT_FORMAT_LEN - 1;
-  }
-  memcpy(g_rcutils_logging_output_format_string, output_format, chars_to_copy);
-  g_rcutils_logging_output_format_string[chars_to_copy] = '\0';
+  create_format_string(output_format);
 
   g_rcutils_logging_severities_map = rcutils_get_zero_initialized_hash_map();
   rcutils_ret_t hash_map_ret = rcutils_hash_map_init(

test/test_logging_output_format.py

@@ -72,6 +72,25 @@ def generate_test_description():
     ))
     processes_to_test.append(name)
 
+    env_simple_escape_tokens = dict(os.environ)
+    # This custom output is to check that escape characters work correctly.
+    env_simple_escape_tokens['RCUTILS_CONSOLE_OUTPUT_FORMAT'] = '\\t{name}\\n\\t{message}\\n'
+    name = 'test_logging_output_format_simple_escape'
+    launch_description.add_action(ExecuteProcess(
+        cmd=[executable], env=env_simple_escape_tokens, name=name, output='screen'
+    ))
+    processes_to_test.append(name)
+
+    env_complicated_escape_tokens = dict(os.environ)
+    # This custom output is to check that escape characters work correctly.
+    env_complicated_escape_tokens['RCUTILS_CONSOLE_OUTPUT_FORMAT'] = \
+        '{name} 0\\a1\\b23\\n44\\r5\\t67 {message}'
+    name = 'test_logging_output_format_complicated_escape'
+    launch_description.add_action(ExecuteProcess(
+        cmd=[executable], env=env_complicated_escape_tokens, name=name, output='screen'
+    ))
+    processes_to_test.append(name)
+
     launch_description.add_action(
         launch_testing.actions.ReadyToTest()
     )
@@ -95,7 +114,8 @@ def test_logging_output(self, proc_output, processes_to_test):
             launch_testing.asserts.assertInStderr(
                 proc_output,
                 expected_output=launch_testing.tools.expected_output_from_file(
-                    path=os.path.join(os.path.dirname(__file__), process_name)
+                    path=os.path.join(os.path.dirname(__file__), process_name),
+                    encoding='unicode_escape'
                 ),
                 process=process_name
             )

test/test_logging_output_format_complicated_escape.regex

@@ -0,0 +1,2 @@
+name1 0\a1\b23\n44\r5\t67 Xx{2045}X
+name2 0\a1\b23\n44\r5\t67 X42x{2043}X

test/test_logging_output_format_simple_escape.regex

@@ -0,0 +1,2 @@
+\tname1\n\tXx{2045}X\n
+\tname2\n\tX42x{2043}X\n