트레이스백 들여다보기
파이썬은 처리되지 않은 예외를 만날 때 트레이스백을 인쇄합니다. 문제를 파악하는데 결정적인 정보가 포함된 경우가 많습니다. 하지만 예외가 발생했을 때 제공되는 트레이스백 객체에는 이렇게 인쇄되는 내용보다 더 많은 정보가 포함되어 있습니다.
트레이스백 객체를 들여다보는 방법을 설명하려고 합니다.
먼저 sample.py 라는 이름으로 다음과 같은 코드를 저장합니다. 줄 번호를 언급할 것이기 때문에 일부러 빈 줄을 모두 제거했습니다.:
def f1(x1, y1=2):
# local var
v1 = x1 ** y1
return f2(v1)
def f2(x2, y2=2):
# local var
v2 = x2 * y2
# result
r = f3(v2)
return r
f3 이라는 함수를 정의하지 않아서 에러가 발생하도록 만들어두었습니다. 이제 REPL 환경에서 다음과 같은 결과를 얻게 됩니다.
>>> import sample
>>> sample.f1(3)
Traceback (most recent call last):
File "<stdin>", line 1, in <module>
File "/Users/flowdas/works/sandbox7/sample.py", line 4, in f1
return f2(v1)
File "/Users/flowdas/works/sandbox7/sample.py", line 9, in f2
r = f3(v2)
NameError: name 'f3' is not defined
Traceback 으로 시작하는 행과 마지막 행 사이의 내용이 트레이스백으로부터 온 정보입니다. 이제 트레이스백 객체를 직접 들여다보기로 하겠습니다. 마지막 예외의 트레이스백 객체는 sys.last_traceback 에서 제공됩니다.
먼저 해야 할 일은 트레이스백 객체로부터 호출 스택에 있는 프레임 객체들을 얻는 것입니다. inspect 모듈의 inspect.getinnerframes() 함수는 이럴 때 편리합니다.
>>> import sys, inspect
>>> from pprint import pprint
>>> frameinfos = inspect.getinnerframes(sys.last_traceback, 3)
>>> pprint([dict(x._asdict()) for x in frameinfos])
[{'code_context': None,
'filename': '<stdin>',
'frame': <frame at 0x7ffabe70c928, file '<stdin>', line 1, code <module>>,
'function': '<module>',
'index': None,
'lineno': 1},
{'code_context': [' v1 = x1 ** y1\n',
' return f2(v1)\n',
'def f2(x2, y2=2):\n'],
'filename': '/Users/flowdas/works/sandbox7/sample.py',
'frame': <frame at 0x106c7b8b8, file '/Users/flowdas/works/sandbox7/sample.py', line 4, code f1>,
'function': 'f1',
'index': 1,
'lineno': 4},
{'code_context': [' # result\n', ' r = f3(v2)\n', ' return r\n'],
'filename': '/Users/flowdas/works/sandbox7/sample.py',
'frame': <frame at 0x106619570, file '/Users/flowdas/works/sandbox7/sample.py', line 9, code f2>,
'function': 'f2',
'index': 1,
'lineno': 9}]
inspect.getinnerframes() 함수는 FrameInfo 라는 이름의 collections.namedtuple 객체들을 제공하는데, 보기 편하게 dict 로 변환했습니다. 내용을 잘 비교해보면 처음에 인쇄되었던 트레이스백과 정확히 같은 순서로 트레이스백 정보가 제공됨을 확인할 수 있습니다. inspect.getinnerframes() 함수의 두 번째 인자로 제공한 3 은 예외가 발생한 지점을 중심으로 소스 코드를 3줄 달라고 요청한 것입니다. 기본값은 1 이기 때문에, 주지 않으면 최초의 트레이스백 처럼 소스 코드가 한 줄만 표시됩니다. 값들을 비교해보면 인쇄되었던 트래이스백에 포함된 모든 정보를 inspect.getinnerframes() 이 제공함을 알 수 있습니다.
이제 한 걸음 더 나가 봅시다. 예외가 발생한 지점에서 각 변수의 값을 확인하려고 합니다.
변수에는 지역, 전역, 자유 변수 세 가지가 있습니다. 이 중 자유 변수는 클로저와 관계있는 것으로, 함수 내에서 다른 함수를 만들고, 내부 함수에서 외부 함수의 지역 변수를 참조하는 상황입니다. 자유 변수는 약간 더 복잡해서 별도의 포스트로 다루는 것이 좋을듯합니다. 오늘은 지역 변수와 전역 변수에만 집중합니다.
지역 변수는 함수의 매개 변수를 포함하는데, 프레임 객체의 f_locals 라는 어트리뷰트로 제공되는 딕셔너리에 들어있습니다. 함수의 매개 변수 관련 정보와 함께 얻으려면 inspect.getargvalues() 함수가 편리합니다.
>>> inspect.getargvalues(frameinfos[1].frame)
ArgInfo(args=['x1', 'y1'], varargs=None, keywords=None, locals={'x1': 3, 'y1': 2, 'v1': 9})
>>> inspect.getargvalues(frameinfos[2].frame)
ArgInfo(args=['x2', 'y2'], varargs=None, keywords=None, locals={'x2': 9, 'y2': 2, 'v2': 18})
역시 collections.namedtuple 객체로 정보를 제공합니다. locals 에 들어있는 것이 예외가 일어난 시점의 지역 변수들의 값입니다.
전역 변수는 프레임 객체의 f_globals 라는 어트리뷰트로 제공되는 딕셔너리에 들어있습니다.
>>> pprint(list(frameinfos[1].frame.f_globals.keys()))
['__name__',
'__doc__',
'__package__',
'__loader__',
'__spec__',
'__file__',
'__cached__',
'__builtins__',
'f1',
'f2']
sample.py 에서는 따로 전역 변수를 만들지 않았기 때문에, 특수 어트리뷰트들을 제외하면 함수 이름들뿐입니다.
한가지 주목할 부분은 이곳에 들어있는 __builtins__ 입니다. 이곳에 전역, 지역, 자유 변수 어느 것도 아니지만 참조할 수 있는 내장 이름 공간이 들어있습니다.
이제 예외가 발생했을 때 예외가 발생한 시점의 각 변숫값들을 찾아내는 방법을 알았습니다. 보통 지역 변수들은 그리 많지 않고 문제를 파악하는 데 도움이 되는 경우가 많습니다. 하지만 전역 변수는 내장 이름 공간까지 염두에 둔다면, 그 양이 많을 뿐만 아니라 대부분은 문제와 관계가 없습니다. 그래서 이 중 코드에서 사용되고 있는 것들을 골라낼 필요가 있습니다. 그러려면 소스 코드를 분석해서 변수들을 골라내야 합니다. 이 작업은 생각보다 그리 큰 작업은 아닙니다. 파이썬이 표준 라이브러리에서 파이썬 구문 분석기를 제공하고 있기 때문입니다. tokenize 모듈입니다.
간단한 예만 들어보겠습니다. 프레임별로 예외가 발생한 지점의 코드 한 줄에 포함된 변수들을 찾아내는 방법입니다. 소스 코드는 inspect.getinnerframes() 함수가 제공한 FrameInfo 의 code_context 에 문자열로 들어있습니다. 이를 tokenize.tokenize() 로 구문분석하면 토큰들이 반환됩니다.
>>> from tokenize import tokenize
>>> from io import BytesIO
>>> pprint(list(tokenize(BytesIO(frameinfos[1].code_context[1].encode('utf-8')).readline)))
[TokenInfo(type=57 (ENCODING), string='utf-8', start=(0, 0), end=(0, 0), line=''),
TokenInfo(type=5 (INDENT), string=' ', start=(1, 0), end=(1, 4), line=' return f2(v1)\n'),
TokenInfo(type=1 (NAME), string='return', start=(1, 4), end=(1, 10), line=' return f2(v1)\n'),
TokenInfo(type=1 (NAME), string='f2', start=(1, 11), end=(1, 13), line=' return f2(v1)\n'),
TokenInfo(type=53 (OP), string='(', start=(1, 13), end=(1, 14), line=' return f2(v1)\n'),
TokenInfo(type=1 (NAME), string='v1', start=(1, 14), end=(1, 16), line=' return f2(v1)\n'),
TokenInfo(type=53 (OP), string=')', start=(1, 16), end=(1, 17), line=' return f2(v1)\n'),
TokenInfo(type=4 (NEWLINE), string='\n', start=(1, 17), end=(1, 18), line=' return f2(v1)\n'),
TokenInfo(type=6 (DEDENT), string='', start=(2, 0), end=(2, 0), line=''),
TokenInfo(type=0 (ENDMARKER), string='', start=(2, 0), end=(2, 0), line='')]
>>> pprint(list(tokenize(BytesIO(frameinfos[2].code_context[1].encode('utf-8')).readline)))
[TokenInfo(type=57 (ENCODING), string='utf-8', start=(0, 0), end=(0, 0), line=''),
TokenInfo(type=5 (INDENT), string=' ', start=(1, 0), end=(1, 4), line=' r = f3(v2)\n'),
TokenInfo(type=1 (NAME), string='r', start=(1, 4), end=(1, 5), line=' r = f3(v2)\n'),
TokenInfo(type=53 (OP), string='=', start=(1, 6), end=(1, 7), line=' r = f3(v2)\n'),
TokenInfo(type=1 (NAME), string='f3', start=(1, 8), end=(1, 10), line=' r = f3(v2)\n'),
TokenInfo(type=53 (OP), string='(', start=(1, 10), end=(1, 11), line=' r = f3(v2)\n'),
TokenInfo(type=1 (NAME), string='v2', start=(1, 11), end=(1, 13), line=' r = f3(v2)\n'),
TokenInfo(type=53 (OP), string=')', start=(1, 13), end=(1, 14), line=' r = f3(v2)\n'),
TokenInfo(type=4 (NEWLINE), string='\n', start=(1, 14), end=(1, 15), line=' r = f3(v2)\n'),
TokenInfo(type=6 (DEDENT), string='', start=(2, 0), end=(2, 0), line=''),
TokenInfo(type=0 (ENDMARKER), string='', start=(2, 0), end=(2, 0), line='')]
여기에서 주목할 부분은 NAME 이라는 토큰들입니다. 여기에는 파이썬 키워드와 변수 이름들이 포함됩니다. 따라서 이 중 파이썬 키워드들을 걸러내면 변수 이름이 나옵니다. 물론 이게 전부는 아닙니다. 가령 . 을 통한 어트리뷰트 참조가 있을 수 있기 때문에, . 을 처리하는 코드도 필요합니다. 또 소스 코드의 어디에서 어디까지 구문 분석할지를 결정하는 로직도 필요합니다.
예외가 발생했을 때 제공되는 트레이스백 객체로부터 꽤 많은 정보를 얻어낼 수 있습니다. 필자는 Sentry 라는 에러 추적기를 즐겨쓰는데, 예외가 발생한 시점의 각종 정보를 수집하고 관리하는 도구입니다. 특히 발생 빈도가 극히 낮아서 테스트를 빠져나간 예외들을 확인하는 데 아주 유용합니다. 지금까지 설명한 것들이, 이런 시스템들이 예외로부터 정보를 추출하는데 사용하는 방법의 핵심입니다. 표준 라이브러리도 cgitb 라는 모듈에서 기본적인 기능을 제공합니다.