늘 있는 일이었지만, 특별히 더 이상한 일이었다. 분명히 발생하는 장애였다. 하지만 늘 그랬듯이 불규칙적이었고, 재현이 불가능하였다.
사건의 발생은, 고객사 중 하나에서 “정상적으로 음성메시지를 남겨도, 실제로 음성 메시지를 플레이 할 때는, 아무 소리가 안난다”는 것이었다. 가볍게 생각했다. record 함수의 잘못된 사용이나, 녹음할 데이터가 없었거나….
일단, 로그 파일부터 확인했다.
/var/log/freeswitch/freeswitch.log
먼저 문제가 발생한 케이스를 추려내고, 그 다음, 정상적인 케이스의 로그를 비교해보았다. 모든 부분에서 같은 내용이었지만, 단 한곳 다른 부분이 있었다.
[DEBUG] switch_rtp.c:5617 Correct ip/port confirmed.
문제가 발생한 로그에서는 위의 라인이 빠져 있었던 것. 바로 freeswitch 소스 파일을 확인해보았다. 해당 로그 라인이 어떨때 나타나는 로그인지 확인했다. 해당 로그는 freeswitch 에서 RTP 패킷을 read 를 시작할 때, 나타내는 로그 중 하나였다. 즉, 문제가 되는 로그에서는 RTP read 시작 로그를 확인할 수 없었다.
이상했다. 왜냐하면 나머지 SIP 관련 로그들은 정상적으로 송/수신 했기 때문이다. 로그내용으로 확인할 수 있었다.
그리고 분석된 장애 내용은 실제로 사용자는 음성사서함 메시지를 남기려고 시도 했었지만 무슨일이에선지, 생성된 wav 파일 사이즈가 모두 44 바이트(wav header size)가 생성되는 현상이었다.
그리고.. 계속된 재현 실패.. 수십 차례에 걸친 다양한 테스트 케이스에도 재현에 성공할 수 없었다. 사실 44 byte가 녹음되는 현상은 몇개 찾을 수 있었다. 하지만 더 세밀한 분석 결과, 이번 장애와는 상관없는 다른 이유에서 발생한 것으로 결론이 난 것들이었다.
그러다가 겨우겨우 오늘 재현에 성공했다.
앞서 말했듯이, 장애는 불규칙적으로 발생하고 있었다. 하지만 그 중에서도 장애가 ‘자주’ 발생하는 고객사가 있었는데, 그 고객사의 전화번호를 이용해서 재현할 수 있었던 것이다.
우리회사는 덴마크에 있었고, 해당 고객사는 독일에 있었다. 덴마크에서 독일 고객사로 전화를 걸어 음성 메시지를 남기면 정상적으로 남길 수 있었다. 하지만 독일 전화번호를 이용하여 독일 고객사로 전화를 걸면 44 바이트의 음성 파일이 생성되는 것이었다.
좋다. 이제야 겨우 재현에 성공했다. 여기까지 도달하기까지 굉장히 많은 시간이 걸렸다(약, 2주일?)
아무튼 테스트를 진행했는데, 모든 서버에서 tcpdump 명령어를 이용하여 패킷을 캡쳐하고 해당 캡쳐 내용들을 비교했다. 분석된 내용은 독일 네트워크 어딘가에서 RTP 패킷을 차단하고 있었던 것. 왜 차단을 했을까? 열띤 토론끝에, 이런 현상은 비단 독일뿐 아니라, 다른 어느곳에서도 가능한 현상이라는 추측이 나왔다. 그래야만 그동안 발생했던 불규칙 장애에 대한 설명이 된다는 것이다.
결론적으로… 아직까지 장애는 진행중이다. 이제야 겨우 재현에 성공하고 문제의 실마리를 잡았기 때문이다. 그리고, 오늘로써 개발자(나)의 잘못이 아닌것으로 밝혀졌지만(ㅎㅎㅎㅎㅎ) 그것과는 별개로 굉장히 인상적인 장애였고, 장애 분석이었다.
왜냐하면, 오늘 네트워크 관리자, 개발자(나), 개발 선임, 컨설턴트 이렇게 4명이 모여 이런저런 토론을 하고, 구체적인 방법을 구상하고, 테스트를 했는데 굉장히 인상적이었기 때문이다.
결론은…혼자 끙끙 앓고 있던 2주일간의 고민이 한방에 해결되었다. 🙂