소프트웨어는 소스 코드의 몇 줄의 잘못된 수정만으로도 전체 서비스의 정지, 데이터 손실과 같은 치명적인 오류가 발생할 수 있습니다. 히스토리를 알고 있는 사람이라면 어디를 수정하면 어디를 같이 수정해야 하는지 알지만, 모르는 경우 잘못된 수정을 하기 쉽습니다. 피플펀드 프로젝트에는 방대한 테스트 코드가 있어 현재 작업한 내용이 전체 시스템을 망쳐버릴 수도 있는 문제를 방지하기 위해, 기능을 만들거나 수정할 때마다 전체 테스트를 수행해 핵심 기능에 문제가 없는지 확인합니다. 테스트를 매번 로컬에서 수행하기에는 시간이 오래 걸리고 귀찮기 때문에, 테스트 서버에서 Jenkins라는 툴을 설치해 자동으로 테스트를 수행합니다.
어느 날, 평소라면 수십 분 내외로 끝나야 할 테스트가 정지되어 더 이상 돌아가고 있지 않음을 확인했습니다. 로컬 컴퓨터에서는 발생하지 않는 문제였고 테스트 서버에서만 Hang이 걸렸기 때문에 급한 대로 로컬에서 테스트를 매번 진행하게 되었습니다. 이로 인해 개발 팀의 생산성이 크게 저하되었기 때문에 테스트 서버에서 왜 돌아가지 않는지 확인하는 작업을 진행하게 되었습니다.
PyCharm Debugger
PyCharm은 JetBrains에서 만든 Python IDE입니다. Visual Studio처럼 디버거를 GUI 환경에서 사용할 수 있어, 로컬에서 디버깅할 때에는 PyCharm를 사용하면 편리합니다.
PyCharm은:
- 로컬 컴퓨터에서 디버깅 모드로 (PyDev로) Python 프로세스를 실행할 수 있습니다.
- 로컬 컴퓨터에서 실행 중인 Python 프로세스에 Attach해 디버깅할 수 있습니다.
- 원격 서버에서 디버깅 모드로 (PyDev로) Python 프로세스를 실행할 수 있습니다.
테스트 서버에서 왜 멈췄는지를 확인하려면 서버에서 동작하고 있는 Python 프로세스에 바로 Attach할 수 있어야 하는데, 제가 원하던 원격 서버에서 실행 중인 Python 프로세스에 Attach해 실행할 수 있는 기능은 존재하지 않았습니다.
pdb: Python Debugger
pdb는 Python의 기본 모듈에 포함되어 있는 기본적인 Python 디버깅 툴입니다. 다른 디버깅 툴을 설치하지 않아도 사용할 수 있다는 장점이 있습니다.
# timeout_example.py
import requests
for page in range(1, 100):
try:
r = requests.get(f'https://httpbin.org/delay/600')
except Exception as e:
print(f'{page} 페이지를 가져오던 중 문제가 발생했습니다. (오류: {e})')이 파일을 pdb를 이용해서 디버깅하려면 다음과 같은 명령어를 사용하면 됩니다.
python3 -m pdb timeout_example.py참고: pdb에는 프로그램 실행 중 Pause할 수 있는 기능을 제공하고 있지 않습니다.
임시 방편으로는 Ctrl-C를 누르면 발생되는 KeyboardInterrupt를 통해 우회적으로 적용할 수 있습니다.
참고 링크: (Stack Overflow - Interrupt (pause) running Python program in pdb?)
Console에서 프로그램을 실행하고 Ctrl-C를 눌러 디버깅할 수 있는 모드로 진입합니다.
(Pdb)w 명령어로 Traceback을 확인합니다.
(Pdb) w
(... 생략 ...)
.../timeout_example.py(6) _request()
-> response = requests.get(url)
(... 생략 ...)
.../usr/lib/python3.5/http/client.py(877) send()
-> self.connect()
.../.venv/lib/python3.5/site-packages/requests/packages/urllib3/connection.py(167) connect()
-> conn = self._new_conn()
.../.venv/lib/python3.5/site-packages/requests/packages/urllib3/connection.py(142) _new_conn()
-> (self.host, self.port), self.timeout, **extra_kw)
.../.venv/lib/python3.5/site-packages/requests/packages/urllib3/util/connection.py(81) create_connection()
-> sock.connect(sa)테스트 과정에서 다른 서비스와 연결이 정상적으로 이루어지는지 확인하는 코드에서 더 이상 진행이 되고 있지 않았습니다. 문제를 진단해 보니 TCP 3-Way Handshake의 SYN 패킷이 방화벽에 가로막혀 Drop 되었지만, Handshake의 SYN-ACK 응답을 하염없이 기다리던 문제였습니다. 패킷이 Drop이 되었다 하더라도 시간이 지났기 때문에 Timeout이 나지 않아, requests의 문서를 확인해 보았습니다.
If no timeout is specified explicitly, requests do not time out. (Requests 공식 문서)
requests는 명시적으로 Timeout을 지정하지 않는 경우 상대방이 응답할 때까지 무조건 기다린다고 합니다. 이에 requests.get 함수를 사용하는 곳에 Timeout을 지정하는 것으로 문제를 해결했습니다.
gdb를 이용하기
pdb는 서버에 접속해 사용하기에는 편리하지만, Pycharm 디버거처럼 서버에서 동작하고 있는 프로세스에 Attach 한 후 디버그하는 기능이 없습니다.
Python 프로세스를 시작하는 명령어를 변경할 수 없는 경우, gdb를 유용하게 사용할 수 있습니다.
gdb는 GNU Debugger의 약자로, C/C++ 뿐만 아니라 Python 등의 디버깅을 지원합니다.
Python 언어의 구현체에는 여러 가지가 있지만 C로 만들어진 CPython 구현체가 공식 구현체이며 대부분 이 구현체를 많이 사용합니다.
CPython은 C로 만들어졌기 때문에, gdb를 이용해서 디버깅할 수 있습니다.
간단한 C언어 프로그램을 디버깅해 보기
gdb가 C 코드를 디버깅할 때 다음과 같이 사용할 수 있습니다.
// example.c
#include <stdio.h>
int main(int argc, char* argv[]) {
int a = 10;
int b = 20;
int c;
c = a + b;
printf("a (%d) + b (%d) = c (%d)\n", a, b, c);
return 0;
}이 소스 코드를 컴파일을 하고 실행해 봅니다.
$ cc example.c # C 컴파일러를 이용해 소스 코드를 컴파일
$ ./a.out # 컴파일된 소스 코드를 실행
a (10) + b (20) = c (30)예상한 대로 프로그램이 잘 동작합니다.
이렇게 만들어진 실행 파일을 gdb를 이용해 디버깅하려면 다음과 같이 gdb로 실행하면 됩니다.
$ gdb a.out
GNU gdb (GDB) 8.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
Reading symbols from a.out...(no debugging symbols found)...done.
(gdb)마지막에 no debugging symbols found 라는 메시지가 보입니다.
이 상태에서는 아무 것도 할 수가 없습니다.
debugging symbol table은 간단히 설명해서, 디버깅을 위하여 소스 코드와 메모리 주소를 매핑해 둔 테이블입니다. 상단의 소스 코드를 다시 한 번 보겠습니다.
int a = 10;이 코드가 바이너리로 컴파일되면, a라는 변수는 단지 0x10203040 같은 메모리 주소가 됩니다.
gdb는 이 0x10203040 주소만으로는 “이 주소는 3번째 줄의 int 형의 a 라는 변수를 가리키는구나!” 라는 정보를 알 수 없습니다.
따라서, 우리는 gdb가 메모리 주소를 이용해 어느 라인의 어느 변수를 가리키고 있는지를 찾을 수 있게 해 주어야 합니다.
[심볼 테이블 예시]
| 명령 주소 | Name + Type | 파일 | 라인 수 |
|---|---|---|---|
0x10203000 |
int (*main)(int, char**) |
/some/src/example.c | 4 |
0x10203040 |
int a |
/some/src/example.c | 5 |
0x10203044 |
int b |
/some/src/example.c | 6 |
0x10203048 |
int c |
/some/src/example.c | 7 |
| … | … | … | … |
프로그램을 컴파일 할 때 디버그 옵션(-g)을 주면 디버깅이 가능한 바이너리 파일이 나옵니다.
$ cc -g example.c # C 컴파일러를 이용해 소스 코드를 컴파일
$ gdb a.out
GNU gdb (GDB) 8.1
(...생략...)
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from a.out...Reading symbols from a.out.dSYM/Contents/Resources/DWARF/a.out...done.
done.
(gdb)이처럼 심볼이 잘 로드된 것을 확인할 수 있습니다. 이러한 심볼 테이블은 소스 코드가 변경될 때마다 바뀌기 때문에, 디버거가 정상적으로 디버깅을 하기 위해서는 컴파일 당시의 소스 코드와 심볼 파일, 실행 파일을 모두 가지고 있어야 합니다. 즉, 디버깅을 할 때에는 1) 실행 파일 2) 소스 코드 3) 심볼 파일, 최소한 3개의 입력을 받아야 정상적인 디버깅이 가능합니다.
배포되는 Python 실행 파일은 실행 파일만 주어지기에, 소스 코드와 심볼 파일을 다운로드해야 합니다. ubuntu 환경에서 기본 python3 인터프리터를 사용한다면, 다음과 같이 설치하면 됩니다.
sudo apt source python3
sudo apt install python3-dbg이제 gdb를 이용하여 Python의 디버깅이 가능합니다.
htop 명령어를 이용하면 현재 동작하고 있는 파이썬 프로세스의 PID를 알 수 있습니다.
sudo gdb python3 26414 으로 실행 중인 프로세스에 attach 해 줍니다. 이 때 사용하는 pid는 htop 명령어를 사용하면 쉽게 알 수 있습니다.
$ sudo gdb python3 26414
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
Attaching to process 26414
Reading symbols from /usr/bin/python3...Reading symbols from /usr/lib/debug/.build-id/59/a8ef36ca241df24686952480966d7bc0d7c6ea.debug...done.
(... 중략 ...)
done.
(gdb)이제 Python 3.5의 디버깅 심볼과 소스 코드를 읽어 디버깅할 준비가 되었습니다.
bt 명령어를 이용해 Call Stack을 볼 수 있습니다.
(gdb) bt
#0 0x00007efe8ec4aa15 in futex_abstimed_wait_cancelable (private=0, abstime=0x7efe812011b0, expected=0,
futex_word=0x7efe7c018b80) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1 do_futex_wait (sem=sem@entry=0x7efe7c018b80, abstime=abstime@entry=0x7efe812011b0) at sem_waitcommon.c:111
#2 0x00007efe8ec4aadf in __new_sem_wait_slow (sem=0x7efe7c018b80, abstime=0x7efe812011b0)
at sem_waitcommon.c:181
(...생략...)
#24 0x000000000053b7e4 in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>,
pp_stack=0x7efe81201b50, func=<optimized out>) at ../Python/ceval.c:4803
#25 call_function (oparg=<optimized out>, pp_stack=0x7efe81201b50) at ../Python/ceval.c:4730
#26 PyEval_EvalFrameEx () at ../Python/ceval.c:3236
#27 0x000000000053b7e4 in fast_function (nk=<optimized out>, na=<optimized out>, n=<optimized out>,
pp_stack=0x7efe81201c80, func=<optimized out>) at ../Python/ceval.c:4803
#28 call_function (oparg=<optimized out>, pp_stack=0x7efe81201c80) at ../Python/ceval.c:4730
#29 PyEval_EvalFrameEx () at ../Python/ceval.c:3236
#30 0x0000000000540f9b in _PyEval_EvalCodeWithName (qualname=0x0, name=0x0, closure=0x0, kwdefs=0x0,
defcount=0, defs=0x0, kwcount=0, kws=<optimized out>, argcount=<optimized out>, args=<optimized out>,
locals=<optimized out>, globals=<optimized out>, _co=0x7efe8db05a50) at ../Python/ceval.c:4018
#31 PyEval_EvalCodeEx () at ../Python/ceval.c:4039
#32 0x00000000004ebd23 in function_call.lto_priv () at ../Objects/funcobject.c:627
#33 0x00000000005c1797 in PyObject_Call () at ../Objects/abstract.c:2165
#34 0x00000000004fb9ce in method_call.lto_priv () at ../Objects/classobject.c:330
#35 0x00000000005c1797 in PyObject_Call () at ../Objects/abstract.c:2165
#36 0x0000000000534d90 in PyEval_CallObjectWithKeywords () at ../Python/ceval.c:4580
#37 0x0000000000609c02 in t_bootstrap () at ../Modules/_threadmodule.c:998
#38 0x00007efe8ec426ba in start_thread (arg=0x7efe81202700) at pthread_create.c:333
#39 0x00007efe8e97841d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109CPython은 C의 Stack을 그대로 사용하기 때문에, CPython의 Call Stack은 C 레벨에서의 Call Stack을 따라갑니다.
대충 훑어보니 call_function 함수가 함수 호출을 담당하네요.
하지만 이 상태에서는 어떤 Python 코드가 문제가 되는지 알 수 없습니다.
Python 스타일로 보려면 추가적인 Python Debugging Helper 명령어를 사용하면 됩니다.
py-bt 라는 명령어를 보면 수많은 Call Stack들 사이에서 Python Call Stack들의 정보만 뽑아 예쁘게 보여줍니다.
기타 사용 가능한 명령어는 다음과 같습니다:
py-bt py-down py-locals py-up python-interactive
py-bt-full py-list py-print python(gdb) py-bt
Traceback (most recent call first):
File "/usr/lib/python3.5/threading.py", line 297, in wait
gotit = waiter.acquire(True, timeout)
File "/usr/lib/python3.5/queue.py", line 173, in get
self.not_empty.wait(remaining)
File "...venv/lib/python3.5/site-packages/analytics/consumer.py", line 71, in next
item = queue.get(block=True, timeout=0.5)
File "...venv/lib/python3.5/site-packages/analytics/consumer.py", line 46, in upload
batch = self.next()
File "...venv/lib/python3.5/site-packages/analytics/consumer.py", line 35, in run
self.upload()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()analytics라는 서드 파티 라이브러리를 가리키고 있군요.
만약 Call Stack만으로 어떤 문제인지 모르겠다면, strace를 사용할 수 있습니다.
이 명령어는 프로그램이 호출하는 System Call을 가로채 보여줍니다.
$ sudo strace -p 26414
strace: Process 26414 attached
restart_syscall(<... resuming interrupted futex ...>) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {385403, 821286857}) = 0
clock_gettime(CLOCK_MONOTONIC, {385403, 821441871}) = 0
clock_gettime(CLOCK_MONOTONIC, {385403, 821512907}) = 0
clock_gettime(CLOCK_MONOTONIC, {385403, 821588282}) = 0
gettimeofday({1521811270, 564833}, NULL) = 0
futex(0x7efe7c018b80, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {1521811271, 64762000}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {385404, 321902715}) = 0
clock_gettime(CLOCK_MONOTONIC, {385404, 322029475}) = 0
clock_gettime(CLOCK_MONOTONIC, {385404, 322098984}) = 0
clock_gettime(CLOCK_MONOTONIC, {385404, 322200378}) = 0
gettimeofday({1521811271, 65442}, NULL) = 0
... (반복)futex 시스템 콜을 계속적으로 호출하고 있습니다. futex는 특정 시간동안 메모리 주소가 변경될 때까지 현재 쓰레드를 멈춥니다.
def next(self):
"""Return the next batch of items to upload."""
queue = self.queue
items = []
while len(items) < self.upload_size:
try:
item = queue.get(block=True, timeout=0.5) # <<<<<<<<< !!!!!
items.append(item)
except Empty:
break
return itemsanalytics 라이브러리는 별도의 쓰레드를 만들어 수집할 내용이 생길 때마다 Queue에 담고, 주기적으로 서버로 전송하는 동작을 합니다. 테스트와는 상관 없는 다른 프로세스를 잡아 디버깅하고 있었습니다.
htop 명령어의 출력 결과:
CPU[|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||100.0%] Tasks: 91, 178 thr; 2 running
Mem[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||1.74G/1.95G] Load average: 1.11 1.07 1.01
Swp[ 0K/0K] Uptime: 36 days, 04:07:58
CPU% MEM% TIME+ Command
0.0 34.6 2:02.47 /usr/bin/java -Djava.awt.headless=true -jar /usr/share/jenkins/jenkins.war --webroot=/var/cache/jenkins/war --httpPort=8080
0.0 0.1 0:00.00 │/bin/sh -xe /tmp/jenkins1674286523837980795.sh
92.7 13.6 12:54.99 │└─ python manage.py jenkins
0.7 13.6 0:00.73 │ └─ python manage.py jenkins그래서 다른 프로세스에게 strace를 걸어서 확인해 보았습니다.
172.31.22.22 라는 IP로 TCP 연결하던 중 ETIMEDOUT 오류가 지속적으로 발생하는 게 눈에 띄었습니다.
하지만 해당 디렉토리에 전체 검색을 해 봐도 172.31.22.22라는 문자열은 없었습니다.
그 다음으로 확인해 볼 부분은 환경 변수 파일입니다. 서버 정보는 모두 환경 변수 파일에 넣기 때문에, 다음으로 확인해 볼 부분은 이 부분이라고 생각했습니다.
확인해 보던 중 redis 주소 설정이 다음과 같이 되어 있었습니다.
redis://test-celery.apn2.cache.amazonaws.com/0해당 Redis 서버의 IP를 확인하기 위해, Ping을 날려 보았습니다.
$ ping test-celery.apn2.cache.amazonaws.com
PING test-celery.apn2.cache.amazonaws.com (172.31.22.22) 56(84) bytes of data.Redis 서버에 접속하는 부분에서의 문제가 맞았습니다. Celery 동작 중에는 처음 연결할 때 Redis 서버로 PING을 날리는데, 위 사례와 같이 해당 Handshake 패킷이 방화벽에 막혀 발생했던 문제였습니다. 이에 테스트 서버에 Redis를 설치하고 로컬 redis를 보도록 환경 변수를 수정해 주었고, 문제가 되던 Hang이 걸리던 문제는 해결되었습니다.