Debugging Robot Code: Logs, Serial Output, rosbag, and Foxglove

Most robot bugs are timing bugs, not logic bugs. A controller that works in simulation fails on hardware because a IMU packet arrives 40 ms late, a serial frame gets truncated, or a tf lookup hits an extrapolation window. print() debugging cannot catch these failures. You need a layered toolchain: structured logs for events, raw serial capture for the firmware boundary, rosbag2 for deterministic replay, and Foxglove for time-aligned visualization.

This guide builds that toolchain for ROS 2 (Humble, Jazzy, and later) with a microcontroller on the other end of a UART or USB-CDC link.

Quick Takeaways

• Logs record discrete events and state transitions. Set severity levels per node and throttle repeating messages.
• Serial capture isolates firmware faults from ROS faults. Timestamp every line at the host.
• rosbag2 with MCAP storage turns a one-off failure into a repeatable test case.
• Foxglove aligns topics on one timeline, so you can see cause and effect across sensors, tf, and controller output.

Layer 1: Structured Logging in ROS 2

Severity Levels and Per-Node Control

ROS 2 provides five severity levels: DEBUG, INFO, WARN, ERROR, FATAL. Every log call also publishes to the /rosout topic, which Foxglove and rosbag2 can capture.

Set the level at launch without recompiling:

# Global level for one node
ros2 run my_robot base_driver --ros-args --log-level debug

# Different level per logger (node name := level)
ros2 run my_robot base_driver --ros-args \
  --log-level warn \
  --log-level base_driver:=debug \
  --log-level rcl:=error

Change the console format with an environment variable:

# Include severity, wall time, node name, and source location
export RCUTILS_CONSOLE_OUTPUT_FORMAT="[{severity}] [{time}] [{name}]: {message} ({file_name}:{line_number})"
export RCUTILS_COLORIZED_OUTPUT=1

Log files land in ~/.ros/log by default. Override the path with ROS_LOG_DIR.

Throttling and Once-Only Logs

A 500 Hz control loop that logs every cycle produces 500 lines per second. That floods the console and slows the node. Use throttled logging:

import rclpy
from rclpy.node import Node
from geometry_msgs.msg import Twist

class VelocityGuard(Node):
    def __init__(self):
        super().__init__('velocity_guard')
        self.max_v = 0.5  # m/s, hard limit
        self.sub = self.create_subscription(Twist, 'cmd_vel', self.cb, 10)

    def cb(self, msg: Twist):
        v = msg.linear.x  # forward velocity command in m/s
        if abs(v) > self.max_v:
            # Emit at most one warning per second, even at 100 Hz input
            self.get_logger().warn(
                f'cmd_vel {v:.2f} m/s exceeds limit {self.max_v:.2f}; clamping',
                throttle_duration_sec=1.0,
            )
            v = max(-self.max_v, min(self.max_v, v))
        # DEBUG output is dropped unless the level is lowered at launch
        self.get_logger().debug(f'applied v={v:.3f}')

def main():
    rclpy.init()
    rclpy.spin(VelocityGuard())

if __name__ == '__main__':
    main()

In rclcpp, the equivalents are RCLCPP_WARN_THROTTLE(logger, *clock, 1000, ...) (period in milliseconds) and RCLCPP_INFO_ONCE.

What to Log

Layer 2: Serial Output from the Firmware Boundary

When a differential drive base misbehaves, first decide whether the fault sits in firmware or in ROS. Raw serial output answers that question.

Quick Inspection

# Check the device and permissions
ls -l /dev/ttyACM0
sudo usermod -aG dialout $USER   # log out and back in afterward

# Interactive view at 115200 baud
picocom -b 115200 /dev/ttyACM0
# Exit with Ctrl-A then Ctrl-X

Bandwidth Sanity Check

A serial link at 115200 baud with 8N1 framing uses 10 bits per byte (1 start, 8 data, 1 stop):

Throughput  = baud / 10 = 115200 / 10 = 11,520 bytes/s
Frame size  = 24 bytes (ASCII line: "123456,-1024,1024\n" padded)
Max rate    = 11,520 / 24 = 480 frames/s
Usable rate = 480 × 0.5 = ~240 frames/s  (leave 50% margin for bursts)

If your encoder stream targets 500 Hz at 24 bytes per frame, the link needs 12,000 B/s. That exceeds the physical limit. The symptom is truncated lines and a growing receive buffer. Switch to a binary protocol, shorten the frames, or raise the baud rate to 921600.

Host-Side Timestamped Logger

Raw screen output carries no timestamps. This script stamps each line on arrival and flags malformed frames:

#!/usr/bin/env python3
"""Timestamped serial logger. Usage: serial_log.py /dev/ttyACM0 115200 out.log"""
import sys, time, serial

port, baud, out_path = sys.argv[1], int(sys.argv[2]), sys.argv[3]

# timeout=0.1 keeps readline() from blocking forever on a dead link
with serial.Serial(port, baud, timeout=0.1) as ser, open(out_path, 'w') as f:
    last_t = None
    while True:
        raw = ser.readline()                 # bytes up to '\n'
        if not raw:
            continue
        t = time.monotonic()                 # monotonic: immune to NTP jumps
        line = raw.decode('ascii', errors='replace').rstrip()
        dt_ms = 0.0 if last_t is None else (t - last_t) * 1e3
        last_t = t

        # Expected format: "<ms>,<left_ticks>,<right_ticks>"
        parts = line.split(',')
        ok = len(parts) == 3 and all(p.lstrip('-').isdigit() for p in parts)
        tag = 'OK ' if ok else 'BAD'
        f.write(f'{t:.6f} dt={dt_ms:7.2f}ms {tag} {line}\n')
        f.flush()

Look for three patterns in the output:

• BAD lines point to buffer overflow, electrical noise, or a baud-rate mismatch.
• Large dt spikes (for example 200 ms at a nominal 10 ms) point to firmware blocking calls or USB scheduling stalls.
• Repeated identical tick values point to a stalled encoder interrupt.

Firmware-Side Practices

Layer 3: Recording and Replaying with rosbag2

A bag captures the exact message stream. Replaying it reproduces a failure on your desk without the robot.

Recording

Use MCAP storage. It supports indexed random access and works natively with Foxglove. Recent ROS 2 distributions ship it as the default. On Humble, install ros-humble-rosbag2-storage-mcap.

# Record selected topics with zstd compression and 1 GB file splitting
ros2 bag record \
  -s mcap \
  -o fault_2026_11_08 \
  --max-bag-size 1000000000 \
  --compression-mode file --compression-format zstd \
  /scan /imu/data /odom /tf /tf_static /cmd_vel /rosout /diagnostics

Always include /tf_static. It publishes once at startup, so a bag that starts late loses it. Add --include-hidden-topics if you need internal topics. Record /rosout so your log events appear on the same timeline as sensor data.

Inspect the result:

ros2 bag info fault_2026_11_08

The output lists duration, message counts per topic, and QoS profiles. A topic with a count far below duration × rate was dropping messages during the fault.

Replaying

# Replay at half speed, publish /clock, loop for repeated testing
ros2 bag play fault_2026_11_08 \
  --clock \
  --rate 0.5 \
  --loop \
  --topics /scan /imu/data /odom /tf /tf_static

Every node under test must run with use_sim_time:=true. Without it, nodes mix wall time with bag time and tf lookups fail with extrapolation errors:

ros2 run my_robot ekf_node --ros-args -p use_sim_time:=true

Exclude the topics your node under test produces (for example /cmd_vel). Otherwise the bag and your live node publish to the same topic and conflict.

Offline Latency Analysis

Compare each message’s header stamp with its recorded receive time to measure transport and driver latency:

#!/usr/bin/env python3
"""Latency of header.stamp vs bag receive time. Usage: bag_latency.py <bag_dir> <topic>"""
import sys, statistics
import rosbag2_py
from rclpy.serialization import deserialize_message
from rosidl_runtime_py.utilities import get_message

bag_dir, topic = sys.argv[1], sys.argv[2]

reader = rosbag2_py.SequentialReader()
reader.open(
    rosbag2_py.StorageOptions(uri=bag_dir, storage_id='mcap'),
    rosbag2_py.ConverterOptions(input_serialization_format='cdr',
                                output_serialization_format='cdr'))

types = {t.name: t.type for t in reader.get_all_topics_and_types()}
msg_cls = get_message(types[topic])          # resolve e.g. sensor_msgs/msg/Imu

lat_ms = []
while reader.has_next():
    name, data, recv_ns = reader.read_next() # recv_ns: bag receive time in ns
    if name != topic:
        continue
    msg = deserialize_message(data, msg_cls)
    stamp_ns = msg.header.stamp.sec * 10**9 + msg.header.stamp.nanosec
    lat_ms.append((recv_ns - stamp_ns) / 1e6)

lat_ms.sort()
p99 = lat_ms[int(0.99 * len(lat_ms)) - 1]
print(f'n={len(lat_ms)}  mean={statistics.mean(lat_ms):.2f} ms  '
      f'stdev={statistics.pstdev(lat_ms):.2f} ms  p99={p99:.2f} ms  max={lat_ms[-1]:.2f} ms')

Jitter matters more than mean latency for estimators. A fusion filter tolerates a constant 15 ms delay but not a delay that swings between 2 ms and 60 ms.

Layer 4: Foxglove for Time-Aligned Debugging

Foxglove opens MCAP files directly and connects to live robots through foxglove_bridge.

Live Connection

sudo apt install ros-$ROS_DISTRO-foxglove-bridge
ros2 launch foxglove_bridge foxglove_bridge_launch.xml port:=8765

In Foxglove, choose Open connection → Foxglove WebSocket and enter ws://<robot-ip>:8765. Keep the bridge on a trusted network, since it exposes your topics without authentication by default.

Recorded Data

Drag the .mcap file into the Foxglove window. For split bags, open the directory’s files together.

Panel Layout for Fault Hunting

Click any point on a plot and every panel jumps to that timestamp. This is the key capability: you see the warning, the sensor values, and the robot pose at the same instant.

Real-World Workflow: Diagnosing Odometry Yaw Drift on a Differential Drive Robot

Symptom: After a 10 m straight run, the robot’s /odom shows 0° heading change, but the physical robot veered about 8°.

Step 1: Record the run.

ros2 bag record -s mcap -o drift_run /odom /imu/data /cmd_vel /tf /tf_static /rosout /joint_states

Step 2: Check the serial boundary. Run serial_log.py in parallel. Inspect the log for BAD frames and dt spikes. Suppose it shows 0.4% bad frames and clean timing. Firmware transport is healthy.

Step 3: Compare yaw sources in Foxglove. Plot the gyro’s angular_velocity.z against the yaw rate derived from encoders. For a differential drive:

ω_enc = (v_R − v_L) / b
v_L   = (Δticks_L / CPR) × 2π r_L / Δt
v_R   = (Δticks_R / CPR) × 2π r_R / Δt

Here b is the wheel separation, CPR is counts per revolution, and r_L, r_R are wheel radii. The plot shows the gyro reporting a steady −2.1°/s while ω_enc stays near zero.

Step 4: Interpret. The encoders see equal wheel speeds but the robot turns. That signature indicates a wheel radius mismatch. A 1.5% radius error between wheels over 10 m produces roughly:

Δθ ≈ (Δr / r) × (distance / b) = 0.015 × (10 / 0.30) ≈ 0.5 rad ≈ 29°  (uncorrected, upper bound)

Your measured 8° falls within that range, so the radius error alone can explain the drift. Wheel wear, tire pressure, or a wrong wheel_radius parameter are the usual causes.

Step 5: Fix and verify by replay. Correct the per-wheel radius parameters, then replay the same bag through the odometry node:

ros2 bag play drift_run --clock --topics /joint_states /imu/data /tf_static
ros2 run my_robot odom_node --ros-args -p use_sim_time:=true \
  -p wheel_radius_left:=0.0330 -p wheel_radius_right:=0.0325

If the recomputed odometry yaw now tracks the gyro integral, the fix holds. You verified it without driving the robot again.

Comparison: Choosing the Right Debugging Tool

Debugging Checklist

1. Run ros2 doctor and ros2 topic hz <topic> to confirm each topic publishes at its expected rate.
2. Run ros2 topic delay <topic> on stamped messages to check transport latency.
3. Confirm use_sim_time is consistent across all nodes during replay.
4. Check QoS compatibility with ros2 topic info <topic> --verbose. A RELIABLE subscriber never connects to a BEST_EFFORT publisher.
5. Verify tf with ros2 run tf2_tools view_frames and ros2 run tf2_ros tf2_echo map base_link.
6. Capture a bag before you change anything. A fix without a recorded baseline cannot be validated.

FAQ

How do I debug a ROS 2 node that crashes without an error message?

Run it under gdb for C++ (ros2 run --prefix 'gdb -ex run --args' pkg node) or add --ros-args --log-level debug. For Python, run with python3 -X faulthandler. Check ~/.ros/log for the last lines written before the crash. A silent exit often means an uncaught exception inside a callback thread or a segfault in a native driver.

What is the difference between rosbag2 SQLite3 and MCAP storage?

SQLite3 is the older default and stores messages in a database file. MCAP is an indexed container built for robotics logging. It offers faster seeking, chunk compression, and direct support in Foxglove. Use MCAP for new recordings unless a legacy tool requires SQLite3.

Why does my rosbag replay produce tf extrapolation errors?

Nodes are mixing wall time with bag time. Start ros2 bag play with --clock and launch every consuming node with use_sim_time:=true. Also confirm that /tf_static was recorded, because a bag that starts after startup loses it.

How do I debug serial communication between ROS 2 and a microcontroller?

Capture raw bytes with a timestamped logger on the host. Add sequence numbers and checksums to the firmware protocol. Check that the data rate stays below 50% of baud / 10 bytes per second. Look for truncated lines, repeated values, and timing gaps to separate firmware faults from ROS faults.