콘솔과 로그 — 관측 가능한 ROS 2 시스템 만들기

1. 로그는 로봇의 유일한 목격자다

앞 화면에서 bag이 "메시지를 다시 보게 해 준다"고 했습니다. 그런데 bag에는 담기지 않는 것이 있습니다. 노드가 무슨 생각으로 그렇게 판단했는지입니다.

/cmd_vel에 0이 발행된 것은 bag에 남습니다. 하지만 그 이유는 남지 않습니다. 장애물을 봤기 때문인지, 목표를 다 갔기 때문인지, 파라미터가 이상해서인지, 아니면 예외가 나서 정지 명령만 나가고 있었던 것인지 알 수 없습니다.

그것을 남기는 것이 로그입니다. 그리고 로봇에서 로그는 특별한 위치를 가집니다.

① 현장에서는 디버거를 붙일 수 없다. 주행 중인 로봇에 중단점을 걸 수는 없습니다. 멈추는 순간 상황이 달라집니다. 실시간 시스템에서 유일하게 허용되는 관찰 수단이 로그입니다.

② 사고는 재현되지 않는다. "어제 창고에서 한 번 그랬다"를 조사할 수 있는 것은 그때 남은 로그뿐입니다.

③ 여러 프로세스가 동시에 돈다. 열두 개 노드가 각자 돌 때, 무슨 일이 어떤 순서로 일어났는지 재구성할 수 있는 것도 로그입니다.

그래서 로그를 잘 쓰는 것은 코딩 실력의 일부입니다. 나중에 자기 자신이 새벽 두 시에 읽을 글을 지금 쓰고 있다고 생각하세요.

개념도 · compare

• 단계/참여자
• rosbag
• 로그
• 연결/행
• 주고받은 메시지를 남긴다|판단의 이유를 남긴다
• 재생해서 다시 실험할 수 있다|사람이 읽고 해석한다
• 용량이 크다|가볍다
• 무엇이 일어났는지 알려 준다|왜 일어났는지 알려 준다

bag과 로그는 서로를 대체하지 않습니다. 무엇이 오갔는지와 왜 그랬는지는 다른 정보입니다.

2. 다섯 단계 — 무엇을 어디에 쓸 것인가

ROS 2의 로그 수준은 다섯 가지입니다. 문제는 다들 INFO만 쓴다는 것입니다. 수준을 제대로 나누면 나중에 필터링만으로 원인을 좁힐 수 있습니다.

DEBUG — 개발자가 흐름을 추적할 때만 보는 것. 변수 값, 계산 중간 결과, 콜백 진입. 평소에는 꺼 두고 문제가 생겼을 때만 켭니다. 아무리 자세히 써도 좋습니다. 어차피 평소에는 안 보이니까요.

INFO — 정상 동작 중 사람이 알아야 할 사건. 노드 시작, 목표 수락, 모드 전환, 지도 로드 완료. 기준은 "이것이 초당 여러 번 나오면 안 된다"입니다. 주기적인 센서 값을 INFO로 찍는 것은 거의 항상 잘못입니다.

WARN — 계속 동작하지만 정상은 아닌 상황. 센서 값이 잠시 끊겼다, 재시도했다, 값이 범위 경계에 있다, 성능이 목표보다 느리다. "지금은 괜찮지만 지켜봐야 한다"가 WARN입니다.

ERROR — 이 기능은 실패했지만 노드는 살아 있는 상황. 목표를 포기했다, 서비스 호출이 실패했다, 파일을 못 읽었다.

FATAL — 계속할 수 없는 상황. 곧 종료됩니다. 하드웨어 초기화 실패, 필수 설정 누락.

기본 수준은 INFO입니다. 즉 DEBUG는 평소에 안 보입니다. 그러니 DEBUG에는 마음껏 자세히 쓰세요. 실무에서 가장 아쉬운 순간은 "그때 그 값을 찍어 뒀더라면"입니다.

개념도 · stack

• 단계/참여자
• FATAL — 계속할 수 없다
• ERROR — 이 기능은 실패했다
• WARN — 괜찮지만 지켜봐야 한다
• INFO — 알아 두면 좋은 사건 (기본 경계)
• DEBUG — 개발자만 보는 상세
• 연결/행
• 가장 심각
• ``
• ``
• 여기까지 기본 출력
• 기본은 숨겨짐

설정한 수준보다 낮은 것은 출력되지 않습니다. 기본값은 INFO입니다.

3. 로그 폭주를 막는 세 가지 장치

로그를 망치는 가장 흔한 실수는 콜백 안에서 그냥 찍는 것입니다.

라이다 콜백이 10 Hz면 로그도 10 Hz입니다. 노드 다섯 개가 그렇게 하면 초당 50줄입니다. 터미널은 흘러가 버리고, 정작 중요한 ERROR 한 줄이 그 홍수에 묻힙니다. 게다가 로깅 자체가 CPU와 디스크를 먹어 로그 때문에 로봇이 느려지는 일까지 생깁니다.

rclpy는 이것을 막을 장치를 갖고 있습니다.

① throttle_duration_sec — 이 시간 안에는 한 번만 찍습니다. 주기적으로 발생하는 경고에 필수입니다. self.get_logger().warn("센서 지연", throttle_duration_sec=2.0)

② once=True — 딱 한 번만 찍습니다. "이 기능은 더 이상 쓰지 않습니다" 같은 안내에 씁니다.

③ skip_first=True — 첫 번째는 건너뜁니다. 시작 직후 한 번은 정상적으로 실패하는 경우(아직 상대 노드가 안 뜬 상황 등)에 유용합니다.

상태 전이에서만 찍는 방법 더 좋은 방법이 있습니다. 값이 바뀔 때만 찍는 것입니다. "장애물 감지됨"을 매 스캔마다 찍는 대신, 감지 상태가 없음에서 있음으로 바뀌는 순간에만 찍습니다. 이렇게 하면 로그가 그대로 사건의 연대기가 됩니다.

한 가지 더: 로그 문자열은 출력되지 않더라도 인자 계산은 일어납니다. DEBUG가 꺼져 있어도 f"{expensive_calculation()}"은 실행됩니다. 무거운 계산이 들어간다면 if self.get_logger().is_enabled_for(...)로 감싸세요.

throttle, 상태 전이 로깅, 주기 요약을 갖춘 실전 로깅. 시작 로그에 설정을 남기는 것도 요령입니다.

#!/usr/bin/env python3
# 로그를 제대로 쓰는 노드.
# throttle, once, 상태 전이 로깅, 구조화된 메시지를 모두 보여 준다.

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

STOP_DISTANCE = 0.4


class LoggingGuard(Node):
    def __init__(self):
        super().__init__("logging_guard")

        self.blocked = False          # 상태 전이 로깅을 위한 이전 상태
        self.scan_count = 0
        self.last_scan_time = None

        self.pub = self.create_publisher(Twist, "cmd_vel", 10)
        self.create_subscription(LaserScan, "scan", self.on_scan, 10)
        self.create_timer(5.0, self.report)

        # 시작 로그에는 "무엇을 어떤 설정으로 시작했는지"를 남긴다.
        # 나중에 로그만 보고 그때의 구성을 재구성할 수 있어야 한다.
        self.get_logger().info(
            f"logging_guard 시작 — stop_distance={STOP_DISTANCE} m, "
            f"구독=/scan, 발행=/cmd_vel")

    def on_scan(self, msg: LaserScan):
        self.scan_count += 1
        now = self.get_clock().now()

        # (1) 주기적인 상세는 DEBUG. 평소에는 보이지 않으므로 마음껏 자세히.
        self.get_logger().debug(
            f"scan #{self.scan_count} 빔={len(msg.ranges)} "
            f"frame={msg.header.frame_id}")

        # (2) 주기적으로 발생할 수 있는 경고에는 반드시 throttle 을 건다.
        if self.last_scan_time is not None:
            gap_ms = (now - self.last_scan_time).nanoseconds / 1e6
            if gap_ms > 150.0:
                self.get_logger().warn(
                    f"스캔 간격이 {gap_ms:.0f} ms 로 벌어졌습니다 (기대 100 ms)",
                    throttle_duration_sec=2.0)
        self.last_scan_time = now

        valid = [r for r in msg.ranges if r > 0.0]
        if not valid:
            # 유효한 값이 하나도 없다 — 센서 이상 신호다.
            self.get_logger().error(
                "스캔에 유효한 거리 값이 없습니다. 센서 연결을 확인하세요.",
                throttle_duration_sec=5.0)
            return

        nearest = min(valid)
        blocked_now = nearest < STOP_DISTANCE

        # (3) 상태가 "바뀔 때만" 찍는다. 로그가 사건의 연대기가 된다.
        if blocked_now != self.blocked:
            if blocked_now:
                self.get_logger().warn(
                    f"장애물 감지 — 최근접 {nearest:.2f} m, 정지합니다")
            else:
                self.get_logger().info(
                    f"경로가 열렸습니다 — 최근접 {nearest:.2f} m, 주행을 재개합니다")
            self.blocked = blocked_now

        cmd = Twist()
        cmd.linear.x = 0.0 if blocked_now else 0.25
        self.pub.publish(cmd)

    def report(self):
        # (4) 주기적인 요약은 낮은 빈도의 INFO 로. 살아 있음을 알리는 심박이다.
        self.get_logger().info(
            f"상태 요약 — 스캔 {self.scan_count} 건 처리, "
            f"현재 {'정지' if self.blocked else '주행'}")


def main():
    rclpy.init()
    node = LoggingGuard()
    try:
        rclpy.spin(node)
    except KeyboardInterrupt:
        node.get_logger().info("사용자 중단으로 종료합니다")
    finally:
        node.destroy_node()
        rclpy.shutdown()


if __name__ == "__main__":
    main()

주의 콜백 안에서 조건 없이 로그를 찍으면 콜백 주파수만큼 로그가 쏟아집니다. 중요한 ERROR 한 줄이 그 홍수에 묻히고, 로깅 자체가 CPU와 디스크를 먹어 로봇이 느려지기까지 합니다. 주기적으로 발생할 수 있는 로그에는 반드시 throttle을 거세요.

4. 로그는 어디로 가는가

get_logger().info()의 목적지는 실행 방식과 Logging 구성에 따라 달라집니다. 일반적인 ROS 2 Node는 Console에 출력하고 /rosout으로도 Log Message를 발행합니다. 파일은 특히 ros2 launch가 Process 출력과 Launch Event를 실행별 Directory에 저장할 때 생성됩니다. 따라서 “한 줄이 언제나 세 곳에 동일하게 저장된다”고 가정하지 말고 현재 실행 방식과 설정을 확인해야 합니다.

① 표준 출력 (터미널) 가장 익숙한 곳입니다. Launch에서는 output="screen", output="log", output="both"처럼 목적지를 명시할 수 있으며 기본값에 의존하지 않는 편이 좋습니다. emulate_tty=True는 TTY가 아닌 Capture 환경에서 줄 단위 출력과 색상 동작을 개선할 때 사용합니다.

② /rosout 토픽 기본 구성을 사용하는 ROS Node의 로그가 하나의 토픽으로 모입니다. 타입은 rcl_interfaces/msg/Log입니다. Node 생성 옵션이나 Logging 설정으로 rosout Publisher를 끌 수 있으므로 모든 Process Log가 무조건 들어온다고 단정할 수는 없습니다. 이것이 중요한 이유는 두 가지입니다. • 다른 컴퓨터에서 원격으로 전체 로그를 볼 수 있다 • ros2 bag record /rosout으로 로그까지 함께 기록할 수 있다

ros2 topic echo /rosout으로 직접 볼 수 있고, rqt_console을 쓰면 수준별 필터와 검색이 되는 GUI로 볼 수 있습니다. 노드가 열두 개일 때는 이것이 훨씬 편합니다.

③ 파일 ~/.ros/log/ 특히 ros2 launch를 실행하면 실행별 Folder와 latest Link가 생기며 Launch가 Capture한 Process Output이 남습니다. ros2 run으로 직접 실행한 모든 Log가 자동으로 같은 형태의 파일에 저장된다고 가정해서는 안 됩니다. 현장에서는 실제 Log Directory와 Service Manager Journal을 함께 확인합니다.

주의: 이 폴더는 자동으로 지워지지 않습니다. 장기 운용하는 로봇에서는 디스크가 서서히 차오릅니다. 정리 정책을 세우거나 ROS_LOG_DIR로 위치를 옮겨 관리하세요.

개념도 · flow

• 단계/참여자
• get_logger().info()
• 표준 출력 — 지금 보는 터미널
• /rosout 토픽 — 원격·기록
• ~/.ros/log/ 파일 — 사후 조사
• 연결/행
• 한 번 호출하면
• 개발 중
• 운용 중
• 사고 후

한 줄의 로그가 가는 세 갈래. 상황에 따라 볼 곳이 다릅니다.

5. 수준과 형식을 바꾸는 법

실행할 때 수준 지정하기 --ros-args --log-level DEBUG를 붙이면 그 프로세스 전체가 DEBUG까지 출력합니다. 특정 노드만 올리고 싶다면 --log-level 노드이름:=DEBUG처럼 씁니다. 전체를 DEBUG로 켜면 대개 읽을 수 없을 만큼 쏟아지므로, 의심되는 노드만 지정하는 습관이 좋습니다.

실행 중에 바꾸기 Logger Level Service가 활성화된 Node는 ros2 service call /노드이름/set_logger_levels ...로 재시작하지 않고 수준을 바꿀 수 있습니다. rclpy에서는 Node 생성 시 enable_logger_service=True를 지정하는 방식처럼 Client Library별 활성화 방법을 확인해야 합니다. Service가 없는 Node에 명령만 보내도 동작하지 않습니다. 운영 Network에서 누가 수준을 바꿀 수 있는지도 통제해야 합니다.

출력 형식 바꾸기 기본 Console 형식에는 일반적으로 Severity, Timestamp와 Logger 이름이 포함되지만 Source 파일·함수·줄 번호나 팀이 정한 Event Field는 없습니다. RCUTILS_CONSOLE_OUTPUT_FORMAT 환경변수로 필요한 Context를 추가할 수 있으며, Format 변경이 중앙 Parser에 미치는 영향도 함께 확인합니다.

쓸 수 있는 항목: {severity} {time} {name} {message} {function_name} {file_name} {line_number}

색과 버퍼링 RCUTILS_COLORIZED_OUTPUT=1은 Colorized Console 출력을 강제할 때 사용할 수 있습니다. RCUTILS_LOGGING_BUFFERED_STREAM은 Console Stream의 Buffering 동작을 제어합니다. 충돌 직전 Log 유실을 줄이는 설정은 유용하지만 I/O 비용이 커질 수 있으므로 목표 배포판의 rcutils 동작을 확인하고 부하 시험 후 적용합니다. 강제 전원 차단까지 완전히 보장하는 설정은 아닙니다.

요점

• 전체 DEBUG는 대개 읽을 수 없다. 의심되는 노드만 지정한다.
• Logger Level Service가 활성화된 Node는 재시작 없이 수준을 올릴 수 있다.
• 출력 형식에 필요한 Source 위치와 Context가 없다면 환경변수로 추가한다.
• 충돌을 쫓을 때는 Buffering 정책과 I/O 부하를 함께 검증한다.
• /rosout을 bag에 함께 기록하면 사후 조사가 훨씬 쉬워진다.

로그 수준·형식·목적지를 다루는 명령 모음. 3번의 출력 형식 설정은 개발 초기에 해 두세요.

# ── 1) 실행할 때 로그 수준 지정 ─────────────────────────
ros2 run my_pkg my_node --ros-args --log-level DEBUG

# 특정 노드만 올리기 (전체 DEBUG 는 대개 읽을 수 없다)
ros2 run my_pkg my_node --ros-args --log-level logging_guard:=DEBUG

# launch 에서
#   Node(package="my_pkg", executable="my_node",
#        arguments=["--ros-args", "--log-level", "DEBUG"])


# ── 2) 실행 중에 바꾸기 (노드를 멈추지 않는다) ────────────
ros2 service call /logging_guard/set_logger_levels \
  rcl_interfaces/srv/SetLoggerLevels \
  "{levels: [{name: 'logging_guard', level: 10}]}"
# 수준 값: DEBUG=10, INFO=20, WARN=30, ERROR=40, FATAL=50


# ── 3) 출력 형식을 쓸 만하게 바꾸기 ──────────────────────
# Source 위치까지 필요한 개발 환경에서는 Format에 명시한다.
export RCUTILS_CONSOLE_OUTPUT_FORMAT="[{severity}] [{time}] [{name}]: {message} ({function_name}() at {file_name}:{line_number})"

# 파이프로 넘겨도 색을 유지
export RCUTILS_COLORIZED_OUTPUT=1

# Buffering 정책 지정 — 목표 배포판에서 유실과 I/O 부하를 시험한다
export RCUTILS_LOGGING_BUFFERED_STREAM=0


# ── 4) 전체 로그를 한곳에서 보기 ─────────────────────────
ros2 topic echo /rosout                      # rosout이 활성화된 ROS Node 로그
ros2 run rqt_console rqt_console             # 수준 필터와 검색이 되는 GUI

# 로그까지 함께 기록해 두면 사후 조사가 훨씬 쉬워진다
ros2 bag record -o run_with_logs /scan /odom /cmd_vel /rosout


# ── 5) 파일로 남은 로그 뒤지기 ──────────────────────────
ls -lt ~/.ros/log/ | head              # 최근 실행 순
tail -f ~/.ros/log/latest/launch.log   # 실시간으로 따라가기

# 여러 노드의 ERROR 만 골라 시간순으로 보기
grep -rh "ERROR" ~/.ros/log/latest/ | sort

# 로그 위치를 옮겨 관리하기 (장기 운용 시 디스크가 찬다)
export ROS_LOG_DIR=/data/roslogs

6. 좋은 로그와 나쁜 로그

나쁜 로그의 전형

"here", "ok", "실패", "값: 3" — 나중에 읽으면 아무 의미가 없습니다. 어디의 무엇이 왜 그랬는지가 없습니다.

"오류 발생" — 무슨 오류인지, 어떤 입력에서인지, 그래서 어떻게 했는지가 없습니다.

좋은 로그의 세 가지 조건

① 무엇이 일어났는가 + 어떤 값에서 + 그래서 무엇을 했는가 나쁨: "장애물 감지" 좋음: "장애물 감지 — 최근접 0.28 m (기준 0.40 m), 정지 명령 발행"

② 실패 로그에는 다음 행동을 적는다 나쁨: "서비스 호출 실패" 좋음: "set_mode 호출 3초 타임아웃 — 재시도 2/3. ros2 service list 로 서버 확인 필요"

③ 시작 로그에 설정을 남긴다 노드가 뜰 때 주요 파라미터를 한 줄로 남기세요. 나중에 로그만 보고 그때 어떤 설정으로 돌고 있었는지 알 수 있습니다. 이것 하나로 해결되는 사건이 놀랄 만큼 많습니다.

실전 진단 흐름 무언가 이상할 때 로그를 쓰는 순서입니다. ① ~/.ros/log/latest/에서 ERROR와 FATAL만 먼저 훑는다 ② 그 시각 직전의 WARN을 본다. 원인은 대개 결과보다 먼저 나타난다 ③ 관련 노드의 시작 로그를 보고 설정을 확인한다 ④ 의심되는 노드만 DEBUG로 올려 다시 돌린다 ⑤ 재현이 어렵다면 /rosout을 bag에 담아 다음 발생을 기다린다

마지막으로: 로그는 사용자를 위한 것이 아니라 미래의 자신을 위한 것입니다. 지금은 뻔해 보이는 맥락이 3개월 뒤에는 전혀 뻔하지 않습니다.

7. Python Logger API를 빠르게 읽는다

다음 Node는 모든 Severity, Exception Context, Throttle과 Logger Service를 한곳에 모은 최소 예제입니다.

#!/usr/bin/env python3
import math

import rclpy
from rclpy.node import Node
from rclpy.logging import LoggingSeverity
from sensor_msgs.msg import BatteryState


class BatteryMonitor(Node):
    def __init__(self):
        super().__init__('battery_monitor', enable_logger_service=True)

        self.declare_parameter('warn_voltage', 22.0)
        self.declare_parameter('error_voltage', 20.5)
        self.warn_voltage = float(self.get_parameter('warn_voltage').value)
        self.error_voltage = float(self.get_parameter('error_voltage').value)
        self.previous_state = 'unknown'
        self.count = 0

        self.subscription = self.create_subscription(
            BatteryState, '/battery_state', self.on_battery, 10)
        self.report_timer = self.create_timer(30.0, self.report)

        self.get_logger().info(
            'event=node_started '
            f'warn_voltage={self.warn_voltage:.2f} '
            f'error_voltage={self.error_voltage:.2f}')

    def on_battery(self, msg: BatteryState):
        self.count += 1
        voltage = float(msg.voltage)

        if not math.isfinite(voltage):
            self.get_logger().error(
                'event=invalid_battery_voltage action=ignore_sample',
                throttle_duration_sec=5.0)
            return

        if voltage <= self.error_voltage:
            state = 'critical'
        elif voltage <= self.warn_voltage:
            state = 'low'
        else:
            state = 'normal'

        if state != self.previous_state:
            log = self.get_logger()
            message = (
                f'event=battery_state_changed from={self.previous_state} '
                f'to={state} voltage_v={voltage:.2f}')
            if state == 'critical':
                log.error(message + ' action=request_safe_stop')
            elif state == 'low':
                log.warn(message + ' action=return_to_charger')
            else:
                log.info(message + ' action=continue')
            self.previous_state = state

        # DEBUG가 켜졌을 때만 상세 문자열과 계산을 준비한다.
        if self.get_logger().is_enabled_for(LoggingSeverity.DEBUG):
            percentage = float(msg.percentage) * 100.0
            self.get_logger().debug(
                f'event=battery_sample voltage_v={voltage:.3f} '
                f'percentage={percentage:.1f} sample={self.count}')

    def report(self):
        self.get_logger().info(
            f'event=health_summary samples={self.count} '
            f'battery_state={self.previous_state}')


def main(args=None):
    rclpy.init(args=args)
    node = BatteryMonitor()
    try:
        rclpy.spin(node)
    except KeyboardInterrupt:
        node.get_logger().info('event=shutdown reason=keyboard_interrupt')
    except Exception:
        node.get_logger().fatal(
            'event=unhandled_exception action=shutdown',
            exc_info=True)
        raise
    finally:
        node.destroy_node()
        rclpy.shutdown()


if __name__ == '__main__':
    main()

코드 빠른 해석

event=... key=value 형식은 완전한 JSON은 아니지만 사람이 읽기 쉽고 rg, awk, Log 수집기에서 Field를 추출하기도 쉽습니다. Message 문장 전체를 자유롭게 바꾸는 대신 event 이름과 핵심 Key를 안정적으로 유지하면 Dashboard와 Alert가 깨지지 않습니다.

exc_info=True는 예외 Type과 Stack Trace를 남겨 “무엇이 실패했는가”뿐 아니라 “어디서 호출되어 왔는가”를 보여 줍니다. 다만 Stack Trace에 경로와 입력값이 포함될 수 있으므로 외부 공개 전에 검토합니다.

8. Launch에서 로그 수준과 목적지를 관리한다

여러 Node를 띄울 때 각각 Terminal 명령을 관리하지 말고 Launch Argument로 관찰 강도를 선택합니다.

from launch import LaunchDescription
from launch.actions import DeclareLaunchArgument, SetEnvironmentVariable
from launch.substitutions import LaunchConfiguration
from launch_ros.actions import Node


def generate_launch_description():
    log_level = LaunchConfiguration('log_level')

    return LaunchDescription([
        DeclareLaunchArgument('log_level', default_value='info'),
        SetEnvironmentVariable(
            'RCUTILS_CONSOLE_OUTPUT_FORMAT',
            '[{severity}] [{time}] [{name}] {message}'),

        Node(
            package='robot_monitor',
            executable='battery_monitor',
            name='battery_monitor',
            output='both',
            emulate_tty=True,
            arguments=['--ros-args', '--log-level', log_level],
            parameters=[{
                'warn_voltage': 22.0,
                'error_voltage': 20.5,
            }],
        ),
    ])

# 평상시 운영
ros2 launch robot_monitor monitor.launch.py log_level:=info

# 재현 시험에서만 상세 관찰
ros2 launch robot_monitor monitor.launch.py log_level:=debug

# Launch가 만든 최근 실행 Directory 확인
printenv ROS_LOG_DIR
ls -la ~/.ros/log/latest

output='both'는 Console과 Launch Log를 함께 원할 때 명시합니다. 다만 동일 Message가 Container Runtime, systemd Journal과 별도 수집 Agent에 중복 저장될 수 있으므로 Production에서는 최종 수집 경로를 하나의 설계도로 정리해야 합니다.

9. 여러 Node의 사건을 연결하는 Correlation ID

Robot의 한 임무는 Goal Manager, Planner, Controller와 Driver를 거칩니다. 각 Node가 “시작”, “실패”만 남기면 어떤 시작과 어떤 실패가 같은 임무인지 알 수 없습니다. Goal마다 mission_id 또는 trace_id를 만들고 모든 관련 Log에 전달합니다.

time=10.120 node=mission event=goal_accepted mission_id=M-0042 goal=dock
time=10.153 node=planner event=plan_started mission_id=M-0042 map=warehouse-a
time=10.482 node=planner event=plan_ready mission_id=M-0042 length_m=18.4
time=12.104 node=controller event=tracking_degraded mission_id=M-0042 cross_track_m=0.31
time=12.230 node=safety event=safe_stop mission_id=M-0042 reason=obstacle distance_m=0.28

이제 mission_id=M-0042만 검색해 Node 경계를 넘어 사건 순서를 복원할 수 있습니다. Correlation ID는 Topic Header의 Frame ID처럼 다른 의미의 Field에 억지로 넣지 말고 Custom Message Field, Goal ID 또는 공통 Context 구조로 전달합니다.

10. Log와 Diagnostics와 Metric을 구분한다

세 관측 수단은 서로 대체하지 않습니다.

10 Hz Sensor 주기를 Log 10줄로 남기는 대신 Metric Counter와 Summary를 사용합니다. 현재 고장 상태는 diagnostic_msgs/DiagnosticArray, 판단의 전환점은 Log, 실제 Data는 Bag에 담는 식으로 역할을 나눕니다.

11. 성능과 Disk 용량을 설계한다

Log 한 줄도 Format, Lock, Console Rendering, /rosout Publish와 Disk Write 비용을 만듭니다. 특히 큰 문자열과 Stack Trace를 고주파 Callback에서 남기면 제어 Jitter가 커질 수 있습니다.

용량을 미리 계산한다

평균 220 Byte Log가 초당 50줄씩 발생하면 Payload만 하루 약 다음 크기입니다.

220 byte × 50 line/s × 86,400 s/day
= 950,400,000 byte/day
≈ 0.95 GB/day

Metadata와 File System Overhead, 압축 여부를 더하면 실제 크기는 달라집니다. Robot 여러 대라면 보존 기간을 곱해 Storage를 설계합니다.

# 현재 ROS Log 사용량
du -sh ~/.ros/log
du -h ~/.ros/log/* | sort -h | tail

# 최근 Launch Log에서 Severity별 개수
rg -o '\[(DEBUG|INFO|WARN|ERROR|FATAL)\]' ~/.ros/log/latest \
  | sort | uniq -c

# 1초에 몇 줄 발생하는지 간단히 관찰
ros2 topic hz /rosout

Production에서는 journald, logrotate, Container Runtime 또는 중앙 수집기의 크기·기간 제한을 사용합니다. 삭제 명령을 주기적으로 무조건 실행하기보다 “최대 용량, 최대 기간, 최소 보존 사고 Log, Upload 완료 확인” 정책을 정합니다.

12. 개인정보와 기밀정보를 로그에 남기지 않는다

Log는 개발자의 Memo가 아니라 운영 Data입니다. 다음 정보는 원문 기록을 피하거나 Masking합니다.

• Password, API Key, Access Token, 인증 Header
• 사람 이름, 전화번호, 이메일과 얼굴 인식 결과
• 정확한 집 주소, GPS 위치와 이동 경로
• 내부 Server URL, Device Secret과 Certificate 내용
• 전체 Camera Frame, 음성 Transcript와 사용자 입력

# 나쁨: Credential과 사용자 식별정보 노출
self.get_logger().error(
    f'login failed token={token} email={email} response={body}')

# 개선: 조사에 필요한 비식별 Context만 남김
self.get_logger().error(
    f'event=login_failed user_hash={user_hash[:8]} '
    f'http_status={status} request_id={request_id}')

Hash도 원본 후보가 좁으면 다시 추정될 수 있습니다. 보존 기간, 접근 권한, 전송 암호화, 삭제 요청과 외부 반출 절차까지 Log 정책에 포함합니다.

13. 실제 Robot 장애 진단 Runbook

1단계: 시간을 맞춘다

여러 Computer의 System Clock이 다르면 사건 순서를 재구성할 수 없습니다. NTP/PTP 상태, ROS Time 사용 여부, Timezone과 Format을 확인합니다.

date --iso-8601=ns
timedatectl status
ros2 param get /target_node use_sim_time

2단계: 결과부터 찾고 직전 원인을 본다

ERROR·FATAL 시각을 찾은 뒤 바로 앞 WARN과 상태 전이를 봅니다. 마지막 Error만 복사하면 진짜 원인인 Network 지연이나 Sensor Stale Warning을 놓칠 수 있습니다.

rg -n 'ERROR|FATAL' ~/.ros/log/latest
rg -n -C 20 'event=safe_stop' ~/.ros/log/latest

3단계: 실행 구성을 복원한다

Software Commit, ROS Distribution, RMW, Domain ID, Parameter File, Launch Argument와 장비 ID를 확인합니다.

printenv ROS_DISTRO RMW_IMPLEMENTATION ROS_DOMAIN_ID
ros2 param dump /target_node
ros2 node info /target_node

4단계: 의심 Node만 관찰 강도를 높인다

전체 System을 DEBUG로 바꾸면 Timing이 달라지고 원인이 사라질 수 있습니다. 한 Logger만 올리고 제한된 시간 동안 재현합니다.

5단계: Log와 Bag을 같은 시간축에서 본다

ros2 bag record -o incident_001 \
  /rosout /diagnostics /tf /tf_static /scan /odom /cmd_vel

Incident Folder에는 Bag, Launch Log, Parameter Dump, System 상태와 짧은 현장 Memo를 함께 보관합니다. 그래야 “무엇이 오갔고, 왜 판단했고, 어떤 구성에서 발생했는가”를 한 번에 복원할 수 있습니다.

14. 확인 퀴즈 15문항

1. bag이 있는데도 로그가 따로 필요한 이유는?

• (1) bag보다 용량이 작기 때문
• (2) bag은 무엇이 오갔는지를 남기지만 노드가 왜 그렇게 판단했는지는 로그에만 남기 때문 정답
• (3) 로그가 더 빠르기 때문
• (4) bag은 재생할 수 없기 때문

해설: /cmd_vel에 0이 발행된 사실은 bag에 남지만, 장애물 때문인지 목표 도달 때문인지 예외 때문인지는 남지 않습니다. 판단의 이유를 남기는 것은 로그뿐이며, 그래서 둘은 서로를 대체하지 않고 함께 봐야 합니다.

2. ROS 2 로그의 기본 출력 수준은?

• (1) DEBUG
• (2) INFO 정답
• (3) WARN
• (4) ERROR

해설: 기본값이 INFO이므로 DEBUG는 평소에 출력되지 않습니다. 이것은 오히려 좋은 소식입니다. DEBUG에는 변수 값이나 계산 중간값을 마음껏 자세히 남겨 두었다가, 문제가 생겼을 때만 수준을 올려 확인하면 되기 때문입니다.

3. "센서 값이 잠시 끊겼지만 재시도해서 계속 동작 중"인 상황에 알맞은 수준은?

• (1) DEBUG
• (2) INFO
• (3) WARN 정답
• (4) FATAL

해설: WARN은 "지금은 괜찮지만 지켜봐야 한다"를 뜻합니다. 동작은 계속되므로 ERROR가 아니고, 정상 상태도 아니므로 INFO가 아닙니다. 이런 상황은 주기적으로 반복될 수 있으므로 반드시 throttle을 함께 걸어야 합니다.

4. 10 Hz 라이다 콜백 안에서 조건 없이 로그를 찍으면 생기는 문제가 아닌 것은?

• (1) 중요한 ERROR가 로그 홍수에 묻힌다
• (2) 로깅 자체가 CPU와 디스크를 먹어 로봇이 느려질 수 있다
• (3) 터미널이 흘러가 버려 관찰이 어렵다
• (4) 메시지 타입이 바뀐다 정답

해설: 로깅은 메시지 타입과 아무 관련이 없습니다. 실제 문제는 중요한 로그가 묻히는 것, 터미널을 읽을 수 없게 되는 것, 그리고 로깅 비용 자체가 시스템을 느리게 만드는 것입니다. 그래서 throttle이나 상태 전이 로깅이 필요합니다.

5. throttle_duration_sec=2.0 을 주면 어떻게 되는가?

• (1) 2초 뒤에 한 번만 출력된다
• (2) 2초 안에는 한 번만 출력된다 정답
• (3) 출력이 2초 지연된다
• (4) 2초마다 로그 파일이 바뀐다

해설: 같은 지점의 로그가 그 시간 안에 여러 번 발생해도 한 번만 출력됩니다. 콜백 주파수만큼 쏟아지는 경고를 사람이 읽을 수 있는 빈도로 줄여 주며, 주기적으로 발생할 수 있는 WARN과 ERROR에는 사실상 필수입니다.

6. "장애물 감지됨"을 매 스캔마다 찍는 대신 권장되는 방식은?

• (1) 로그 수준을 DEBUG로 내린다
• (2) 감지 상태가 바뀌는 순간에만 찍어 로그를 사건의 연대기로 만든다 정답
• (3) 로그를 아예 없앤다
• (4) 파일에만 기록한다

해설: 상태 전이에서만 찍으면 "언제 막혔고 언제 풀렸는가"가 로그에 그대로 남아 사건의 흐름을 읽을 수 있습니다. 매번 찍는 방식은 같은 정보를 수백 번 반복할 뿐이며 정작 변화의 순간을 찾기 어렵게 만듭니다.

7. DEBUG가 꺼져 있어도 주의해야 할 점은?

• (1) 로그 파일은 여전히 커진다
• (2) 출력은 되지 않아도 문자열에 넣은 계산은 실행된다 정답
• (3) /rosout에는 그대로 나간다
• (4) CPU 사용량이 오히려 늘어난다

해설: 로그 함수를 부르기 전에 인자가 먼저 평가되므로, 무거운 계산을 문자열에 넣으면 출력되지 않아도 비용이 발생합니다. 비싼 계산이 필요하다면 해당 수준이 켜져 있는지 먼저 확인하고 감싸는 것이 안전합니다.

8. 기본 rosout 구성을 사용하는 ROS Node의 로그가 모이는 토픽은?

• (1) /log
• (2) /rosout 정답
• (3) /diagnostics
• (4) /console

해설: /rosout에는 rcl_interfaces/msg/Log 타입으로 rosout이 활성화된 ROS Node의 로그가 모입니다. 다른 컴퓨터에서 원격으로 보거나 Bag에 기록할 수 있고 rqt_console은 수준별 Filter와 검색 기능을 제공합니다.

9. 터미널을 닫은 뒤에도 로그가 남아 있는 곳은?

• (1) /tmp/ros
• (2) ~/.ros/log/ 정답
• (3) /var/log/ros
• (4) 현재 작업 디렉터리

해설: 특히 ros2 launch 실행은 ~/.ros/log/ 아래 실행별 Folder에 Capture한 출력을 남깁니다. 직접 실행한 Process는 Supervisor나 Shell Redirection 등 실제 실행 구성을 확인해야 하며 장기 운용에는 별도 보존 정책이 필요합니다.

10. 특정 노드만 DEBUG로 올리는 실행 옵션은?

• (1) --ros-args --log-level DEBUG
• (2) --ros-args --log-level 노드이름:=DEBUG 정답
• (3) --ros-args --debug 노드이름
• (4) --ros-args -p log_level:=DEBUG

해설: 노드 이름을 앞에 붙이면 그 노드만 수준이 올라갑니다. 전체를 DEBUG로 켜면 대개 읽을 수 없을 만큼 로그가 쏟아지므로, 의심되는 노드만 지정하는 습관이 진단 시간을 크게 줄여 줍니다.

11. 노드를 재시작하지 않고 로그 수준을 올리는 방법은?

• (1) 환경변수를 다시 설정한다
• (2) set_logger_levels 서비스를 호출한다 정답
• (3) 로그 파일을 지운다
• (4) QoS를 변경한다

해설: Logger Level Service를 활성화한 Node는 set_logger_levels로 실행 중 수준을 바꿀 수 있습니다. 먼저 Service 존재와 Client Library 설정을 확인하고 운영 환경에서는 호출 권한을 통제해야 합니다.

12. RCUTILS_CONSOLE_OUTPUT_FORMAT을 설정하는 주된 이유는?

• (1) 로그 용량을 줄이려고
• (2) 팀에 필요한 Source 위치와 일관된 Context 형식으로 바꿔 사후 조사를 쉽게 하려고 정답
• (3) 색을 없애려고
• (4) 로그 수준을 바꾸려고

해설: 기본 형식은 Severity, Time과 Logger 이름을 제공하지만 Source 위치와 팀별 Context 요구는 다릅니다. {file_name}, {function_name}, {line_number} 등을 필요에 따라 넣되 중앙 수집 Parser와 성능을 함께 검증합니다.

13. 노드가 죽는 순간의 마지막 로그를 잃지 않으려면?

• (1) RCUTILS_COLORIZED_OUTPUT=1
• (2) RCUTILS_LOGGING_BUFFERED_STREAM=0 으로 버퍼링을 끈다 정답
• (3) 로그 수준을 FATAL로 올린다
• (4) ROS_LOG_DIR을 바꾼다

해설: 버퍼링이 켜져 있으면 아직 기록되지 않은 내용이 버퍼에 남은 채 프로세스가 죽어 마지막 몇 줄이 사라질 수 있습니다. 하필 그 몇 줄이 원인인 경우가 많으므로, 충돌을 쫓고 있다면 버퍼링을 꺼야 합니다.

14. 좋은 로그의 조건으로 가장 적절한 것은?

• (1) 가능한 한 짧게 쓴다
• (2) 무엇이 일어났는지, 어떤 값에서인지, 그래서 무엇을 했는지를 함께 적는다 정답
• (3) 모두 ERROR 수준으로 통일한다
• (4) 영어로만 쓴다

해설: "장애물 감지"보다 "장애물 감지 — 최근접 0.28 m (기준 0.40 m), 정지 명령 발행"이 훨씬 유용합니다. 값과 기준과 대응이 함께 있으면 로그 한 줄만으로 판단의 근거를 재구성할 수 있어 재현 없이도 원인을 좁힐 수 있습니다.

15. 로그로 문제를 진단할 때 권장되는 순서는?

• (1) 처음부터 전부 정독한다
• (2) ERROR와 FATAL을 먼저 훑고 그 직전의 WARN을 본 뒤 시작 로그의 설정을 확인한다 정답
• (3) DEBUG부터 켜고 처음부터 다시 돌린다
• (4) 로그 파일 크기를 비교한다

해설: 원인은 대개 결과보다 먼저 나타나므로 ERROR 시각 직전의 WARN이 결정적 단서인 경우가 많습니다. 그다음 시작 로그로 그때의 설정을 확인하고, 그래도 모르겠을 때 의심되는 노드만 DEBUG로 올려 다시 돌리는 것이 가장 빠른 경로입니다.

연습 문제

1. rosbag2, Log, Diagnostics와 Metric이 각각 답하는 질문을 설명하세요.
2. DEBUG·INFO·WARN·ERROR·FATAL을 Battery Monitor 상황에 맞춰 구분하세요.
3. 고주파 Callback에서 조건 없는 INFO가 Robot 동작에 미치는 영향을 설명하세요.
4. Throttle, Once와 상태 전이 Log를 각각 어떤 상황에 사용하나요?
5. 좋은 사건 Log에 포함해야 할 Context Field를 쓰세요.
6. Console, /rosout, Launch Log와 systemd Journal의 차이를 설명하세요.
7. Logger Level Service 사용 전에 확인해야 할 사항은 무엇인가요?
8. RCUTILS_CONSOLE_OUTPUT_FORMAT에 시간·Logger 이름·Severity를 넣어야 하는 이유를 설명하세요.
9. DEBUG가 꺼졌는데도 무거운 문자열 계산이 성능을 낮출 수 있는 이유와 방지 방법을 쓰세요.
10. Launch에서 output, emulate_tty와 Node별 Log Level을 구성하는 방법을 설명하세요.
11. Correlation ID가 여러 Node의 장애 조사에 필요한 이유는 무엇인가요?
12. 평균 300 Byte Log가 초당 20줄 발생할 때 하루 Payload 용량을 계산하세요.
13. Log에 남기면 안 되는 개인정보·기밀정보와 안전한 대체 Field를 예로 드세요.
14. 여러 Computer의 Clock이 맞지 않으면 Log 분석에 어떤 문제가 생기나요?
15. 실제 Robot 사고 후 Log·Bag·Parameter를 이용한 표준 진단 순서를 설명하세요.

참고 자료

• ROS 2 Logging 개념
• Logging and logger configuration
• rclpy.logging API
• rclpy Node API
• rqt_console 사용법
• ROS 2 Launch의 Event Handler