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