print·로깅·디버거 골라 쓰기 입문 (pdb·lldb)

시리즈: 테스트·디버깅 강좌 2/6 (초급). 여기저기 print 를 넣고 운에 맡기며 디버깅하는 신입 개발자를 위한 글입니다. 다 읽으면 print·로깅·디버거를 상황에 맞게 고르고, pdb 와 lldb 로 실제 버그를 따라가고, 헷갈리는 버그를 두 줄짜리 재현 코드로 줄일 수 있습니다.

1강은 프로그램이 죽을 때 남기는 보고서를 읽는 법이었습니다. 그런데 대부분의 버그는 죽지 않습니다. 합계가 틀리고, 리포트가 엉뚱한 행을 고르고, 루프가 끝나지 않습니다. 신입 온보딩 과제에서 "돌긴 도는데 답이 달라요", 장애 대응 회고에서 "에러 로그는 없는데 금액이 이상했다". 아무도 스택 트레이스를 건네주지 않는 이 상황을 푸는 것이 이번 강의입니다.

모두 Apple Silicon Mac(M1 Pro), Python 3.9.6, PHP 8.5.6, Apple clang 21, lldb-2103 에서 실행했습니다. 경로는 ~/demo/ 로 줄였습니다.

이번에 쫓을 버그

쇼핑몰에서 10% 쿠폰을 적용하는 코드입니다. 온보딩 과제로 이대로 받았다고 생각해 보세요.

import sys


def apply_discount(price, percent):
    return price - price * percent // 100


def cart_total(items, percent):
    total = 0
    for name, price, qty in items:
        total += apply_discount(price, percent) * qty
    return total


CART = [("볼펜", 120, 3), ("노트", 300, 2)]
COUPON = {"HELLO10": 0.1, "BROKEN": None}   # bug: 0.1 should be 10

if __name__ == "__main__":
    print(cart_total(CART, COUPON[sys.argv[1]]))

$ python3 discount.py HELLO10
960.0

기대값은 108 × 3 + 270 × 2 = 864 입니다. 나온 건 960, 즉 할인이 전혀 안 된 금액이고, 게다가 소수(float)입니다. 예외도 트레이스백도 없습니다. 주석이 답을 알려 주고 있긴 하지만, 중요한 건 "주석이 없었다면 각 도구가 무엇을 알려 줬을까"입니다.

print 디버깅, 그리고 print 를 삼켜 버리는 C 의 함정

가장 먼저 떠오르는 건 apply_discount 안에 print(price, percent) 를 넣는 것입니다. 잘 통하고, 열 줄짜리 스크립트라면 맞는 선택입니다. 하지만 코드가 커지면 문제가 두 가지 생깁니다.

1. print 에는 레벨이 없어서 코드를 고치지 않으면 끌 수 없고, 깜빡한 print 가 운영 출력에 섞인다.
2. 출력이 버퍼링된다(일단 메모리에 모아 두었다가 나중에 한꺼번에 쓴다). 그 전에 프로그램이 죽으면 사라진다.

두 번째는 이론이 아닙니다. 아래 C 프로그램은 사용자 ID 세 개를 조회합니다. ID 7 은 없으니 find_user 가 NULL 을 돌려줍니다.

#include <stdio.h>
#include <string.h>

struct user { int id; const char *name; };

static struct user USERS[] = { {1, "minjun"}, {2, "seoyeon"}, {3, "jiho"} };

static struct user *find_user(int id) {
    for (size_t i = 0; i < sizeof USERS / sizeof USERS[0]; i++)
        if (USERS[i].id == id) return &USERS[i];
    return NULL;                       /* not found */
}

static size_t name_length(int id) {
    struct user *u = find_user(id);
    return strlen(u->name);            /* crashes when u == NULL */
}

int main(void) {
    int ids[] = {2, 3, 7};
    for (int i = 0; i < 3; i++)
        printf("id=%d len=%zu\n", ids[i], name_length(ids[i]));
    return 0;
}

$ clang -std=c17 -Wall -Wextra -g -O0 users.c -o users
$ ./users > out.txt; echo "exit=$?"; wc -c < out.txt
exit=139
       0

크래시 전에 두 줄을 printf 했는데 파일은 비어 있습니다. stdout 이 파일이나 파이프로 갈 때 C 는 블록 단위로 버퍼링합니다. 블록이 쓰이기 전에 크래시(종료 코드 139, 세그멘테이션 폴트)로 프로세스가 죽은 것입니다. 터미널이라면 줄 단위 버퍼링이라 두 줄이 보입니다. printf 를 버퍼링되지 않는 fprintf(stderr, …) 로 바꾸니 같은 종료 코드 139 전에 두 줄(id=2 len=7, id=3 len=4)이 제대로 나왔습니다. 장애 대응 회고에서 "로그가 크래시 직전에서 끊겨 있었다"가 사람을 헷갈리게 하는 이유 중 하나가 이것입니다.

lldb: C 프로그램은 어디서, 무엇을 들고 죽었나

print 는 필요 없습니다. -g(디버그 정보 포함)로 빌드하고 디버거가 크래시를 잡게 합니다. lldb -s lldb.txt ./users 로 명령 파일(run, bt, frame variable, up, frame variable, quit)을 흘려 넣었습니다(실행 메시지와 소스 표시 일부는 생략).

(lldb) run
id=2 len=7
id=3 len=4
Process 36872 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
    frame #0: 0x0000000100000634 users`name_length(id=7) at users.c:16:22
   14   static size_t name_length(int id) {
   15       struct user *u = find_user(id);
-> 16       return strlen(u->name);            /* crashes when u == NULL */
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
  * frame #0: 0x0000000100000634 users`name_length(id=7) at users.c:16:22
    frame #1: 0x00000001000005b4 users`main at users.c:22:43
    frame #2: 0x0000000188a244e4 dyld`start + 6992
(lldb) frame variable
(int) id = 7
(user *) u = NULL
(lldb) up
frame #1: 0x00000001000005b4 users`main at users.c:22:43
-> 22           printf("id=%d len=%zu\n", ids[i], name_length(ids[i]));
(lldb) frame variable
(int[3]) ids = ([0] = 2, [1] = 3, [2] = 7)
(int) i = 2

• bt(backtrace)는 1강의 스택 트레이스 그 자체입니다.
• frame variable 은 선택한 프레임의 지역 변수를 모두 보여 줍니다. u = NULL.
• up 으로 호출한 쪽으로 가면 어떤 입력에서 죽었는지 보입니다. i = 2, ID 7.
• address=0x8 도 재미있습니다. struct user 안에서 name 은 8바이트 위치에 있습니다(4바이트 int + 4바이트 패딩). u == NULL 인 채로 u->name 을 읽으니 주소 8을 건드린 것입니다.

여기서 id=2 len=7 이 보이는 건 lldb 가 터미널 위에서 프로그램을 돌리기 때문입니다. lldb 를 더 쓰고 싶다면(워치포인트, -O2 빌드) C 성능·Make·lldb를 보세요.

pdb: Python 버그를 한 줄씩 따라가기

pdb 는 Python 에 기본으로 들어 있는 디버거입니다. python3 -m pdb discount.py HELLO10 으로 시작합니다. 자주 쓰는 명령은 다음과 같습니다.

재현할 수 있도록 here-doc 으로 명령을 흘려 넣었습니다. 순수 pdb 는 파일에서 읽은 명령을 화면에 보여 주지 않아서, (Pdb) 뒤에 명령을 찍어 주기만 하는 20줄짜리 래퍼를 썼습니다. 손으로 쳐도 출력은 같습니다.

> ~/demo/discount.py(1)<module>()
-> import sys
(Pdb) break 11
Breakpoint 1 at ~/demo/discount.py:11
(Pdb) continue
> ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
(Pdb) p name, price, qty, percent
('볼펜', 120, 3, 0.1)
(Pdb) step
--Call--
> ~/demo/discount.py(4)apply_discount()
-> def apply_discount(price, percent):
(Pdb) where
  … 디버거 자신의 프레임 2개 생략
  ~/demo/discount.py(19)<module>()
-> print(cart_total(CART, COUPON[sys.argv[1]]))
  ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
> ~/demo/discount.py(4)apply_discount()
-> def apply_discount(price, percent):
(Pdb) p price * percent
12.0
(Pdb) p price * percent // 100
0.0
(Pdb) return
--Return--
> ~/demo/discount.py(5)apply_discount()->120.0
-> return price - price * percent // 100
(Pdb) next
> ~/demo/discount.py(10)cart_total()
-> for name, price, qty in items:
(Pdb) p total
360.0
(Pdb) quit

세 번째 p 가 발견의 순간입니다. percent 가 0.1 이라서 price * percent // 100 은 12.0 // 100, 즉 0.0 입니다. 할인은 항상 0 이고, float 가 total 로 새어 나갑니다. print 를 어디에 넣을지 짐작할 필요 없이, 루프에서 멈추고 들여다봤을 뿐입니다.

사후 디버깅: 죽은 뒤에 들여다보기

BROKEN 쿠폰은 None 이라서 죽습니다. python3 -m pdb -c continue discount.py BROKEN 은 예외까지 달린 뒤, 예외를 던진 프레임에서 멈춥니다.

TypeError: unsupported operand type(s) for *: 'int' and 'NoneType'
Uncaught exception. Entering post mortem debugging
> ~/demo/discount.py(5)apply_discount()
-> return price - price * percent // 100
(Pdb) p price, percent
(120, None)
(Pdb) up
> ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
(Pdb) p name, qty
('볼펜', 3)
(Pdb) quit

프로그램 안에서는 except 블록에 import pdb; pdb.post_mortem(), 또는 아무 곳에나 breakpoint()(Python 3.7 이상)를 쓰면 같은 프롬프트가 뜹니다.

logging: 레벨, 포맷, UTC 시각

디버거는 버그가 나는 순간 키보드 앞에 있어야 합니다. 새벽의 운영 서버에서는 불가능합니다. 그래서 로깅입니다. 레벨(DEBUG < INFO < WARNING < ERROR < CRITICAL), 시각, 이름이 붙은 print 이고, 코드를 고치지 않고도 출력량을 조절할 수 있습니다.

import logging
import sys
import time

logging.Formatter.converter = time.gmtime          # timestamps in UTC
logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)sZ %(levelname)-7s %(name)s: %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
    stream=sys.stderr,
)
log = logging.getLogger("checkout")


def apply_discount(price, percent):
    log.debug("apply_discount price=%r percent=%r", price, percent)
    if not 0 <= percent <= 100:
        log.warning("percent out of range: %r", percent)
    return price - price * percent // 100


def checkout(order_id, items, percent):
    total = sum(apply_discount(p, percent) * q for p, q in items)
    log.info("order=%s items=%d total=%s", order_id, len(items), total)
    return total


checkout("K-3001", [(120, 3), (300, 2)], 10)
checkout("K-3002", [(120, 1)], 0.1)
try:
    checkout("K-3003", [(120, 1)], None)
except TypeError:
    log.exception("checkout failed order=%s", "K-3003")

2026-11-14T06:00:35Z INFO    checkout: order=K-3001 items=2 total=864
2026-11-14T06:00:35Z INFO    checkout: order=K-3002 items=1 total=120.0
2026-11-14T06:00:35Z ERROR   checkout: checkout failed order=K-3003
Traceback (most recent call last):
  File "~/demo/log_demo.py", line 31, in <module>
    checkout("K-3003", [(120, 1)], None)
  File "~/demo/log_demo.py", line 23, in checkout
    total = sum(apply_discount(p, percent) * q for p, q in items)
  File "~/demo/log_demo.py", line 23, in <genexpr>
    total = sum(apply_discount(p, percent) * q for p, q in items)
  File "~/demo/log_demo.py", line 17, in apply_discount
    if not 0 <= percent <= 100:
TypeError: '<=' not supported between instances of 'int' and 'NoneType'

장애 대응에서 이 줄들이 쓸모 있는 이유:

• UTC 와 Z. 서버, 휴대폰, 해외 팀원은 시간대가 제각각입니다. 시간대가 없는 로그 줄은 다른 로그와 맞춰 볼 수 없습니다. logging 은 converter = time.gmtime 을 지정하지 않으면 로컬 시각을 씁니다.
• order=K-3002 같은 key=value 는 grep 으로 찾을 수 있습니다.
• except 안의 log.exception 은 전체 트레이스백을 붙입니다(1강 "메시지만 출력하기" 실수의 해결책).
• 두 번째 줄을 꼼꼼히 읽으면 버그가 보입니다. total=120.0, float 이고 할인이 없습니다. 범위 검사는 걸리지 않았습니다. 0.1 은 0 과 100 사이니까요. 로그는 증상을 보여 줄 뿐이고, 생각은 사람이 해야 합니다.

level=logging.DEBUG 로 바꾸면 호출을 하나도 고치지 않고 apply_discount price=120 percent=10 줄이 나타납니다. PHP 에도 같은 개념의 error_log() 가 있어서 CLI 에서는 stderr 로 씁니다. php -d error_log=app.log 를 주면 [14-Nov-2026 06:05:50 UTC] checkout order=K-3002 percent=0.1 type=float 가 파일에 기록됐습니다. 서버의 date.timezone 설정이 UTC 인지 확인해 두세요(이번 환경은 UTC 였습니다). 셸 스크립트에서의 같은 이야기는 튼튼한 셸 스크립트와 cron 로깅에 있습니다.

멈춰 버렸을 때: faulthandler

프로그램이 멈추면 아무것도 출력되지 않습니다. Python 의 faulthandler 는 제한 시간이 지나면 모든 스레드의 스택을 찍어 줍니다.

import faulthandler
import time

faulthandler.dump_traceback_later(2, exit=True)   # print every thread's stack after 2 s


def wait_for_payment(status):
    while status != "paid":        # bug: status is never refreshed
        time.sleep(0.1)


wait_for_payment("pending")

Timeout (0:00:02)!
Thread 0x00000001f582e180 (most recent call first):
  File "~/demo/hang.py", line 9 in wait_for_payment
  File "~/demo/hang.py", line 12 in <module>

python3 -X faulthandler 를 쓰면 C 확장 모듈의 세그멘테이션 폴트에서도 스택이 나옵니다(Fatal Python error: Segmentation fault, 종료 코드 139).

러버덕과 최소 재현: 도구 없이 찾은 버그 두 개

러버덕 디버깅은 아무것도 모르는 상대에게(동료가 바쁘면 고무 오리 인형에게) 코드를 한 줄씩 소리 내어 설명하는 방법입니다. 온보딩 기록에 태그를 붙이는 함수입니다.

def add_tag(post, tag, tags=[]):
    tags.append(tag)
    post["tags"] = tags
    return post


a = add_tag({"title": "온보딩 1일차"}, "python")
b = add_tag({"title": "온보딩 2일차"}, "회고")
print(a)
print(b)

{'title': '온보딩 1일차', 'tags': ['python', '회고']}
{'title': '온보딩 2일차', 'tags': ['python', '회고']}

설명해 봅니다. "tags 는 호출할 때마다 새 빈 리스트가 되고… 정말?" "호출할 때마다"를 입 밖으로 내는 순간 이야기가 무너집니다. Python 은 기본값을 def 가 실행될 때 한 번만 평가하므로, 모든 호출이 리스트 하나를 공유합니다. 고치는 법은 tags=None 으로 두고 tags = [] if tags is None else tags 입니다.

최소 재현은 버그가 여전히 나타나는 가장 작은 프로그램입니다. 32줄짜리 릴리스 리포트가 아래 CSV 를 읽고 플랫폼별 최신 빌드를 출력하고 있었습니다.

app,platform,build,date,notes
shop,ios,8,2026-09-30,첫 공개 빌드
shop,ios,9,2026-10-14,로그인 크래시 수정
shop,android,9,2026-10-14,로그인 크래시 수정
shop,ios,10,2026-11-02,새 결제 화면
shop,android,10,2026-11-02,새 결제 화면
shop,android,11,2026-11-10,쿠폰 반올림 핫픽스

$ python3 release_report.py releases.csv
release report (2026-11-14)
  android  build   9  2026-10-14  로그인 크래시 수정
  ios      build   9  2026-10-14  로그인 크래시 수정

Android 는 11, iOS 는 10 이 더 새것입니다. 버그가 남아 있는지 매번 확인하면서 조금씩 깎았습니다. 데이터를 코드에 직접 넣고, 그룹 나누기를 지우고, 날짜와 메모를 지우고, csv 모듈을 지웠습니다. 마지막에는 한 줄이 남았습니다.

$ python3 -c 'print(max(["9", "10"]))'
9
$ python3 -c 'print(max(["9", "10"], key=int))'
10

CSV 에서 오는 값은 문자열이고, 문자열은 한 글자씩 비교하니 "9" > "1" 입니다. 리포트를 고치는 법은 key=lambda r: int(r["build"]). 한 줄짜리 재현 코드는 질문이나 버그 리포트에 붙이기에도 가장 좋습니다. 32줄 스크립트와 외부에 줄 수 없는 CSV 로는 아무도 도와줄 수 없습니다.

실측: 로깅을 꺼 두었을 때의 비용

뜨거운 경로에 log.debug 를 남겨도 될까요? 각 방식을 20만 번 호출하고 7번 반복한 중앙값입니다(Python 3.9.6, Apple M1 Pro). 로거 레벨은 INFO 라서 debug 는 모두 꺼져 있고, info 는 시각을 붙여 메모리 버퍼에 씁니다.

def debug_lazy(i):    log.debug("order=%s i=%d", ORDER, i)
def debug_fstring(i): log.debug(f"order={ORDER} i={i}")
def debug_guarded(i):
    if log.isEnabledFor(logging.DEBUG):
        log.debug("order=%s i=%d", ORDER, i)
def info_enabled(i):  log.info("order=%s i=%d", ORDER, i)

꺼진 debug 는 약 0.3µs. 요청 하나에 1,000번 불러도 0.3ms 라 문제없습니다. 그런데 f-string 은 아무것도 출력하지 않는데도 약 세 배가 듭니다. debug 가 "필요 없다"고 판단하기 전에 Python 이 문자열을 만들어 버리기 때문입니다. 실제로 출력되는 줄은 약 10µs 로, 꺼진 호출의 약 35배입니다. 필요한 건 INFO 로, 자세한 건 % 형식 인자로 DEBUG 에, 정말 무거운 인자는 isEnabledFor 로 감쌉니다. 프로그램 전체의 속도는 Python 프로파일링과 최적화에서 다룹니다.

솔직한 한계와 버전 메모

• 여기서 쓴 Python 은 3.9.6 입니다. breakpoint() 는 3.7 부터 있습니다. 새 Python 에서는 pdb 기능이 계속 추가되고 있지만, 실행한 건 3.9 에 있는 것뿐입니다. 절대 시간은 버전과 기계마다 다르니 기억할 것은 비율입니다.
• python3 -m trace --trace 는 실행된 줄을 전부 찍습니다. 여기서도 잘 돌았고 "어느 분기를 탔나"를 볼 때 편하지만, 실제 프로그램에서는 수천 줄이 나옵니다.
• PHP: 이 Mac 에는 Xdebug 가 없어서 PHP 단계 실행은 다루지 않았습니다. 실행한 건 error_log() 와 php -d 설정입니다.
• macOS 의 디버거는 lldb 입니다. gdb 는 설치돼 있지 않습니다. 명령이 일부 다릅니다(bt 는 같고, frame variable 은 gdb 에서 info locals).
• 디버거와 로그가 서로 다른 말을 하면 읽을 수 있는 코드를 믿으세요. AI 어시스턴트가 자신 있게 틀린 진단을 내렸고 로그가 그걸 반박한 이야기를 AI 에이전트의 오진을 로그로 잡아낸 기록에 적어 두었습니다.

연습 문제

1. 위 pdb 세션에서 apply_discount 가 120.0 을 반환한 순간의 percent 를 보려면 어떤 명령 하나를 치면 됐을까요?
2. ./app >> app.log 로 돌린 C 프로그램이 죽었는데, 로그가 크래시 50줄 전에서 끝나 있습니다. 마지막 줄들을 나오게 하는 방법 두 가지를 드세요.
3. log.debug(f"payload={json.dumps(big)}") 를 DEBUG 가 꺼져 있을 때 비용이 거의 없도록 고치세요.

정답

1. --Return-- 줄에서 멈춰 있는 동안 p percent(또는 p price, percent). 그 시점에는 프레임이 아직 살아 있습니다. args(a)로도 현재 함수의 인자가 모두 나옵니다.
2. 디버그 출력을 stderr 로 보내기(버퍼링 없음), main 처음에 setvbuf(stdout, NULL, _IOLBF, 0) 로 줄 버퍼링 하기, 중요한 줄 뒤에 fflush(stdout) 하기. 더 좋은 건 lldb 아래나 -fsanitize=address 로 돌려서 크래시 자체를 보는 것입니다.
3. if log.isEnabledFor(logging.DEBUG): log.debug("payload=%s", json.dumps(big)). "%s", big 만 넘기면 메시지 조립은 피해도 json.dumps 는 못 피합니다. 가드는 둘 다 피합니다.

이전 강의: 1강 에러 메시지와 스택 트레이스 읽는 법 · 다음 강의: 3강 첫 단위 테스트 · 이 시리즈: 테스트 더블, 불안정한 테스트, git bisect. 프로그래밍 학습 로드맵으로 돌아가기.