오류의 역사…

요즘 참 재미난 드라마 많이 한다. 특히나 난 의학 드라마를 좋아하는 편인데 골든타임이라는 의학 드라마가 새로 시작했다. 대박~ 원고 때문에 못 보고 있다가 원고 마감을 아슬하게 겨우 넘기고 어제는 홀가분한 마음으로 밀린 드라마 정주행을 시작했다. 굳굳~ 그런데 드라마 보는데 너무 가슴을 후벼파는 장면이 나와서 이 글을 쓰게 되었다. 일단 골든타임의 한 장면을 먼저 바라보고…

#0

작년에 내가 한 큰 작업 중에 하나는 XIGNCODE 서버 코드를 새로 작성하는 일이었다. 새로 작성하게 된 계기는 여러 가지가 있는데 설계 당시 우리가 생각했던 것보다 서버 쪽 기능이 많아지기도 했고, 서버 적용 난이도를 좀 더 낮출 필요가 있었기 때문이다. 코드를 좀 더 세분화 시키고 싶은 마음도 있었다. 어쨌든 이런 목적으로 작업을 시작했는데 생각보다 이 일은 내가 작년에 한 일 중에 가장 잘한 일이 되었다.

새로 서버를 작성하면서 난 파이썬에 심취해서 파이썬을 연동해서 사용했다. 많은 잡다한 기능을 파이썬 코드로 작성할 수 있어서 참 매력적인 일이었다. 그런데 문제는 시간이 조금 지난 후에 나타났다. 고객사에서 잘 동작했고, 우리 테스트 PC에서도 잘 동작했는데, 유독 테스트 PC 중에 한 대에서만 바탕 화면에 게임 서버를 설치하는 경우에 시작 시에 크래시가 발생하는 것이었다. 그.것.도. 파이썬 DLL에서.

난 치기에 불타 올랐다. 후훗. 파이썬 DLL에 숨겨진 버그를 찾아서 파이썬 커뮤니티를 놀라게 해주겠어, 라며 말이다. 크래시는 파이썬 DLL 내의 메모리를 해제하는 지점에서 발생했다. 그래서 난 힙 할당/해제 함수를 후킹해서 모두 추적/기록 하는 엄청난 모듈을 만들었고 파이썬 DLL에서 발생하는 모든 메모리 사용 내역을 뽑아 볼 수 있게 되었다. 그렇게 엄청난 분량의 로그가 출력됐고, 그 엄청난 분량의 로그를 파이썬으로 다시 분석했는데 오류가 없었다. 안타깝게 한 톨의 오류도 없었다. 한 바이트의 힙 오버런도 없었고, 이중 해제도 없었다. 완벽했다.

멘붕에 빠진 나는 python.org에 들어갔고 2.7.2가 올라왔다는 사실을 알게 되었다. 내가 사용했던 소스는 이전 버전이었다. 그래서 2.7.2 소스를 컴파일해서 넣었다. 그랬더니 마법같이 잘 됐다. 그래서 난 속으로 아 형님들이 그 새 뭘 고쳤구나, 라고 생각하며 변경 로그를 뒤졌지만 그런 수정 사항은 애초에 찾을 수 없었다. 잠수함 패치라도 했나, 라는 생각까지……

이렇게 하루가 지났다. 난 왜 2.7.1은 안 되고 2.7.2는 되는지에 집요하게 매달렸다. 뭐가 잘못일까? 뭐가 잘못일까? 그러다가 2.7.1 소스를 다시 받아서 컴파일해서 실행하는 짓까지 하게 되었는데… 결과는 정말 참혹스러웠다. 멀쩡하게 잘 실행되는 것이 아닌가? 그 때 깨달았다. 맞아, 내가 뭘 고쳤었지 ㅠㅜ~ 파이썬 소스의 초기화 부분에서 쓸모 없는 부분이라고 내가 일부를 고친 것이 생각났다. 기존에 컴파일했던 소스에서 그걸 다시 원복 시키고 컴파일을 했더니 멀쩡하게 잘 되는 것이 아닌가? ㅋㅋㅋ~

사무실에 혼자였지만 너무 얼척이 없어서 한바탕 웃었던 기억이 아직도 생생하다. 이틀간의 개.삽.질…

#1

자 이제 진짜 좀 임팩트있는 고백을 할 차롄 것 같다. 몇 해전 초여름 나는 내 인생에서 가장 어려운 버그를 마주하고 있었다. 그 이전에도 그 이후에도 나를 그만큼 괴롭혔던 버그는 없었던 것 같다. 심지어 꿈에도 게임 캐릭터가 나타나서 나를 마구 짓누르곤 했다.

버그는 단순했다. 어느 순간 갑자기 게임이 데드락에 빠지는 문제였다. 그냥 게임을 플레이 할 때에는 잘 발생하지 않았고, 8명이 들어가서 방을 만든 다음에 한 30분쯤 게임을 하면 간헐적으로 데드락이 발생했다. 이 문제를 해결하기 위해서 정말 많은 인원이 같은 게임을 지루하리만큼 많이 플레이를 해야 했다.

한 달여가 지나서 모두가 그 게임의 고수가 됐을 즈음에 버그의 원인을 찾을 수 있었다. 그 결과는 나를 재차 멘붕에 빠트리기에 충분했고, 다시는 이런 실수를 되풀이하지 않겠다는 마음으로 이 버그에 다음과 같은 거창한 비문을 달았다.

/*--

여기에 xxx 버그가 있었다.

xxx 캠페인 모드에서 게임이 행이 걸리는 버그가 있었다.
4.18일부터 근 한 달간 해당 문제를 해결하지 못해서 골치가 아팠다.
문제는 다름아닌 이 코드. 0x1234가 하드 코딩된 것이 화근이었다.

xxx 오디오 파일 핸들이 0x1234인 경우에 이 코드가 그 핸들을 닫아버려서,
xxx 특정 스레드가 무한 루프에 빠지게 되었다.

한 달간 엉뚱한 곳만 찾아 헤매었는데...
O 대리가 만든 logsteps.dll이 문제 해결의 단초를 제공했다.
CreateFile/CloseHandle을 훅해서 모니터링한 결과 그 핸들을 우리가 닫고 있었던 것이다.

---
해당 행 현상의 원인은 크리티컬 섹션으로 인한 데드락입니다. 
데드락이 발생하게 된 원인은 파일 핸들이 의도하지 않은 곳에서 먼저 닫혔기 때문으로 판단됩니다. 
데드락은 다음과 갈은 시나리오로 발생한 것으로 추정됩니다.

1. 무슨 스레드인지 모르는 어디선가에서 사운드 파일 핸들이 닫힘
2. ALAudio.dll!FALAudioStreamManager::DestroyStream 스레드가 생성됨
	A. FScopeCriticalSection을 사용해서 크리티컬 섹션 획득
	B. ALAudio.dll!FALAudioStreamOgg::ReadChunks 호출
		i. vorbisfile.dll!ov_read 호출
			1. 상기 닫힌 핸들로 ReadFile 호출함. 
			   닫힌 핸들이기 때문에 정상적이 값을 반환하지 못하고 실패함. 
			   이로 인해서 ReadChunks 함수가 리턴하지 못하고 무한 루프를 돌게 됨.

3. 메인 스레드에서 Engine.dll!ALAudioSubsystem::Update 함수가 호출됨
	A. 상기 DestroyStream이 획득하고 있는 크리티컬 섹션을 획득하려고 시도함. 
	   상기 스레드가 무한 루프에 빠져 있기 때문에 같이 무한 루프에 빠짐. 
	   게임 메인 스레드이기 때문에 다른 모든 작업이 진행되지 않고 멈추게 됨.
---

내가 썼던 보고서의 일부다. 1번 항목 무슨 스레드인지 모르는 어디선가가 바로 여기였다.
모두 꼼꼼하게 체크하지 않은 내 탓이었다. 
이 보고서를 쓰고 나서도 진짜 문제를 찾기까지 2주가 더 걸렸다.
어쨌든 O 대리가 고생한 덕에 찾게 되어서 다행이다.

이 한 줄 때문에 우리는 한 달 동안 200시간 넘게 xxx를 해야만 했다.
정말 토나오는 시간이었다.

--*/

그렇다면 얼마나 대단한 코드가 이 엄청난 버그를 불러온 것일까? 문제의 코드는 정말 어처구니 없을 정도로 간단하다. 아래 코드가 전부다. 간단한 디버그 체크 루틴이다. 내 실수는 다름아닌 핸들 값으로 나와도 전혀 어색하지 않은 0x1234라는 값을 선택한 데 있었다. 생.각.이 없었던 것이다.

__try
{
	CloseHandle((HANDLE) 0x1234);
}
__except(EXCEPTION_EXECUTE_HANDLER)
{
	// 디버거 탐지
}

#2

마지막 이야기는 우리 이야기는 아니고 다른 업체 이야기다. 최근에 알약 드라이버가 업데이트 되면서 우리 게임과 충돌이 발생하는 문제가 있었다. 2009년 만들 당시를 제외하고는 거의 블루스크린 이슈가 없었는데 그 날 따라 이상하게 블루스크린 클레임이 세 건이나 들어왔다. 그 중에 한 건은 고객이 풀덤프를 메일로 보내주는 수고를 아끼지 않았다. 난 개발팀 팀장과 앉아서 12시가 넘을 때까지 그 덤프를 봤는데 원인이 다소 불분명했다. 메모리의 모든 값들이 모두 제 자리에 우리가 예상했던 대로 들어있었는데 블루스크린이 발생했던 것이다. 우리는 윈도우 소스코드 까지 뒤져가면서 윈도우 내부 함수에서 왜 블루스크린이 발생했을 지를 추적했지만 오리무중이었다.

시간이 너무 늦었고 덤프만 봐서는 답이 없을 것 같아서 일단 다음날 유저에게 다시 연락을 해보기로 했다. 블소가 OBT를 시작하던 날이었다. 집에 가는데 옆에 회사 다니는 녀석한테 전화가 와서는 PC방에 가서 그 쩐다는 블소 캐릭터를 만들고 무려 7렙까지 키우고는 — 블소 결제는 안했다. — 집으로 돌아왔다. 씻고는 컴퓨터를 켜서는 게임 사이트 모니터링을 잠깐 했는데 난리가 났다는 것을 직감했다. 블루스크린 발생한다는 글이 도배가…… 핡~ 그리고 그 중에 아주 똑똑한 유저가 알약을 끄면 된다는 것까지 알아내서 올려놨다.

다시 회사로 왔다. 알약을 설치해서 테스트를 했다. 100% 블루스크린이 재현됐다. 알약 드라이버는 전날 빌드된 타임스탬프였다. 알약이 게임 프로세스에 접근하는 것을 차단하면 블루스크린이 발생하는 것처럼 보였다. 그 새벽에 일단 사이트 담당자 분들께 현상을 설명 드리고 수정 작업이 진행된다고 했다. 그리고 드라이버 코드에서 알약을 허용 처리해 준 다음 빌드를 했다.

다음날 QA팀에서 테스트를하고 수정한 드라이버를 배포했다. 더불어 이스트소프트 측에도 연락을 했는데 내가 놀란 점은 이스트소프트의 대응이었다. 보통 큰 업체들은 이런 종류의 이야기를 하면 니들 잘못이니까 니들이 고치세요~ 이런 반응이 대부분이다. 그런데 이스트소프트는 달랐다. 덤프가 필요하다고 해서 QA팀에서 덤프를 보내 줬는데 바로 자신들의 자체 보호 기능과 충돌이 난 것 같다고 4-5시간 내에 수정해 주겠다는 회신이 온 것이다. 그리고 4-5시간만에 수정된 드라이버를 업데이트해 주었다.

난 이스트소프트의 이 대응에 정말 진짜 감동을 받았는데 왜냐하면 그 전에는 그 어떤 국내 업체에게서도 그런 반응을 받은 적이 없었기 때문이다. 이스트소프트의 대응은 너무나 상식적이다. 블루스크린이 났으니 덤프가 필요하다는 말. 덤프를 분석했더니 자신의 모듈의 수정 내용에 문제가 있을 수도 있겠다는 말. 그리고 광속으로 수정 업데이트를 진행해 주었다. 난 이 경험이 있고 난 다음 알툴바를 교묘하게 설치하는 것쯤은 눈감아 주기로 했다. ㅋ~

#3

주저리 주저리 긴 이야기를 했는데 내가 하고 싶은 이야기는 간단하다. 알약 개발자들은 그렇게 쉽게 찾아낸 오류를 난 왜 이렇게 어렵게 찾아낸 것일까? 왜 그 사소한 버그를 발견하는 데에 터무니없이 오랜 시간이 걸렸을까? 내가 고친 부분은 기억도 못하고 그.렇.게.나 많은 사람들에게 검증 받은 모듈에 문제가 있다고 생각했을까? 소스 코드 한 줄 없는 게임은 디버깅을 해서 데드락의 원인을 완벽하게 찾아내는 동안에 모든 소스 코드를 가지고 있는 우리 제품에서 왜 버그를 발견하지 못했을까?

답은 간단하다. 바로 문제가 나에게 있지 않고 다른 곳에 있다고 생각했던 나의 오만한 마음이다. 프로세스의 문제도, 스킬의 문제도 아니었다. 지식의 문제가 아닌 마음가짐의 문제였던 것이다. 이런 일련의 사건을 경험하면서 나는 인간의 한계를 뛰어넘는 개발 스킬, 최고의 프로세스, 쩌는 팀을 가지고 있다 해도 오만한 마음가짐으로는 자기 발등에 떨어진 왕방울만한 문제도 제대로 볼 수 없다는 생각이 들었다.

많은 개발자들이 버그로 고생한다. 그리고 버그를 빠르게 찾는 방법을 고민한다. 디버깅 스킬, 개발 지식, 뛰어난 직관, 방법론 등을 찾아 헤맨다. 하지만 진짜 답은 그런 복잡한 도구와 어려운 지식에 있지 않고 문제가 나에게 있다고 생각하는 겸손한 마음가짐 속에 있는 건 아닐까? 그 옛날 맹자 선생님께서 하신 말씀과 다르지 않다. 지난 10년간 내가 프로그래머로 일하면서 배운 가장 중요한 지식은 거의 모든 경우에 자신의 잘못을 먼저 바라보는 사고가 문제 해결에 가장 큰 도움이 된다는 것이었다.

인이라는 것은 활 쏘는 것과 같다. 활을 쏠 때는 자세를 바르게 한 후에 쏘는 법이다. 화살이 과녁에 맞지 않으면 자기를 이긴 자를 원망할 것이 아니라 (과녁에 맞지 않은 까닭을) 도리어 자기 자신에게서 찾는다. – 맹자