Read a Traceback From the Bottom Up

한 줄 요약

트레이스백에서 원인을 말해 주는 것은 맨 아랫줄이고, 그 위의 스택은 어떻게 거기까지 갔는지를 말해 준다.

왜 이게 필요했나

트레이스백을 처음 보면 눈이 맨 위로 갑니다. 사람은 위에서 아래로 읽도록 훈련돼 있기 때문입니다. 그런데 파이썬 트레이스백의 구조는 정확히 반대입니다.

Traceback (most recent call last):
  File "report.py", line 34, in <module>      ← 가장 바깥 호출
    sys.exit(main(*sys.argv[1:]))
  File "report.py", line 26, in main          ← 실제로 터진 자리
    amount = int(parts[2])
ValueError: invalid literal for int() with base 10: 'abc'   ← 무엇이 왜

맨 아랫줄이 예외 종류와 이유를 말합니다. 그 바로 위가 실제로 터진 코드 줄입니다. 위쪽은 거기까지 어떻게 도달했는지의 경로입니다.

그래서 실무에서 처음 볼 것은 세 개입니다. 예외 이름, 예외 메시지에 포함된 실제 값, 그리고 바로 위 프레임의 파일과 줄 번호. 이 셋이면 대개 원인이 확정됩니다. ValueError: ... 'abc' 는 "숫자여야 할 자리에 abc 가 들어왔다" 는 뜻이고, 그러면 다음 질문은 하나뿐입니다 — 어느 행이 그 'abc' 를 갖고 있는가.

어떻게 동작하나

여기서 흔한 실수가 하나 있습니다. 출력을 파일로 저장했는데 트레이스백이 없는 경우입니다.

python3 report.py > out.txt        # 트레이스백이 안 담긴다
python3 report.py > out.txt 2>&1   # 담긴다

트레이스백은 표준출력이 아니라 표준오류로 나갑니다. 고객사에서 "로그에 아무것도 없다" 는 말을 들었을 때 첫 번째로 확인할 것이 이것입니다. 배치 잡의 크론 설정에 2>&1 이 빠져 있어서 몇 달째 실패 원인이 어디에도 안 남고 있는 경우를 자주 만납니다.

수정 자체는 대개 간단합니다. 어려운 것은 그다음입니다.

현장에서 만나는 모습

깨진 행 하나 때문에 죽는 스크립트를 고칠 때, 두 가지 방식이 있습니다.

첫 번째는 그 행을 건너뛰게 만드는 것입니다. 스크립트가 돌아가고 오늘의 문제는 끝납니다.

두 번째는 건너뛰면서 무엇을 왜 건너뛰었는지 남기게 만드는 것입니다. 다음 주에 같은 일이 생기면 로그 파일 한 번 열어서 1분 만에 끝납니다.

두 번째가 계측 심기입니다. 재현되지 않는 문제를 다루는 정공법이기도 합니다. 재현을 목표로 삼으면 며칠을 쓰고 못 만들고 끝나지만, 목표를 다음번 관측으로 옮기면 실패해도 남는 것이 있습니다. 심어 둔 계측은 이 버그가 아니어도 다음 버그에서 쓰입니다.

주의할 것도 하나 있습니다. 타이밍과 경합이 원인인 문제는 계측을 넣는 행위 자체가 타이밍을 바꿔 증상을 감춥니다. 이럴 때는 실행 경로에 끼어들지 않는 관측을 골라야 합니다. 이미 남고 있는 로그의 시각을 맞춰 보거나, 표본 추출로 부담을 줄이거나, 사후에 상태를 덤프하는 쪽입니다.

마지막으로, 고친 코드가 다른 입력에서도 맞는지 확인해야 끝입니다. 오늘 데이터에만 맞춘 수정은 수정이 아니라 우연입니다.

언어마다 읽는 방향이 다르다

트레이스백은 언어마다 순서가 반대입니다. 이것을 모르면 엉뚱한 줄을 봅니다.

언어	맨 위	맨 아래
Python	가장 바깥(진입점)	오류가 난 자리
Java	오류가 난 자리	가장 바깥
Go (panic)	오류가 난 자리	가장 바깥
JavaScript	오류가 난 자리	가장 바깥

파이썬만 반대라 헷갈립니다. 파이썬은 Traceback (most recent call last) 라고 친절하게 적어 주는데, 그 문장이 곧 "아래가 최신" 이라는 뜻입니다.

감싸인 오류를 끝까지 따라가기

프레임워크는 대개 원본 예외를 감쌉니다. 진짜 원인은 사슬의 끝 에 있습니다.

Traceback (most recent call last):
  ...
psycopg.OperationalError: connection failed

The above exception was the direct cause of the following exception:   ← __cause__
Traceback (most recent call last):
  ...
app.errors.StorageUnavailable: 저장소에 닿을 수 없습니다

파이썬은 raise ... from e 면 "direct cause", 예외 처리 중에 또 예외가 나면 "During handling of the above exception" 으로 구분합니다. 두 번째는 대개 오류 처리 코드 자체의 버그 라는 신호입니다 — 원인을 다루려다 또 죽은 것입니다.

Java 는 Caused by: 를 뒤로 이어 붙이고, Go 는 errors.Unwrap 으로 풉니다. 어느 쪽이든 가장 안쪽 예외의 메시지 가 조사의 출발점입니다.

내 코드로 좁히는 법

프레임워크 프레임이 수십 줄이면 눈이 미끄러집니다. 자기 코드만 걸러 냅니다.

# 스택에서 우리 패키지만
grep -E 'File "/app/' traceback.txt

# pytest — 우리 코드 프레임만 보여 준다
pytest --tb=short -p no:cacheprovider

그리고 가장 아래(파이썬 기준)의 우리 코드 프레임 이 대개 진짜 자리입니다. 그보다 안쪽은 라이브러리이고, 라이브러리가 틀린 경우는 드뭅니다. 우리가 넘긴 값이 잘못된 것입니다.

재현이 안 될 때 남길 것

운영에서만 나는 오류는 스택만으로 부족합니다. 예외를 잡는 자리에서 그때의 입력 을 함께 남깁니다.

except Exception:
    log.exception("주문 처리 실패", extra={
        "order_id": order.id,
        "payload_hash": hashlib.sha256(raw).hexdigest()[:12],   # 원문은 남기지 않는다
        "trace_id": current_trace_id(),
    })
    raise

원문 대신 해시를 남기는 것이 요점입니다. 개인정보를 로그에 넣지 않으면서도 같은 입력이 다시 왔는지 는 알 수 있습니다.

다음 실습에서 할 것

어느 날부터 실패하는 배치 스크립트의 트레이스백을 확보하고, 예외 종류와 최초 실패 행을 특정하고, 사양대로 고친 뒤, 건너뛴 행을 기록하는 계측을 심고, 마지막으로 전혀 다른 입력 파일에 돌려 일반화됐는지 확인합니다.