에러 메시지와 스택 트레이스 읽는 법 입문

시리즈: 테스트·디버깅 강좌 1/6 (초급). 빨간 글자가 화면을 채우는 순간 손이 멈추는 신입 개발자를 위한 글입니다. 다 읽으면 Python, PHP, JavaScript, Java, Dart, Swift, C 의 에러 보고에서 '봐야 할 한 줄'을 찾고, 답이 나오는 방식으로 검색할 수 있습니다.

신입 온보딩 첫 주에 사수에게 "안 돼요"라고 묻기 전에, 그리고 코드 리뷰에서 "이거 왜 터졌는지 확인했어요?"라는 질문을 받기 전에 갖춰야 할 기술입니다. 스택 트레이스는 잡음이 아니라, 프로그램이 포기한 순간 '어디에 있었는지'를 정확히 알려 주는 기록입니다. 골치 아픈 점은 언어마다 출력 순서도, "이 예외는 저 예외 때문"이라는 표현도 다르고, 내 코드와 상관없는 줄이 잔뜩 섞여 있다는 것입니다.

아래는 모두 Apple Silicon Mac(M1 Pro)에서 실제로 실행했습니다. Python 3.9.6, PHP 8.5.6, JavaScriptCore(macOS 에 들어 있는 jsc), OpenJDK 26, Dart 3.11.5, Swift 6.4.2, Apple clang 21 입니다. 홈 디렉터리 경로는 ~/demo/ 로 줄였고, 그 밖에 손댄 곳은 … 로 표시했습니다.

5분 만에 읽는 첫 트레이스백

스택 트레이스(Python 에서는 트레이스백)는 에러가 난 순간 실행 중이던 함수 호출 목록입니다. 하나하나를 프레임이라고 부르고, 함수 하나·파일 하나·줄 하나에 대응합니다. main 이 order_total 을 부르고, 그게 line_total 을 불러서 터졌다면 프레임은 세 개입니다.

아래를 orders.py 로 저장하고, 두 번째 상품에 qty(수량)가 없는 order.json 을 옆에 둡니다.

import json
import sys


def load(path):
    with open(path) as f:
        return json.load(f)


def line_total(item):
    return item["price"] * item["qty"]


def order_total(order):
    return sum(line_total(item) for item in order["items"])


def main(path):
    order = load(path)
    print(order["id"], order_total(order))


main(sys.argv[1])

{"id": "K-3001", "items": [{"name": "볼펜", "price": 120, "qty": 3}, {"name": "노트", "price": 300}]}

$ python3 orders.py order.json
Traceback (most recent call last):
  File "~/demo/orders.py", line 23, in <module>
    main(sys.argv[1])
  File "~/demo/orders.py", line 20, in main
    print(order["id"], order_total(order))
  File "~/demo/orders.py", line 15, in order_total
    return sum(line_total(item) for item in order["items"])
  File "~/demo/orders.py", line 15, in <genexpr>
    return sum(line_total(item) for item in order["items"])
  File "~/demo/orders.py", line 11, in line_total
    return item["price"] * item["qty"]
KeyError: 'qty'

읽는 순서는 이렇습니다.

1. 마지막 줄이 에러 타입과 메시지입니다. KeyError: 'qty'. KeyError 는 "딕셔너리에 그런 키가 없다"는 뜻이고, 메시지는 없는 키의 이름입니다.
2. 머리말에 most recent call last(가장 최근 호출이 마지막)라고 쓰여 있습니다. 그러니 에러 바로 위 프레임, line_total 의 11번째 줄이 실패한 곳입니다.
3. 위로 거슬러 올라가는 것은 "어떻게 거기까지 왔는지"가 궁금할 때만입니다. order_total 이 제너레이터 식(<genexpr>)에서 불렀고, 그걸 main 이 불렀습니다.

고칠 곳은 line_total 이 아닙니다. 올바른 주문이면 이 코드는 잘 돕니다. 이상한 건 데이터입니다. 주문을 거절할지, qty 를 1로 볼지, JSON 을 만든 쪽을 고칠지는 기획의 판단입니다. 트레이스백의 일은 정확한 줄과 정확한 키를 가리키는 것이고, 그 일은 해냈습니다.

실패한 프레임이 내 코드가 아닐 때

이번에는 JSON 을 망가뜨립니다(마지막 원소 뒤에 쉼표 하나). 트레이스백이 길어집니다.

$ python3 orders.py bad.json
Traceback (most recent call last):
  File "~/demo/orders.py", line 23, in <module>
    main(sys.argv[1])
  File "~/demo/orders.py", line 19, in main
    order = load(path)
  File "~/demo/orders.py", line 7, in load
    return json.load(f)
  File "…/lib/python3.9/json/__init__.py", line 293, in load
    return loads(fp.read(),
  File "…/lib/python3.9/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "…/lib/python3.9/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "…/lib/python3.9/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 67 (char 66)

아래 네 프레임은 표준 라이브러리 안입니다. 여기가 틀렸을 가능성은 거의 없습니다. 봐야 할 것은 내 파일에 있는 가장 최근 프레임, orders.py 7번째 줄의 json.load(f) 입니다. 그리고 메시지가 입력의 어디를 보면 되는지 알려 줍니다.

여기서 한국어 데이터라서 보인 점이 있습니다. 같은 구조의 영어 데이터(상품명 pen)에서는 column 68 이었는데, 볼펜 으로 바꾸니 column 67 이 됐습니다. Python 의 열 번호는 바이트가 아니라 글자 수로 셉니다. UTF-8 로 6바이트인 볼펜 도 2글자로 세기 때문에 3글자인 pen 보다 한 칸 앞당겨진 것입니다. 에디터의 열 표시와 같은 단위이니 그대로 이동하면 됩니다.

어느 언어에서나 통하는 규칙은 "표준 라이브러리, 프레임워크, 런타임의 프레임은 건너뛰고, 내가 쓴 경로가 나올 때까지 간다"입니다. Spring 이나 Django 앱이라면 30개 프레임을 건너뛸 때도 있습니다. 에러가 난 곳은 저쪽 코드여도, 원인은 대개 내 코드가 넘긴 값입니다.

연쇄 예외: "caused by", "During handling", "Next"

실제 코드는 저수준 예외를 잡아서 맥락을 붙여 다시 던집니다. 그러면 보고 하나에 트레이스가 두 개 들어가고, 순서가 중요해집니다.

def parse_order(text):
    try:
        data = json.loads(text)
        return data["id"], data["items"][0]["qty"]
    except KeyError as e:
        raise OrderError("order K-3001 is missing a field") from e

Traceback (most recent call last):
  File "~/demo/chained.py", line 12, in parse_order
    return data["id"], data["items"][0]["qty"]
KeyError: 'qty'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "~/demo/chained.py", line 27, in <module>
    parse_order(text)
  File "~/demo/chained.py", line 14, in parse_order
    raise OrderError("order K-3001 is missing a field") from e
__main__.OrderError: order K-3001 is missing a field

raise … from e 는 의도한 연쇄입니다. 원래의 KeyError 가 먼저, 감싼 쪽이 나중에 나옵니다. 이것과 except 블록 안에 버그가 있는 경우를 비교해 보세요.

Traceback (most recent call last):
  File "~/demo/chained.py", line 20, in parse_order_sloppy
    return data["id"], data["items"][0]["qty"]
KeyError: 'qty'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "~/demo/chained.py", line 29, in <module>
    parse_order_sloppy(text)
  File "~/demo/chained.py", line 22, in parse_order_sloppy
    log.warning("bad order: %s", text)   # bug: 'log' was never defined
NameError: name 'log' is not defined

"During handling" 은 버그가 두 개라는 뜻입니다. 데이터 문제, 그리고 고장 난 에러 처리기(log 가 정의되지 않음). 장애 대응 회고에서 자주 나오는 모양인데, 에러를 보고하는 경로는 어느 시스템에서나 가장 테스트가 덜 된 코드이기 때문입니다.

Java 는 감싼 쪽을 먼저, 원래 예외를 Caused by: 뒤에 보여 줍니다.

$ java Orders.java
Exception in thread "main" java.lang.IllegalArgumentException: bad qty in order K-3001
    at Orders.loadQty(Orders.java:19)
    at Orders.main(Orders.java:28)
Caused by: java.lang.NumberFormatException: For input string: "3 "
    at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
    at java.base/java.lang.Integer.parseInt(Integer.java:527)
    at java.base/java.lang.Integer.parseInt(Integer.java:624)
    at Orders.loadQty(Orders.java:17)
    at Orders.main(Orders.java:28)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    … 런처 프레임 4줄 생략

답은 따옴표 안에 있습니다. "3 " 끝에 공백이 있고, Integer.parseInt 는 공백을 잘라 주지 않습니다. 엑셀에서 복사한 값에서 자주 생깁니다. 긴 Java 트레이스에서는 마지막 Caused by: 까지 스크롤하는 것이 원칙입니다.

PHP 는 Next 라는 단어를 쓰고, 원래 예외가 먼저 나옵니다.

$ php -d display_errors=0 orders.php bad
PHP Fatal error:  Uncaught JsonException: Syntax error in ~/demo/orders.php:18
Stack trace:
#0 ~/demo/orders.php(18): json_decode('{"id":"K-3002",...', true, 512, 4194304)
#1 ~/demo/orders.php(28): loadOrder('{"id":"K-3002",...')
#2 {main}

Next RuntimeException: cannot parse order in ~/demo/orders.php:20
Stack trace:
#0 ~/demo/orders.php(28): loadOrder('{"id":"K-3002",...')
#1 {main}
  thrown in ~/demo/orders.php on line 20

PHP 는 호출마다 인자를 15글자로 잘라 보여 줍니다. 디버거 없이도 이상한 입력을 알아챌 수 있는 경우가 많습니다. -d display_errors=0 을 붙인 이유는, PHP CLI 가 기본값으로는 로그 경로(stderr)와 stdout 양쪽에 같은 에러를 두 번 찍기 때문입니다.

같은 버그, 일곱 개의 런타임

"qty 가 없다" 버그가 다른 언어에서는 어떻게 보이는지 나란히 봅니다. 아예 터지지 않는 것에 주목하세요.

PHP 8.5 는 없는 배열 키를 경고로 처리하고 null 로 계속 갑니다.

$ php -d display_errors=0 orders.php missing
PHP Warning:  Undefined array key "qty" in ~/demo/orders.php on line 5
0

합계는 0, 종료 코드도 0. 이대로 배포됩니다. 개발 중에는 PHP 경고를 에러로 취급하세요.

JavaScript(jsc)는 빠진 필드에서는 조용히 NaN 을 내고, 객체 자체가 없을 때 비로소 터집니다.

$ jsc orders.js
K-3001 total: NaN
Exception: TypeError: undefined is not an object (evaluating 'order.items.reduce')
orderTotal@orders.js:5:21
global code@orders.js:10:34

형식은 함수@파일:줄:열 이고, 최신이 위입니다. undefined is not an object 는 JavaScriptCore(Safari)의 표현이고, Chrome 과 Node 의 V8 에서는 같은 버그가 Cannot read properties of undefined (reading 'reduce') 로 나옵니다(여기서는 실행하지 않음). new Error("…", { cause: e }) 로 던진 경우 jsc 의 잡히지 않은 에러 출력에는 cause 가 나오지 않았습니다. e.cause 를 직접 출력해야 했습니다.

Java 26 은 어느 값이 null 이었는지 메시지에 적어 줍니다(helpful NullPointerException).

Exception in thread "main" java.lang.NullPointerException: Cannot invoke "java.lang.Integer.intValue()" because the return value of "java.util.Map.get(Object)" is null
    at Orders.lineTotal(Orders.java:6)
    at Orders.orderTotal(Orders.java:11)
    at Orders.main(Orders.java:26)

Dart 는 번호 붙은 프레임을 최신순으로 보여 주고, 런타임 자신의 프레임이 아래에 옵니다.

Unhandled exception:
type 'Null' is not a subtype of type 'int' in type cast
#0      lineTotal (file://~/demo/orders.dart:4:48)
#1      orderTotal (file://~/demo/orders.dart:10:12)
#2      main (file://~/demo/orders.dart:17:9)
#3      _delayEntrypointInvocation.<anonymous closure> (dart:isolate-patch/isolate_patch.dart:314:19)
#4      _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:193:12)

"Null 은 int 의 하위 타입이 아니다"는 "없는 값을 int 로 캐스팅했다"의 Dart 식 표현입니다. Flutter 로 API JSON 을 다루면 거의 매일 봅니다.

Swift 는 한 줄만 찍고 종료 코드 133(트랩)으로 끝납니다.

$ ./orders_swift
orders_swift/orders.swift:4: Fatal error: Unexpectedly found nil while unwrapping an Optional value

스택을 보려면 lldb 아래에서 실행하고 bt(backtrace)를 칩니다. 프레임 0~3 은 Swift 런타임이 에러를 보고하는 부분이고, 프레임 4 가 내 코드입니다. 문제를 일으킨 인자까지 보이고, 한글 상품명도 그대로 나옵니다.

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = Fatal error: Unexpectedly found nil while unwrapping an Optional value
     frame #0: … libswiftCore.dylib`_swift_runtime_on_report
     frame #1: … libswiftCore.dylib`_swift_stdlib_reportFatalErrorInFile + 204
     frame #2: … libswiftCore.dylib`closure #1 in closure #1 in _assertionFailure(_:_:file:line:flags:) + 400
     frame #3: … libswiftCore.dylib`_assertionFailure(_:_:file:line:flags:) + 276
   * frame #4: 0x0000000100000dc8 orders_swift`lineTotal(name="노트", qty=1) at orders.swift:4:24
     frame #5: 0x0000000100000ac8 orders_swift`orderTotal(items=2 values) at orders.swift:9:39
     frame #6: 0x0000000100000824 orders_swift`main at orders.swift:13:7
     frame #7: … dyld`start + 6992

가장 무서운 건 C 입니다. i <= n_items 루프가 malloc 한 원소 3개짜리 배열의 한 칸 뒤를 읽습니다. 그냥 빌드하면 500 을 찍고 종료 코드 0. 넘쳐서 읽은 자리가 우연히 0 이었을 뿐입니다. AddressSanitizer(-fsanitize=address -g)로 빌드하면 첫 번째 잘못된 읽기에서 멈춥니다.

==36812==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x6020000000fc at pc 0x0001043e8a8c bp 0x00016ba16330 sp 0x00016ba16328
READ of size 4 at 0x6020000000fc thread T0
    #0 0x0001043e8a88 in line_total orders.c:5
    #1 0x0001043e89dc in order_total orders.c:11
    #2 0x0001043e8964 in main orders.c:18
    #3 0x000188a244e0 in start+0x1b4c (dyld:arm64e+0x204e0)

0x6020000000fc is located 0 bytes after 12-byte region [0x6020000000f0,0x6020000000fc)
allocated by thread T0 here:
    #0 0x000104d9d274 in malloc+0x78 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x41274)
    #1 0x0001043e882c in main orders.c:16
    #2 0x000188a244e0 in start+0x1b4c (dyld:arm64e+0x204e0)

SUMMARY: AddressSanitizer: heap-buffer-overflow orders.c:5 in line_total
… 섀도 바이트 표 30줄

보고 전체는 47줄이지만 필요한 건 세 가지입니다. 에러 종류(heap-buffer-overflow), 첫 스택의 #0(orders.c:5), 그리고 "0 bytes after 12-byte region". 이는 "int 3개짜리 배열의 끝 바로 다음 원소를 읽었다"는 뜻입니다. 두 번째 스택은 그 배열을 할당한 곳입니다. 아래의 섀도 바이트 표는 새니타이저 개발자용이니 넘어가도 됩니다.

한눈에 보기: 어느 쪽이 최신이고, 연쇄를 뜻하는 말은 무엇인가

온보딩 첫 주에 만나는 에러도 실제 출력에서 모았습니다.

흔한 실수: 메시지만 출력하기

실수. 예외를 잡아서 그대로 출력합니다.

try:
    total = order["items"][0]["price"] * order["items"][0]["qty"]
except Exception as e:
    print("error:", e)                 # 초보자가 흔히 쓰는 형태
    print("repr: ", repr(e))           # 타입이라도 보이니 조금 낫다
    traceback.print_exc()              # 가장 좋다: 전부 보인다

실제로 일어나는 일.

error: 'qty'
repr:  KeyError('qty')
Traceback (most recent call last):
  File "~/demo/swallow.py", line 5, in <module>
    total = order["items"][0]["price"] * order["items"][0]["qty"]
KeyError: 'qty'

KeyError 의 str(e) 는 그냥 'qty' 입니다. 장애 대응 회고에서 error: 'qty' 만 가득한 로그를 받으면, 무슨 예외였고 어디서 왔는지 아무도 모릅니다. 고치는 법은 타입과 스택을 남기는 것입니다. traceback.print_exc(), 실무 코드라면 logger.exception(...)(2강에서 보여 줍니다). 어느 언어나 같습니다. Java 는 e.printStackTrace() 나 예외를 마지막 인자로 받는 로거, PHP 는 (string) $e, JavaScript 는 e.stack 입니다.

또 하나의 단골 실수는 json/decoder.py 를 열어서 표준 라이브러리를 고치려는 것입니다. 가장 최근 프레임이 내가 쓰지 않은 코드라면, 내가 쓴 가장 최근 프레임까지 올라가세요.

에러 메시지로 검색 잘하는 법

검색 엔진도 이슈 트래커도 단어로 맞춥니다. 에러 줄에는 다른 누구에게도 없는 단어가 들어 있습니다. 홈 디렉터리, 주문 번호, 메모리 주소, 프로세스 ID. 이걸 지웁니다. 위 예제에는 아래의 작은 필터로 충분합니다.

import re
import sys

RULES = [
    (r"(?:[A-Za-z]:)?(?:/[\w.@~-]+)+/", ""),        # directories -> keep file name only
    (r"0x[0-9a-fA-F]+", ""),                          # addresses
    (r"==\d+==", ""),                                 # sanitizer PIDs
    (r"'[^']{12,}'|\"[^\"]{12,}\"", "'…'"),          # long quoted user data
    (r"\b[A-Z]-\d+\b|\b\d{4,}\b", ""),                # ids, big numbers
    (r"\s+", " "),
]


def error_key(line):
    for pattern, repl in RULES:
        line = re.sub(pattern, repl, line)
    return line.strip()


for raw in sys.stdin:
    if raw.strip():
        print(error_key(raw))

$ python3 errkey.py < samples.txt
FileNotFoundError: [Errno 2] No such file or directory: '…'
PHP Fatal error: Uncaught JsonException: Syntax error in orders.php:18
java.lang.IllegalArgumentException: bad qty in order
ERROR: AddressSanitizer: heap-buffer-overflow on address at pc bp sp

남은 고정 부분을 따옴표로 감싸고, 언어나 라이브러리 이름, 최근에 동작이 바뀌었다면 그 버전을 붙여 검색합니다. 예: "Unexpectedly found nil while unwrapping an Optional value" swift dictionary. 영어 메시지는 번역하지 말고 영어 그대로 검색해야 답이 훨씬 많습니다. 우리 코드가 낸 메시지(bad qty in order)라면 웹 검색은 소용없습니다. 우리 저장소를 그 문자열로 검색하면 throw 하는 줄로 바로 갑니다.

솔직한 한계와 버전 메모

• Python 3.9 는 이 Mac 의 Xcode 커맨드라인 도구에 들어 있는 버전입니다. Python 3.11 부터는 실패한 부분식 아래에 ^^^^ 가 붙고, 3.10 부터는 NameError, AttributeError 에 "Did you mean …?" 힌트가 나옵니다. 둘 다 여기서는 실행하지 않았습니다.
• Java 의 자세한 NullPointerException 메시지는 JDK 14(JEP 358)에 들어왔고 JDK 15 부터 기본으로 켜졌습니다. 확인한 것은 26 입니다. Caused by 에 런처 프레임이 보인 건 단일 파일 실행(java Orders.java) 때문이고, 컴파일한 앱에서는 ... N more 로 접힙니다.
• JavaScript Error 의 cause 옵션은 ES2022 입니다. Node 나 브라우저는 cause 를 jsc 와 다르게 보여 줍니다. 실행한 건 jsc 뿐입니다.
• Swift 에 내장된 크래시 백트레이스는 이 환경에서 "backtrace-on-crash is not supported for privileged executables" 라며 동작하지 않아서 lldb 를 썼습니다. Linux 에서는 기본으로 켜져 있습니다.
• ASan 의 줄 수와 주소는 실행할 때마다 바뀌지만 프레임은 바뀌지 않습니다.

연습 문제

1. Python 트레이스백이 ValueError: invalid literal for int() with base 10: '3 a' 로 끝나고, 마지막 세 프레임이 ~/project/app.py, …/site-packages/pandas/…, …/site-packages/pandas/… 입니다. 어디부터 보나요?
2. Java 로그에 IllegalStateException: checkout failed 가 있고 Caused by: 가 두 개 이어집니다. SQLException, 그다음 SocketTimeoutException. 무엇을 조사하나요?
3. 다음을 좋은 검색어로 바꾸세요. PHP Warning: Undefined array key "qty" in /var/www/shop/src/orders.php on line 5

정답

1. app.py 의 가장 최근 프레임입니다. 거기가 '3 a' 를 pandas 에 넘긴 줄입니다. pandas 는 자기 버그가 아니라 여러분의 데이터를 보고하고 있습니다.
2. 마지막 SocketTimeoutException 입니다. DB 호출이 타임아웃됐고, 위는 전부 감싼 것입니다. 다음으로 네트워크나 DB 가 왜 느렸는지 봅니다.
3. "Undefined array key" php, 필요하면 PHP 버전을 붙입니다. 경로, 줄 번호, qty 는 지웁니다. 하지만 먼저 5번째 줄을 읽는 게 가장 빠릅니다. 메시지가 이미 "키가 없다"고 말하고 있으니까요.

---

다음 강의: 2강 print·로깅·디버거 골라 쓰기 · 이 시리즈의 다음 내용: 첫 단위 테스트, 목과 픽스처, 불안정한 테스트, git bisect. 새니타이저와 lldb 를 더 보고 싶다면 C 의 정의되지 않은 동작으로. 프로그래밍 학습 로드맵으로 돌아가기.