패킷분석이 쓰이는 곳은 다양하다. 네트워크 트래픽, 응용프로그램간의 트래픽 등등.
이번에는 응용프로그램 관점에서 한번 접근해 보고자 한다. 필자가 간단하게 동작시켜 운영하는 프로그램이 하나 있었다. 자동으로 FTP 에 연결하여 파일을 전송시키는데, 그 과정이 빠르게 이뤄지지 않고 눈에 보일만큼의 어느정도 Delay 가 발생하고 있었다. 이런 경우 다양한 원인이 존재하겠는데, 일단 다음과 같이 하나하나씩 문제의 원인을 찾아나가 보았다.
1) FTP 클라이언트와 서버간 트래픽 확인
tcpdump 를 이용하여 트래픽 덤프를 시작한후, 수동으로 FTP 전송 프로그램을 실행하였다. 다음과 같은 트래픽을 관찰할 수 있었는데, NBT UDP 패킷인 Query 가 보였다. 대략 보면 14:21:18 에 나타났고, 14:21:21 까지 지속되었다. 여기서 몇 초간의 지연이 발생하는 것을 확인하였고, 왜 이런 형태가 나타나는지 찾아야 하는 것이다.
# tcpdump -i eth0 host 192.168.x.x
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
14:21:18.246571 IP test.netbios-ns > comm-gw.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; UNICAST
14:21:18.246869 IP comm-gw.netbios-ns > test.netbios-ns: NBT UDP PACKET(137): QUERY; POSITIVE; RESPONSE; UNICAST
14:21:19.746141 IP test.netbios-ns > comm-gw.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
14:21:19.746448 IP comm-gw.netbios-ns > test.netbios-ns: NBT UDP PACKET(137): QUERY; POSITIVE; RESPONSE; UNICAST
14:21:21.246179 IP test.netbios-ns > comm-gw.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
14:21:21.246426 IP comm-gw.netbios-ns > test.netbios-ns: NBT UDP PACKET(137): QUERY; POSITIVE; RESPONSE; UNICAST
14:21:22.766782 IP test.1044 > comm-gw.ftp: S 1801204199:1801204199(0) win 65535 <mss 1460,nop,nop,sackOK>
14:21:22.766806 IP comm-gw.ftp > test.1044: S 1835421802:1835421802(0) ack 1801204200 win 5840 <mss 1460,nop,nop,sackOK>
2) nslookup 으로 혹시 DNS 쿼리 확인
혹시나 클라이언트에서 DNS resolving 이 관련있나 nslookup 을 통해 확인하였으니 정상적으로 빠르게 응답해 주었음
3) 넷바이오스와 관련한것 찾아 제거해보기
일단 넷바이오스와 관련한 것이다 보니 시스템 상에서 이와 관련한 것을 Disable 한 후 같은 증상이 계속 일어나는지 확인하기로 하였다. TCP/IP 설정의 고급에서 Wins -> Disable TCP/IP Over Netbios 한 후 UDP 패킷이 발생하지 않았다. 이제 해결된 것인가 ? 하고 FTP 연결을 다시 해봐도 똑같이 Delay 는 계속 발생되고 있다. 분명 이전에 나타났던 트래픽은 나타나지 않지만 지연은 계속된다는 점이다.
시스템 관점에서 몇 가지를 다 확인해 보아도 증상은 해결되지 않았다.
4) 마지막으로, 응용프로그램을 직접 디버깅
호출되는 FTP 응용프로그램을 직접 디버깅을 하여 무엇이 원인인지 세부적으로 접근해 보고자 하였다. 사용한 디버거는 Ollydbg 이며, 실행을 해 나가면서 각 코드별로 Delay 되는 부분은 없는지 찾아나갔다. 그러다, 0x0040A5E3 지점에서 Delay 가 발생하는 것이었다.
gethostbyaddr 를 Call 하면서 발생된 문제였던 것이다. 대략 여기서 5-10 초 정도의 딜레이가 발생하였던 것인데, 이후 사용하는 DNS 에서 Reverse DNS 레코드를 추가하였더니 문제가 깔끔히 해결되었다. 바로 gethostbyaddr API 를 호출하는 과정에서 Delay 가 발생한다는 사실을 알았기 때문이다.
물론, Delay 가 발생하여도 시스템 동작상에는 큰 이슈가 없었지만. 향후 이런 지연 요소가 시스템 전체 과정상에 영향을 줄 수 있는 부분이기 때문에 확실히 해결하고 넘어가는 것이 좋다.
이번 CaseStudy 로 다뤄본 부분은, 직접적인 네트워크 원인으로만 단정짓지 말고 분석을 시작하지 말자는 점이다. 문제해결을 위해 전체를 들여다보고 분석하는 과정에서 트래픽에서 발생된 특정 패턴으로 인해 이게 문제의 원인이다 하고 가정을 해 버리면 접근관점이 한정되어 문제해결 파악에 시간이 걸리게 된다. 위에서 발생한 UDP 패킷만 보고 왜 이게 발생하지 하고 시스템과 네트워크의 관점에서만 계속 문제를 찾다보면 해결이 어려워진다는 것이다. 물론, 결국은 gethostbyaddr 에 의해 발생되어 전체적인 관점에서 보면 네트워크와도 연결이된 것이 맞지만. 필자가 말하는 것은, 문제 원인 파악에는 직접적으로 문제의 원인을 파악하고자 하는 그 대상으로부터 차차 찾아 넓혀가야 한다는 것이다.
즉, 문제의 원인 파악에는 혼자가 아니라 각 관련 담당자들의 도움이 있어야 해결이 쉬워진다. 이와 관련해서는 다음 CaseStudy 에서 왜 협업이 필요한지에 대해서 의견을 나눠보도록 하겠다.
[참고]
1. gethostbyaddr()
댓글 없음:
댓글 쓰기