❓ How to enable rclc debug logging?

[jeevan-vexev]

• Hardware description: Custom board with STM32F765BIT
• RTOS: N/A
• Installation type: micro-ROS for PlatformIO with Arduino Framework.
• Version or commit hash: Humble

I'm trying to debug why I occasionally see RCL_RET_ERR sometimes return from rclc_executor_spin_some() in my main project. To do so I'm trying to print out additional debug information from the executor to narrow down what the root cause of the RCL_RET_ERR. I've tried to create a simple project to print out the debug information from rclc_executor_spin_some() but I can't get it to output anything!

Steps to reproduce the issue

• Program the board using main.cpp and colcon.meta linked below.
• See "test log debug print" printed to Serial.
• No messages from rclc_executor_spin_some() are printed.

Expected behavior

• Logging messages (e.g. RCUTILS_LOG_x() from https://github.com/ros2/rclc/blob/rolling/rclc/src/rclc/executor.c) are printed to stderr/stdout and /rosout

Actual behavior

• Only "test log debug print" printed to Serial

Additional information

Code snips

Let me know if more context is needed!

main.cpp:

#include <Arduino.h>

#include <micro_ros_platformio.h>
#include <micro_ros_utilities/type_utilities.h>
#include <rclc/executor.h>
#include <rclc/rclc.h>
#include <rosidl_runtime_c/string_functions.h>

#include <rcl_interfaces/msg/log.h>

#include "drivers/gpio.h"


rcl_node_t node;
rclc_support_t support;
rcl_allocator_t allocator;
rclc_executor_t executor_main;

rcl_timer_t low_freq_timer;

rcl_publisher_t rosout_publisher;


#define ARRAY_LEN(x) (sizeof(x) / sizeof((x)[0]))
#define RCCHECK(fn) {rcl_ret_t temp_rc = fn; if ((temp_rc != RCL_RET_OK)) {error_loop();}}
#define RCSOFTCHECK(fn) {rcl_ret_t temp_rc = fn; if ((temp_rc != RCL_RET_OK)) {Serial.println( \
        "Soft check fail")}}

/**
 * @brief loop to indicate error
 * @todo Add explicit error codes
 */
void error_loop(void)
{
  while (true) {
    delay(100);
    gpio_state_toggle(GPIO_LED_ONBOARD);
    Serial.println("Hard check fail");
  }
}


void low_freq_timer_callback(rcl_timer_t * timer, int64_t last_call_time)
{
  gpio_state_toggle(GPIO_LED_ONBOARD);

  RCUTILS_LOG_DEBUG_NAMED("", "test log debug print");
}

// cppcheck-suppress unusedFunction
void setup()
{
  Serial.begin(115200);
  // Trap until USB VCOM port attached to microROS prior to proceeding
  SerialUSB.dtr(true);
  while (!SerialUSB.dtr()) {
    delay(100);
  }
  SerialUSB.begin();
  set_microros_serial_transports(SerialUSB);
  delay(1000);

  const uint64_t low_freq_timer_timeout = 400;
  gpio_init();
  allocator = rcl_get_default_allocator();
  rcl_init_options_t init_options = rcl_get_zero_initialized_init_options();
  RCCHECK(rcl_init_options_init(&init_options, allocator));
  #ifdef ROS_DOMAIN_OVERRIDE
  RCCHECK(rcl_init_options_set_domain_id(&init_options, ROS_DOMAIN_OVERRIDE));
  #endif
  RCCHECK(rclc_support_init_with_options(&support, 0, NULL, &init_options, &allocator));
  RCCHECK(rcutils_logging_set_logger_level("", RCUTILS_LOG_SEVERITY_DEBUG));
  RCCHECK(rclc_node_init_default(&node, "micro_ros_node", "hardware", &support));

  RCCHECK(
    rclc_publisher_init_default(
      &rosout_publisher,
      &node,
      ROSIDL_GET_MSG_TYPE_SUPPORT(rcl_interfaces, msg, Log),
      "/rosout"
    )
  );

  RCCHECK(
    rclc_timer_init_default(
      &low_freq_timer,
      &support,
      RCL_MS_TO_NS(low_freq_timer_timeout),
      low_freq_timer_callback
    )
  );

  // handles_num is the total num of subscriptions, timers, services, clients and guard conditions
  const size_t handles_num = 1;
  RCCHECK(rclc_executor_init(&executor_main, &support.context, handles_num, &allocator));
  RCCHECK(rclc_executor_add_timer(&executor_main, &low_freq_timer));
}

void loop()
{
  RCCHECK(rclc_executor_spin_some(&executor_main, RCL_MS_TO_NS(1)));
}

colcon.meta:

{
    "names": {
        "rmw_microxrcedds": {
            "cmake-args": [
                "-DRMW_UXRCE_MAX_NODES=1",
                "-DRMW_UXRCE_MAX_PUBLISHERS=15",
                "-DRMW_UXRCE_MAX_SUBSCRIPTIONS=3",
                "-DRMW_UXRCE_MAX_SERVICES=7",
                "-DRMW_UXRCE_MAX_CLIENTS=0"
            ]
        }
        "rclc": {
            "cmake-args": [
                "-DRCUTILS_LOG_MIN_SEVERITY=RCUTILS_LOG_MIN_SEVERITY_DEBUG"
            ]
        }
    }
}

[platformio]
src_dir = mcu
workspace_dir = ../../build/mcu_pio

[env]
board_microros_distro = humble

check_flags =
  cppcheck: --inconclusive --inline-suppr --suppress=*:*/libdeps/*
check_skip_packages = yes

lib_deps =
  https://github.com/micro-ROS/micro_ros_platformio#48096f8


[env:ststm32]
; pin platform version to 17.4, as 17.5 has build
; issues with undefined reference to `SerialUSB`
platform = [email protected]
framework = arduino
board = rev_b
extra_scripts = pre:boards/config_board.py
monitor_dtr = 1

build_src_filter =
  +<stm32/*>

build_flags =
  ${env.build_flags}
  ; enable SerialUSB
  -I mcu/stm32/
  -DPIO_FRAMEWORK_ARDUINO_ENABLE_CDC_WITHOUT_SERIAL
  -DUSBCON
  ; Increase USB buffer sizes. Each TX and RX buffer is calculated based
  ; on the teensy 4.0 default USB buffer sizes (TX: 8192, RX: 4096)
  ; (see https://github.com/PaulStoffregen/cores/blob/master/teensy4/usb_serial.c)). Note the TX/RX buffer
  ; sizes are calculated by multiplying the packet number by 64.
  ; Default buffer sizes:
  ;   CDC_TRANSMIT_QUEUE_BUFFER_PACKET_NUMBER 2
  ;   CDC_RECEIVE_QUEUE_BUFFER_PACKET_NUMBER 3
  ; Minimum buffer sizes:
  ;   CDC_TRANSMIT_QUEUE_BUFFER_PACKET_NUMBER 1
  ;   CDC_RECEIVE_QUEUE_BUFFER_PACKET_NUMBER 2
  -DCDC_TRANSMIT_QUEUE_BUFFER_PACKET_NUMBER=128
  -DCDC_RECEIVE_QUEUE_BUFFER_PACKET_NUMBER=64

  -DSERIAL_TX_BUFFER_SIZE=256
  -DSERIAL_RX_BUFFER_SIZE=256

  ; Reduce timeout of I2C from 100 to 10. This should still allow
  ; 1000 bytes of data to be sent via I2C at 100 kHz, more than enough for
  ; the BME environemntal and pressure sensor comms.
  -DI2C_TIMEOUT_TICK=10

  -DRCUTILS_LOG_MIN_SEVERITY=RCUTILS_LOG_MIN_SEVERITY_DEBUG

board_microros_user_meta = ststm32_custom.meta

lib_deps =
  ${env.lib_deps}