오랫만에 만난 대어

처음에는 에러 발생 지점을 잡아서 exception 처리만 하면 될 줄 알았다.

새롭게 진행 중인 제품의 QA가 진행중이다. 마지막 RC 가 다가오는 시점에서 제품의 뷰어 프로그램에서 Hang(프로그램 멈춤현상)이 발생한다는 이슈가 올라왔다. 이전부터 몇번 있었던 현상을 여유로운 테스트 기간이 있다고 생각하여 미루어 왔던 것이 이제는 Release가 코앞이라 미룰 수가 없다. 문제에 대한 재현 스텝이 없이 그저 어느 순간 그렇게 되더라는 QA의 이슈 내용을 한숨 쉬며 읽고 나서 원인을 찾아나선다.

1) 버그 재현하기 - 어디선가 루프 돌고 있겠군
뭐, 아무리 델파이라고 해도 hang 이라면 뻔한거지. 어디서가 엉뚱하게 무한 루프 돌고 있거나, 아님 양쪽 스레드가 서로 데드락이 걸려있겠지. 집중해서 단칼에 잡는다는 심정으로 이슈 재현을 기다렸다. 만약 hang 걸린 상태에서 CPU가 피크 치고 있다면 이건 무한 루프이고, CPU가 놀고 있다면 데드락 일테니 거기서 부터 시작해 보자. 문제는 이 증상이 쉽게 발생하지 않는다는 것이다. QA에서는 하루에 한번 꼴, 개발 머신에서는 1, 2 시간에 한번꼴. 기다리고 기다리다가 드디어 문제가 재현이 되었다. 상황은 한 스레드가 CPU의 25%를 먹는 증상. 4CPU 중 1CPU만 Full을 치는 상황이니 이건 어디선가 무한 루프인가?

2) 콜 스택 확인하기
재현되는 순간에 문제 프로세스의 콜스택을 확인하고 나면 대충 감이 올테지. Process Explorer 를 사용하여 hang 걸린 프로세스를 보니 특정 스레드에서 열심히 삽질 중이다. 델파이의 디버그 정보 파일 생성을 하는 방법을 몰라서 한참을 뒤적여서 콜스택 확인하니 UI의 메인 스레드가 아닌가.

3) 메인 스레드에서 무언가 삽질이?
메인 스레드가 hang 이 걸려있다. 그 이유를 상상해 보지만 도무지 답이 안 나온다. 대체로 서버와의 통신과 데이터 파싱은 전담 스레드가 진행하는데 왜 난데없이 메인 스레드가  hang이 걸리는 것일까? 한참을 고민하고 자료를 뒤적이다가 델파이의 Synchronize 함수를 알게 되었다. 이 묘한 함수는 멀티 스레드 환경에서 스레드간 동기화를 지원해 주는 함수라는데, 그 동작 방식이 참 기묘하다. 간단하게 어느 스레드에서 수행되는 특정 함수에 Synchronize 를 사용하면 그 함수는 지금의 스레드가 아닌 메인 스레드가 수행을 해 주는 것이란다. 여기 저기 스레드에서 마구마구 Synchronize을 사용하게 되더라도 메인 스레드는 하나이니 동기화가 된다나 뭐라나.  즉 특정 스레드에서 어떤 함수를 수행하면 메인 스레드가 그 함수를 수행한다는 이런 개념은 도통 생소하다. 마침 우리 코드에서도 동일 함수들이 쓰이고 있다. 역시나 유지보수 하다가 죽어나니 급하게 Synchronize를 걸었나 보다.

4) 여러 스레드에서 요청된 함수를 메인 스레드가 수행하다가 먹통이 된다?
그렇다면 Synchronize를 사용해서 각 스레드들이 메인 스레드에 함수 수행을 요청하고, 그 함수를 수행하던 메인 스레드는 어찌어찌하다가 먹통이 된다? 그럴 듯한 시나리오다. 그렇다면 어디에서 먹통이 될까. Synchronize를 걸고 있는 모든 함수를 열심히 뒤져 보았다. 특히나 해당 함수들의 for, while, wait 계열 함수들의 문제점은 없는지를 뒤져 보았다. 하지만 각 함수들에는 문제점이 없어 보인다. 게다가 현재 뷰어는 메인 스레드를 빼면, 3개의 하위 스레드가 더 돌고 있을뿐. 게다가 각 스레드는 전혀 다른 종류의 일을 수행하는 스레드들인걸. 흐음.

5) 재현하기, 재현하기, 재현하기
찾으면 찾을수록 오리무중이 되어간다. 필요한 코드 위치마다 디버그 로그 코드를 집어 넣었다. 마침, 델파이 디버그 모드로 실행을 하다보니 hang 발생 직전에 exception 이 발생한다. 옳다구나 디버그 모드에서 잡혔으니 이제 술술이다. 그런데 이건 또 웬일인가. exception 이 발생할 때마다 코드의 위치가 다르다. 아무런 연관이 없는 곳에서 뻑뻑 죽어난다. 이럴수가. 물론 그래도 소득은 있다. 바로 string 관련 조작을 하면서 죽는다는 것. 그렇다고 동일한 string 조작 api도 아니지만, 여튼 비슷한 계열의 함수에서 난다는 것.

6) string 조작 중 메모리 할당 오류인가
몇번의 재현이 되고 현상을 확인하면 하루가 휘익 지나간다. 몇번의 재현으로 동일한 증상 확인을 시도했지만, 몇시간을 기다려 재현되는 순간마다 hang 걸리는 양상이 틀리다 보니 난관에 부딪쳤다.
여튼 string 계열 함수에서 대부분의 exception이 발생한다는 것을 발견했다. 일단 문제 되는 곳에다가 마구 마구 try, except 를 걸어볼까나.

7) 허걱. exception 이 안 잡힌다.
오류가 나는 곳곳에 try, except 를 걸고 재현을 기다리는 데, 이럴수가. except에 걸리지를 않는다. 이 무슨 기묘한 현상인고. 디버그 로그를 또 추가한다. 문제되는 코드 앞뒤로 촘촘히 디버그 로그를 기록해 보았다. 그리고 다시 대기.

8) string 계열 함수에서 hang
디버그 로그를 잔뜩 기록하고 대기하다 보니, 문제 현상은 string 계열 함수 자체에서 hang 이 걸리고 있다는 것을 알게 되었다. 델파이의 StringReplace, StringList의 DelimitedText 호출시 멈춰있음이 확인된다. 허걱. 이런. 델파이 3개월 사용 경험에 의하면 (--a) 이 함수가 얼마나 많이 쓰이는 넘인데. C++의 strcpy 계열과 동등한 레벨 아닌가. 화악 델파이의 API 버그라고 우겨볼까. 흐으.

9) heap이 깨지는 걸까?
동일한 코드 위치는 아니지만, 동일한 String 계열의 함수라면 이건 멀티스레드 문제 아니면 heap 문제가 아닐까. 문제 발생하는 코드 중에는 global 변수 사용하는 곳도 있지만 그냥 local 변수 사용되는 것도 있다. 항상 동일한 api 는 아니지만, string을 조작하는 코드에서 대부분 발생한다면 이제 문제의 유력한 범인은 heap 이다. string 조작을 위해서 메모리를 동적으로 할당했다 해제했다 할텐데 그 와중에 쫑 나는 게지. 그래, 이거야.

10) 델파이에서 dll 사용시에 그런 문제가 있다는데!
델파이의 heap으로 관심을 집중하여 구글링을 하다 보니, 델파이에서 외부 dll을 사용하여 메모리 할당/해제시에 heap이 깨지는 문제가 발생할 수 있단다. 옳거니! 그런 문제는 원인 파악이 어렵긴 하지만 fastsharemem 라는 넘을 사용하면 외부 dll과 메인 실행 파일 간에 동일한 heap을 사용할 수 있도록 해 주어야 쉽게 해결할 수 있단다. 주말에 난리법석 떨면서 출근한 보람이 있구나. 어여 적용해 보아야지. 흐흐.

11) heap 이 깨지는 거 맞나?
우리 제품에 dll로 메모리 할당/해제하는 녀석들이 있는지를 확인해 보니, 마침 의심되는 dll 하나가 있다.
열심히 fastsharemem 을 적용하여 다시 재현되기를 기다리기. 허걱. 그런데 동일한 현상이 바로 나타난다. 흑. 이것이 아니란 말인가. 다시 미궁 속으로.

12) 동시에 연결된 모든 뷰어에 이상 증상이 나타난다?
이제는 개발 멤버 전원이 투입이 되어 테스트를 계속 진행 중이다. 마지막 RC를 넘겨야 하는 시점이므로 주말 배수의 진을 치고 디버깅을 시도한다. 각자가 나름의 원인을 찾아 며칠을 골몰하고 있지만 뽀족한 답이 없어서 지쳐가고 있다. 이슈의 현상과 오류가 나는 지점을 알겠는데, 도무지 해결할 방법이 없다. 급기야 그냥 특정시간에 살짝 프로그램을 재시작 할까 라는 꼼수 제안들이 나타난다. 흐미.

13) 특정 시간에 전달되는 패킷의 정체는?
한 서버에 개발자 4명이 붙어서 해당 버그를 잡느라 골몰하고 있는데, 한참이 지나고 나니 지나쳤던 증상 하나가 되뇌어진다. 바로 해당 이슈 문제가 발생하면 붙어있던 뷰어들 모두가 다 동일한 증상이 나타난다는 것이다. 만약 멀티스레드 문제나 메모리 할당/해제 중 heap이 깨지는 문제라면 모든 뷰어에서 동일하게 발생할 가능성은 희박하다. 그런데 매번 동일하게 한 서버에 붙어있던 뷰어가 모두 hang이 걸린다는 것!

14) 그렇다면 서버가 이상하다?
그렇다면 이건 서버가 문제라는 건가? 지금까지 몇날 몇일을 클라이언트 뷰어만 쳐다보고 있던 우리는 갑자기 혼동이 일어난다. 어느 순간 서버가 이상한 패킷을 날리고, 해당 패킷을 받은 뷰어는 모두 hang이 걸린다. 그럴듯한 시나리오다.

15) 문제 시점의 서버의 패킷을 분석하라.
또 디버깅 코드를 넣는다. 서버로 부터 받은 패킷을 모두 기록하도록. 디버그 로그를 쓰는 함수가 버거워하는 것이 보일 정도로 빼곡히 로그를 기록하도록 하고, 다시 재현시도. 들여다 보고 있자니 역시나 의심스러운 부분이 발견된다. 바로 특정 시간에 수십 수백개의 CRLF가 날라온다는 것이다. 마침 문제 발생 이전, 이후로 들어온다. 이리하여 공은 서버로 넘어간다.

16) 새로운 희망?
서버를 분석해 보니, 역시나 초기화 되지 않은 변수를 주기적으로 날리는 코드를 발견하였다. 그 변수는 초기화 자체가 안되었기 때문에 언제 뭐가 날아갈지 가늠이 안되는 넘이란다. 그래서 그 부분을 수정하고 다시 테스트! 희망이 보인다.

17) 그냥 기존 버그일 뿐이라고
몇날 몇일 날밤을 새고 나서 지친 개발자들이 희망에 차서 다시 힘을 낸다. 새로운 코드를 적용하고 재현되는지 대기. 그런데, 또 발생한다. 아~ 이론 ㅠ.ㅜ

18) 일단 꺼 보자고
이번 프로젝트는 이전 제품 코드에 새로운 기능을 추가한 것이다. 이전 제품 코드는 QA도 거치고, 사이트도 적용 중이므로 안정성이 확보되었기 때문에 이전 코드에 대해서는 노터치. 급기야 새로 추가된 모든 소스를 대부분 제거를 했는데도 동일한 증상은 계속된다. 자, 이제 슬슬 이전 코드를 의심해 볼때가 된것도 같은데. 마침 개발자 중 한명이 서버, 뷰어간 SSL 통신을 끄고 시도해 보자고 제안한다. 몇차례 암호화가 의심된 적은 있었지만, 기존 테스트나 사이트에서 아무런 문제가 없었으므로 그저 지나쳤던 코드이다. 에이~ 설마~. 대충 의견을 듣고 유야무야 넘어가려는데, 이 마당에 손해볼 것도 없지라는 생각에 모두들 함 시도해 보자고 한다. 서버와 뷰어간 SSL 기능을 끄고 재현을 시도해 본다. 오홋. 그런데 문제가 발생하지 않는다! 꽤 오랜 시간이 흘러도 죽지 않고 꿋꿋이 떠 있는 뷰어. 이럴수가. 저게 문제라니. 저건 기존 코드라서 문제 될 것이 없을 거라고 했는데!

19) 코드가 동일한 것 같은데...
서버, 뷰어간 암복호화 중에 문제가 발생하는 것을 얼떨결에 발견하게 되었다. 이제 문제 코드만 찾아내면 된다. 그런데, 서버와 암복호화 코드와 뷰어의 암복호화 코드를 들어야 보니 동일한 코드로 구성되어 있는 듯 하다. 이상하다 싶어 다른 코드로 넘어가려는데, 옆의 동료가 서버 코드를 뷰어 코드에 그대로 적용해 보자고 한다. 대충 보니 동일하여 그럴 필요 있나 싶었는데, 동료분은 밑져야 본전이니 해 보잖다. 서버의 코드를 가져다가 뷰어에 갖다 붙이고 보니, 오호라 정말로 코드라 약간 틀리다. 메모리 해제 하는 코드의 위치가 하나는 함수 중반부에 있고, 다른 하나는 말미에 있다. 서버의 코드를 그대로 뷰어에 적용 후 다시 재현되기를 대기. 시간이 흐르고... 올레~ 드디어 문제가 발생하지 않는다!!

20) 진실이 드러나다.
문제의 원인은 기존 서버, 뷰어간 암호화 과정 중에 있었다. 뷰어에서 암호화된 패킷을 복호화 하는 과정 중에 오류가 발생하면 조용히 에러 처리 해 주면 될 것을 억지로 메모리를 건드리다가 heap이 깨졌던 것이다. 여기서 heap 이 망가지고 나니, 이후에 heap을 사용하는 어딘가에서 에러가 발생했던 것이다. 그것도 아주 랜덤하게.

21) 오랫만에 만난 대어
결국 4~5일간의 혈투가 끝났다. 문제는 전혀 의심하지 않았던, 의심하지 말라던 기존 코드에서 발견되었다. 4일 밤낮을 헤매면서 끈질기게 시나리오를 써가던 우리들은 마지막 정상 동작을 보고나서, 편의점에서 라면 한그릇 먹고 각자 택시를 타고 집으로 흩어졌다. 오랫만에 만난 대어였다. 4일 동안 수십개의 자신만의 시나리오를 만들면서 버그를 추적하던 4인의 개발자는 편안한 마음으로 택시에 몸을 의지하였다. 피곤한 몸이지만 이것이 개발자의 희열 아니겠는가. 하나의 버그를 잡기 위한 그 수많았던 상상의 나래들. 그 어느 예술가의 작품만큼이나 창의적이지 않았던가. 무한한 창작으로 우리는 해냈다. 낚시대를 던지고 끈질기게 기다렸으며, 몇 번의 입질과 좌절에도 굴하지 않고 끝까지 추적하여 우리 오늘 이렇게 대어 한마리 잡아냈다.

 - 2011.04.27 Joshua95