소프트웨어 이야기

(디버깅에 대한 제 희망사항입니다.
익숙하지 않는 단어는 개의치마시고 편하게 읽어보시길…)

[PDF로 보기]

저는 개발자입니다.
장비S/W와 NMS용 S/W개발에 관여를 합니다.

제 Code가 오 동작을 하는 경우에 log를 찍도록 해놓았습니다.  예를 들어서 memory가 없어 malloc이 fail되는 일을 말합니다.  희망사항이지만, Crash하는 경우에도 당시 상태를 알 수 있으면 좋겠군요.  이런 것이 기술적으로 힘들다고 하면, crash했다는 사실만이라도 알 수 있으면 좋겠습니다.

제가 시간이 많아서 항상 console을 보고 있으면 log가 찍히는 것을 알 수 있지만, 모든 console을 다 보고 있을 수는 없습니다.  게다가 NMS의 경우에 Console이라는 것이 없기 때문에 Dialog를 띄우는데, 사용자가 불평을 할 것이 뻔하기 때문에 이걸 매번 띄울 수도 없는 일입니다.  NMS에도 console같은 것이 있으면 두말할 나위 없겠지요.  하지만, NMS에서 console이 지원된다 하더라고 장비와 마찬가지로 설치된 모든 NMS의 console을 보고 있을 수 는 없는 일입니다.

가끔씩 앞에 가서 button하나를 눌러보면, 그 동안 오 동작 했던 log라도 볼 수 있으면 좋겠습니다.  log에는 언제 발생한 것인지 알 수 있으면 좋겠고, 실마리를 쉽게 잡을 수 있는 정보가 있으면 좋겠습니다.  NMS는 PC에 하드가 충분하니까, log를 저장하기 쉬울 겁니다.  장비는 메모리밖에 없기 때문에 뭔가 저장할 수 있는 방법이 있으면 좋겠군요.  Flash에 적어 놓기는 양이 너무 많고, PC로 보내서 저장해 놓으면 좋을 것 같은데, 기술적으로 가능한지 모르겠습니다.

하기야 제일 좋은 것은, 제가 개발한 세상의 모든 장비와 NMS에서 발생하는 오류를 한자리에서 알 수 있는 일이죠.  집중 서버에 접속해보면, 어느 NMS, 어느 장비에서 어떤 오류가 현재 발생하고 있는지 실시간으로 알 수 있는 거죠.  NMS와 장비의 버전 정도는 포함되어 있겠죠?

이것이 1년 전의 제 희망이었습니다.

지금요? 이제 행복합니다.
아니 사실은 이 모든 것이 완성되고 나서 불행의 시작입니다.
제가 어림짐작으로 예상했던 것보다 두 배 아니 10배는 많은 오류들이 있다는 것을 알아버렸습니다.  차라리 모르는 편이 나을 뻔 했습니다.  밤에 잠을 잘 수가 없습니다.

Bug가 있으면 고쳐야겠죠?
제일 긴급한 것부터 고쳤습니다.

Crash!
Crash는 절대로 있어서는 안됩니다.  장비가 죽으면 서비스에 지장이 있을 수 도 있고, NMS가 죽으면 사용자들은 장비가 죽은 것으로 인식하기 때문이죠.  요즘 세대는 누구나 Visual의 노예입니다.

NMS가 죽으면 log를 담긴 file을 남깁니다.  그리고 그 file을 sinus 서버로 보내줍니다.
NMS만큼 상세한 정보는 아니지만 장비도 죽으면서 다행히도 몇 가지 정보는 sinus로 보내왔습니다.  file을 열어보니 PC값과 Stack정보가 담겨 있습니다.  PC값과 Stack정보를 function call로 찾아보기 위해 map file을 찾습니다.  다행히도 log에 버전 정보가 담겨 왔군요.  해당 map file을 찾아보니…
아…! 여기서 죽었군요.  이 function 이름 앞에 모듈이름이 있어 금방 담당자를 찾아서 알려줍니다.

안녕하세요, 저는 그 모듈 담당자입니다.
저는 제 모듈에 대해 자부심을 가지고 있습니다.  많은 분들께서 저의 결과물을 믿어주시고 사용해 주시거든요.  지금까지 5개사 10여개 프로젝트에서 사용되고 있답니다.  멋지지요?
그런데, 이렇게 어의 없이 죽어버리다니, 제 자존심에 금이 갔습니다.  얼른 원인을 분석해야겠습니다.  우선 해당 버전의 map file을 찾아서 보내온 자료를 검토해 봅니다.

아! 여기 pointer값이 엄청나게 크군요.
그런데 어떻게 이런 일이 발생하지요?  음 이런, 사용자가 넘겨주는 값이군요.  아마도 누군가가 잘못된 값을 넘겨주셨나 봅니다.  그럼 그렇지요.  휴~ 다행입니다.  자존심 회복.
근데, 도대체 누가 제 function을 부른 건지 알 수가 없군요.  Stack에 누가 불렀는지는 쓰여있는데 function call의 depth가 있다 보니 보내준 stack범위를 넘어섰습니다.  최악이군요.
일단 제 function을 사용하는 곳이 어디인지 찾아 봐야겠습니다.  사용한 버전들의 library들을 살펴보니 3군데서 사용하고 있습니다.

두 군데는 이전부터 사용하고 있는 곳 같고 (제가 작성한 코드가 아니거든요), 한 군데는 이번에 새로 추가된 코드이군요.  코드를 대충 훑어 보니, malloc한 흔적이 보입니다.  free한 후에 해당 memory를 사용한 것 같지만, 제 코드가 아니니 담당자에게 연락을 했습니다.

안녕하세요.  그 코드 담당자 입니다.
Crash된 이유가 제 코드일 가능성이 많다고 해서, 코드를 살펴보고 있는 중입니다.
사실 조금 불안하기는 했는데, 모듈 단위의 시험이 완벽하지 못했나 봅니다.
해당 버전의 코드를 다시 돌려봅니다.
물론 이번에는 Trace를 켜고 눈으로 확인하면서 하고 있습니다.  그분이 작성한 모듈의 trace켜놓으니 제가 전달하는 그 pointer값이 한눈에 보이는 군요.

제 PC 한구석에서 뾰로록 메시지가 떠오릅니다.  네이트인가 했는데, 이런~ 그 현상이 발생 했다고 알려주는 거군요.  두 눈 똑바로 뜨고 있었는데 제가 지나쳤군요.  Scroll을 따라 올라가서 Trace를 보니 저런~ pointer값이 엄청나게 크군요.  보고에 받은 값과 동일하지는 않지만, 제 잘못이 맞는 것 같군요.
다행입니다.  Release되기 전에 잡을 수 있어서 말입니다.
모듈 담당자 분께 수정을 했다고 알려드리니 흐뭇해 하시는 군요.

그리고, 1주일이 편안하게 지나갔습니다.
그런데 그 모듈 담당자 분께서 저를 또 찾으시는 겁니다.  같은 곳에서 crash가 또 일어났다고 하시면서 이번에는 stack 크기를 늘려놓으셨는지, 제 function call이름이 정확하게 찍혀 있군요.  이럴 수가 ~~~.
자료를 받아 들고 시험실로 돌아와서 상황을 재현해보려고 3시간째 씨름 중입니다.
딱 한번 나왔었는데, trace를 켜고 증거를 찾으려고 하니까 웬일인지 계속 숨바꼭질입니다.
Reset를 시키고 부팅되는 동안 커피 한잔 타서 돌아와보니, 아 상황이 다시 발생하고 있지 않겠습니까?
반가운 마음에 trace를 켜니 상황이 다시 없어졌습니다.  거참.
잠자리에 누웠는데, 잠이 오질 않습니다.  혹시 Trace 때문인가?

평소 10시가 되야 출근을 하는데, 그날은 눈을 뜨자마자 회사로 달려갔습니다.
역시. Trace를 켜면 상황이 없어지고, Trace를 끄면 상황이 나타나더군요.  이런 황당함이란.
존경하는 선배님께 이런 자초지종을 말씀 드렸더니, 도사 같은 한 말씀으로 길을 알려주시는 군요.
원격에서 Trace를 한번 켜서 시험을 해보라고.
이런~ 어떻게 된 건지 원격에서 trace를 켜니까 상황이 계속 나타납니다.  이렇게 좋을 수가.
상황이 이해는 안되지만, Bug를 순식간에 수정하고, 자동 모듈 시험을 확인한 뒤,
수정 사실을 모두에게 알려드렸습니다.

나중에 안 사실이지만, console에 trace를 켜면 timing상에 delay가 생기게 된다고 하는 군요.
이 delay때문에 일어난 일이고, 이런 상황을 위해 원격 trace는 조금 늦게 보여지지만 코드 수행상의 delay는 최소화 시켜 구현되어 있다고 알려주셨습니다.

그러시면서 팀원들은 모두 모아, 노우하우 하나를 들려주십니다.

제가 모듈을 개발하면서 가장 힘든 일이 뭐였을까요?
모듈 자체를 개발하는 일은 워낙 신나는 일이기 때문에, 조금 어렵더라도 힘들지는 않습니다.
힘든 일은 개발 이외의 일들이죠.  두 가지가 있는데 하나는 integration이고 다른 하나는 시험과 A/S입니다.

사실 두 가지 모두 다 시험입니다.
Integration이라는 것은 담당자와 담당자 간의 믿음을 시험하는 것이니까요.
한 사람은 '버그의 원인이 발견되기 전에는 나 또한 의심에서 자유로울 수 없다' 고 생각하지만 어떤 사람은 '버그의 원인이 나라고 증명되기 전까지는 의심받으면 안 된다' 라고 생각하지요.  첫 번째 분하고 일하는 것은 언제나 즐거운 경험이지만, 두 번째 분하고 일하는 것은 약간의 기술과 지혜가 필요합니다.

그분이 버그의 원인이라는 것을 증명해 드리는 일이죠.
문장만 읽어보면 무슨 원한 관계 같이 들리지만, 누가 버그의 원인인지를 빨리 파악하는 건 모두에게 행복한 일입니다.  설령 원인이 저라도 말입니다.  그래야 더 재미있는 개발할 시간이 생기죠. 

Integration의 버그는 대부분 interface에 발생합니다.
그래서 trace는 다른 사람이 내 interface 부를 때 사용한 내용을 표시하고, return된 값이나 output으로 돌려준 값을 return시에 표시합니다.  그리고 다른 담당자의 interface를 호출할 때도 보낸 값과 수신된 값을 찍는 경우가 있습니다.  사실 이런 경우는 특별한 경우로써, 모두 interface entry부분에서 표시해주면 중복이 되는 부분이지만, 문화의 차이로 인해 entry, exit에 대한 trace가 없는 경우에는 사용을 해야지만 버그의 담당자를 확실하게 찾을 수 있는 방법입니다.  또한 entry부분의 stack display를 켜주면 누가 interface를 부르고 있는지도 알 수 있지요.
명확한 증거입니다.

trace를 켜서 보면 대부분의 버그의 직접적인 원인을 찾을 수 있습니다.
부족한 부분을 채워주는 것이 dcom이죠.  dcom으로 내부의 상태를 보면 직접적인 원인이 발생하게 된 간접적인 원인을 파악하는 데 도움이 됩니다.  dcom에 어떤 명령어를 어떤 방식으로 넣느냐는 예술이죠.  정답이 없습니다.  사용하면서 발전하는 거죠.

일반적으로 많이 사용되는 memory의 사용정보, memory값 확인, task정보 등은 기본적으로 제공됩니다.  trace와 dcom을 사용하면 빠른 시간 내에 버그의 원인을 찾는데 많은 도움이 됩니다.

여기서 부가적으로 사용할 수 있는 몇 가지를 보면, verify, diag 그리고 원격 debugging등이 있습니다.
verify는 일종의 watchdog입니다.
예를 들어 circular Q의 크기가 10이라고 합시다.  circular Q의 count를 두었는데 속도를 위해 매번 계산하지 않고 interface부분에서 별도로 계산을 합니다.  빠르긴 하지만 잘못될 가능성이 있는 거죠.  이런 경우 dcom에 verify라는 명령어를 만들고 여기서 count의 값이 0..10 이외의 값인지를 확인합니다.  ++나 --를 잘못 사용해서 count값이 엉망이라면 verify가 잡아냅니다.  저는 그저 한번씩 verify라고 쳐보면 됩니다.  시간을 두고 주기적으로 verify를 실행해도 되겠군요.  거기서 log를 만들면 저는 앉아서 모는 사실을 알 수 있을 테니까요.  좋은 세상입니다.

verify는 사용할 곳이 많습니다.
memory가 조금씩 없어지는 버그도 verify를 사용하면 실마리를 잡을 수 있습니다.
memory의 증가치를 지켜보면 되거든요. 내부 buffer pool이 없어지는 경우도 비슷합니다.
task가 starvation이 일어나는지 지켜 볼 수 도 있고, 다른 task의 stack영역을 침범하는지도 확인할 수 있습니다.  상상해 보십시오.  스스로 상태를 확인 하는 곳에는 모두 사용할 수 있습니다.

diag는 조금 더 active한 디버깅 방법입니다.
언젠가는 HAL이 생기고 H/W device diagnostic이 생겨나겠지만, 그때 까지만 이라도 버텨야 합니다.  정말이지 초기에 H/W device diagnostic기능은 대단히 중요한 기능입니다.  memory나 device의 일부분이 오 동작 하는 경우, Integration된 장비에서 그 원인을 찾는 일은 너무나도 많은 시간이 소요됩니다.
전 그런 일에 제 시간을 쓰고 싶지 않거든요.  구현하고 싶은 것이 얼마나 많습니까? 하하
그때까지 당분간 사용할 (꼭 그렇지는 않지만) diagnostic 명령어 입니다.  diag라고 치면 H/W device를 시험합니다.  근데 runtime시험은 초기 시험에 비해서 어렵고, 제한사항도 많습니다.  그래서 제한적이죠.  초기 시험이 완벽하고, runtime시험도 조금 있는 (몇 년 동안 켜두면 중간에 고장 나기도 하거든요) 그런 환경이 좋아 보입니다.

마지막으로 원격 디버깅입니다.

원격 디버깅하면 근사해 보이지만, 실제로는 원격에 있는 console을 아주 멀리 끌고 온 것이죠.  울릉도에 장비가 오 동작을 한다고 전화가 왔습니다.  전화로 한 시간째 이야기를 하고 있는데 마치 외국사람하고 이야기하는 기분입니다.  당췌 그쪽 상황이 어떤지 잘 이해가 안 되는 군요.  가까운 곳이라면 당장 차를 몰고 가보고 싶습니다.
근데, 울릉도라면… 이런 배를 타고 하루 걸리는 곳인데.  후…
엇, 그런데 다행히도 Internet이 되는군요.  (오~ 대한민국입니다.)
원격에서 console을 볼 수 있다는 debugch을 연결해 봅니다.  오 이런, 조금 느리기는 하지만 console의 내용이 다 보입니다.  장비가 눈앞에 없어서 답답할 뿐이지, 어느 정도 감은 옵니다.  (NMS을 연결해보니 장비 모양도 얼추 보이는군요. 아싸~)  Console을 연결하고 설명을 들어보니 상황이 이해가 됩니다.

누군가가 설정이 잘못해놨군요.  UI를 잘못 눌러서 설정이 변경되었나 봅니다.  다음에 이런 전화를 안받으려면, 이런 설정은 운영자가 깜짝 놀라도록 큼지막한 경고! 표시를 해둬야겠습니다.

흐뭇한 마음으로 그 동안 켜놓았던 trace를 끄려고 하는데, 이런 통신 두절입니다.  ping을 해보았더니 안 되는 군요.  아마 지나가던 오징어배가 광케이블을 건드렸나 봅니다.  (나중에 안일이지만 허브의 망가진 랜 컨넥터가 헐거워 졌더군요.  케이블 갈아야겠습니다)  그래도 괜찮습니다.  원격장비에서 trace를 보내다가 지치면 자동으로 꺼질 겁니다.  물론 더 이상 이곳으로 trace를 보내는 수고를 하지도 않을 거고요.

그나저나, 울릉도를 다녀오려면 1박2일이었는데, 전화로 해결이 되어 얼마나 다행인지 모르겠군요.  저희 사장님도 좋아하시네요.  '울릉도 이틀이면 비용이 얼만데…'
이제 즐거운 개발 시간이군요.  야호~

PS. 지금 생각난 것인데, 버그의 실마리를 찾기 위해, NMS의 경우 사용자가 조작한 UI의 순서와 값들을 Replay할 수 있으면 좋겠다는 생각이 듭니다.  장비의 경우에는 수행한 명령어의 log가 많은 도움이 될 겁니다.