CaseStudy, FTP 접속 지연 원인 - 10초의 흔적을 찾아라!

오래간만에 쓰는 포스팅인것 같습니다. 이런저런 일들이 많다보니 블로깅도 게을러지고 있네요. :-)

오늘은 CaseStudy 형태로 애플리케이션의 접속 지연에 대해서 실제 사례를 한번 다뤄볼까 합니다. FTP 접속을 언급하려고 하는데, 이전에도 한번 사례로 FTP 를 다룬적이 있습니다. 약간 비슷할 수도 있지만 관점이 조금 다르긴 합니다. 일단 분석하게 된 이유는 이렇습니다.

FTP 를 통해서 특정 시스템에 접속하는데 접속이 바로 이뤄지지 않고 지연이 발생하는 것입니다.

C:\>ftp 192.168.0.1
Connected to 192.168.0.1.

여기서 10 초정도의 지연이 발생하고 다음과 같이 접속이 이뤄집니다.

C:\>ftp 192.168.0.1
Connected to 192.168.0.1.
220 TEST FTP server (Version 6.4/OpenBSD/Linux-ftpd-0.17) ready.
User (192.168.0.1:(none)):

일단 시스템에서 패킷 덤프를 해 보았습니다. 일반적인 3way Handshake 과정이 이뤄지고 있습니다. 클라이언트인 192.168.98.128 이 comm-gw(192.168.0.1) FTP 포트에 SYN 패킷을 보내면서 연결 시도를 합니다.

11:15:31.363275 IP 192.168.98.128.1087 > comm-gw.ftp: S 1725038219:1725038219(0) win 65535 <mss 1460,nop,nop,sackOK>
11:15:31.363305 IP comm-gw.ftp > 192.168.98.128.1087: S 3794060333:3794060333(0) ack 1725038220 win 5840 <mss 1460,nop,nop,sackOK>
11:15:31.363554 IP 192.168.98.128.1087 > comm-gw.ftp: . ack 1 win 65535



11:15:37.309023 IP 192.168.98.128.netbios-dgm > 192.168.255.255.netbios-dgm: NBT UDP PACKET(138)
11:15:42.577429 IP comm-gw.ftp > 192.168.98.128.1087: P 1:72(71) ack 1 win 5840
11:15:42.714480 IP 192.168.98.128.1087 > comm-gw.ftp: . ack 72 win 65464


그런데 ACK 까지 전달이 되고 통신을 하는 과정에서 지연이 보입니다. 11:15:31초 후에 42초 쯤 관련된 트래픽이 나타납니다. 클라이언트 관점에서 봤을때는 연결이 이뤄지고 서버에서 응답이 오기까지 지연이 보이는 것으로 추정됩니다.


일반적으로 이런 지연이 발생되는 원인중에 하나로 Name Lookup 이 있습니다. 그래서 /etc/hosts 파일에 해당 클라이언트 IP 를 넣어주고 패킷 덤프를 다시 해 봅니다.

# tcpdump -i eth4 host 192.168.98.128
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth4, link-type EN10MB (Ethernet), capture size 96 bytes


11:18:11.836148 IP aa-05-01.proofd > comm-gw.ftp: S 3515309442:3515309442(0) win 65535 <mss 1460,nop,nop,sackOK>
11:18:11.836173 IP comm-gw.ftp > aa-05-01.proofd: S 2006125397:2006125397(0) ack 3515309443 win 5840 <mss 1460,nop,nop,sackOK>
11:18:11.836340 IP aa-05-01.proofd > comm-gw.ftp: . ack 1 win 65535
11:18:11.837724 IP comm-gw.ftp > aa-05-01.proofd: P 1:72(71) ack 1 win 5840
11:18:11.955346 IP aa-05-01.proofd > comm-gw.ftp: . ack 72 win 65464
^C


그런데, 앞서 본 것과 달리 속도 지연이 없어졌습니다. 11:18:11 안에 모든 과정들이 끝나버렸습니다. 10초 이상 지연이 발생한 것과는 대조적입니다. 조금 더 자세히 살펴보기 위해 ftp 데몬을 추적해 보기로 했습니다. 다만, ftpd 데몬이 지속적으로 떠 있는 것이 아니라 inetd 데몬에 의해서 접속시 마다 프로세스가 생성되므로 다음과 같이 해 보았습니다.

1초마다 프로세스를 살펴봐서 in.ftp 문자열이 검색되면 해당 프로세스 ID 를 넘겨받아 strace -p PID 로 하는 것입니다.

# while true; do ps -ef | grep in.ftp | grep -v grep | gawk -F' ' '{system("strace -p "$2)}'; sleep 1; done

Process 16864 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 1
ioctl(4, FIONREAD, [43])                = 0
recvfrom(4, "\360\275\201\202\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("168.126.63.1")}, [16]) = 43
close(4)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 28) = 0
fcntl64(4, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
gettimeofday({1382065750, 265867}, NULL) = 0
poll([{fd=4, events=POLLOUT}], 1, 0)    = 1 ([{fd=4, revents=POLLOUT}])
send(4, "\360\275\1\0\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 43, MSG_NOSIGNAL) = 43
poll([{fd=4, events=POLLIN}], 1, 3000)  = 1 ([{fd=4, revents=POLLIN}])
ioctl(4, FIONREAD, [43])                = 0
recvfrom(4, "\360\275\201\202\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 43
close(4)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("168.126.63.1")}, 28) = 0
fcntl64(4, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
gettimeofday({1382065752, 399158}, NULL) = 0
poll([{fd=4, events=POLLOUT}], 1, 0)    = 1 ([{fd=4, revents=POLLOUT}])
send(4, "\360\275\1\0\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 43, MSG_NOSIGNAL) = 43
poll([{fd=4, events=POLLIN}], 1, 6000)  = 1 ([{fd=4, revents=POLLIN}])
ioctl(4, FIONREAD, [43])                = 0
recvfrom(4, "\360\275\201\202\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("168.126.63.1")}, [16]) = 43
close(4)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("168.126.63.1")}, 28) = 0
fcntl64(4, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
gettimeofday({1382065753, 199402}, NULL) = 0
poll([{fd=4, events=POLLOUT}], 1, 0)    = 1 ([{fd=4, revents=POLLOUT}])
send(4, "\360\275\1\0\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 43, MSG_NOSIGNAL) = 43
poll([{fd=4, events=POLLIN}], 1, 5000)  = 0 (Timeout)
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 5
connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 28) = 0
fcntl64(5, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(5, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
gettimeofday({1382065758, 201686}, NULL) = 0
poll([{fd=5, events=POLLOUT}], 1, 0)    = 1 ([{fd=5, revents=POLLOUT}])
send(5, "\360\275\1\0\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 43, MSG_NOSIGNAL) = 43
poll([{fd=5, events=POLLIN}], 1, 3000)  = 1 ([{fd=5, revents=POLLIN}])
ioctl(5, FIONREAD, [43])                = 0
recvfrom(5, "\360\275\201\202\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 43
close(4)                                = 0
close(5)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("168.126.63.1")}, 28) = 0
fcntl64(4, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
gettimeofday({1382065758, 888660}, NULL) = 0
poll([{fd=4, events=POLLOUT}], 1, 0)    = 1 ([{fd=4, revents=POLLOUT}])
send(4, "\360\275\1\0\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 43, MSG_NOSIGNAL) = 43
poll([{fd=4, events=POLLIN}], 1, 6000)  = 1 ([{fd=4, revents=POLLIN}])
ioctl(4, FIONREAD, [43])                = 0
recvfrom(4, "\360\275\201\202\0\1\0\0\0\0\0\0\003128\00298\0015\003111\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("168.126.63.1")}, [16]) = 43
close(4)                                = 0
open("/etc/nologin", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
open("/etc/ftpwelcome", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
uname({sys="Linux", node="TEST", ...}) = 0
stat64("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=119, ...}) = 0
stat64("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=119, ...}) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC)  = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=336, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4f000
read(4, "127.0.0.1\tlocalhost\n127.0.1.1\tTES"..., 4096) = 336
read(4, ""..., 4096)                    = 0
close(4)                                = 0
munmap(0xb7f4f000, 4096)                = 0
fstat64(1, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4f000
write(1, "220 TEST FTP server (Version"..., 71) = 71
rt_sigaction(SIGALRM, {0x804ef40, [ALRM], SA_RESTART}, {SIG_DFL}, 8) = 0
alarm(900)                              = 0
fstat64(0, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4e000
read(0, ^C <unfinished ...>
Process 16864 detached
Process 16864 attached - interrupt to quit
read(0, ^C <unfinished ...>
Process 16864 detached
Process 16864 attached - interrupt to quit
read(0, quit
^\ <unfinished ...>
Process 16864 detached

Process 16864 attached - interrupt to quit
read(0, ^C <unfinished ...>
Process 16864 detached
Process 16864 attached - interrupt to quit
read(0,
^C <unfinished ...>
Process 16864 detached
^\Quit
Process 16864 attached - interrupt to quit
read(0, ^Z


여기서는 실제로 보여주는 것이 한계가 있지만, strace 로 해서 보면 name lookup 하는 부분에서 딜레이가 발생하는 것이 보입니다. 즉, 이런 형태를 검증해 보는 하나의 방법으로 보시면 될것 같습니다. 하지만, 여기에 문제가 있습니다. 접속하는 클라이언트가 수백대가 넘게 있습니다. 그 IP 들을 일일이 넣어주기도 쉽지가 않습니다. 분명히 또 다른 방법이 있을것입니다. 'man in.ftpd' 를 통해서 세부적인 옵션을 확인해 보았더니 -n 이라는 것이 있습니다.

 -n      Use numeric IP addresses in logs instead of doing hostname lookup.

ftpd 데몬을 많이 써보았지만 굳이 옵션을 찾아볼 일이 없었는데 -n 이 호스트이름 대신 IP 주소로 사용하여 로그를 기록하게 되어 있네요. 자 그래서 -n 옵션을 사용해 반영했더니, 동일하게 모든 클라이언트에서 접속해도 빠른 속도로 접속이 이뤄집니다.

/etc/hosts 파일에 개별적으로 사용할 수도 있지만 좀더 광범위하고 효율적인 작업면에서는 -n 옵션이 더욱 적절했던 것입니다.

패킷덤프를 통해서 패킷의 흐름을 살펴보고, 서버에서의 응답에 지연이 있는 것으로 판단되어 서버단에서 문제를 찾아들어가며 해결한 경우입니다. 문제가 발생할 경우 해결하기 위한 방법에는 메뉴얼 처럼 딱 정해진것이 없습니다. 기본 해결 방법은 같을 수 있지만 그것을 찾아들어가기 위한 것은 다양합니다. 이것또한 그 중에 하나입니다.

어떤이는 접속이 되니까 그냥 그대로 사용할 수도 있고 또 다른 사람은 왜 지연이 있을까 하고 의문을 갖게 됩니다. 물론 이런 지연이 영향을 미칠만큼이냐 또는 아니냐에 따라서 판단은 달라지게 됩니다. 하지만 이런것에 Question 을 가지고 계속 질문해 보면 그 답을 찾는 과정에서 많은 것을 얻고 배우게 됩니다. 바로 이런것이 Experience 입니다. 저 또한 블로그를 하는 이유가 이러한 경험을 여러분들과 함께 공유하기 위함입니다.

자, 그럼 오늘은 여기까지 하고 마무리 짓겠습니다.

문제가 발생했을때 실마리를 어떻게 풀어나갈것인지 참고가 되었으면 좋겠습니다.

/Rigel

FTP(File Transfer Protocol)가 벌써 40주년이 되었다네요!

최근 기사를 보니,  파일전송 프로토콜의 대명사인 FTP(File Transfer Protocol)가 어느덧 40주년을 맞이했다고 한다. 정확히는 4월16일 이다. FTP 의 RFC 문서가 나온년도는 1971 년이다. 40주년이나 되었다는 것이 믿기지 않을 정도로, 이렇게 빨리 시간이 흘렀나 하는 생각이 든다. 처음 이 프로토콜은 1971년 4월 MIT 의 Abhay Bhushan 에 의해서 제안되었고 인테넷의 근간이 되는 ARPANet 에서 두 시스템 사이에서 대량의 파일을 전송하기 위한 것이었다.

보안적으로 보면, 그 당시는 보안이 크게 고려되지 않아 Clear Text 로 사용자이름과 패스워드가 네트워크 상으로 전송되었다. FTP 세션을 맺을때 랜덤한 포트 번호가 할당되어서 감청과 같은 부분도 괜챦을 것이라 생각하였지만, 그것은 보안장치로서는 부족하다는 것을 알게되었고, SSL 과 같은 보안 매커니즘이 같이 결합되어 사용되었다.

지금은 보안을 고려한 전송 방식도 많이 나와있지만, 아직까지도 FTP 는 파일 전송으로 대중적인 프로토콜 임은 분명하다. 나 또한, 내부 시스템끼리는 즐겨 사용한다. SFTP, SCP 등을 쓸 수도 있지만, 역시나 편한 것은 이것이 아니겠던가? 물론, 보안이 꼭 필요한 곳은 암호화가 사용되지만 말이다.

40주년이 된, FTP 가 과연 얼마나 우리 귀에 익숙하게 오르내릴지는 모르지만...

[참고]
1. RFC114, A FILE TRANSFER PROTOCOL
http://tools.ietf.org/html/rfc114
2. The Register, FTP celebrates ruby anniversary
http://www.theregister.co.uk/2011/04/15/ftp_turns_40/
3. ARPANet
http://en.wikipedia.org/wiki/ARPANET

두번째 CaseStudy, 한가지 원인으로만 단정짓고 시작하지 말자.

패킷분석이 쓰이는 곳은 다양하다. 네트워크 트래픽, 응용프로그램간의 트래픽 등등.

이번에는 응용프로그램 관점에서 한번 접근해 보고자 한다. 필자가 간단하게 동작시켜 운영하는 프로그램이 하나 있었다. 자동으로 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()

http://msdn.microsoft.com/en-us/library/ms738521(VS.85).aspx