2013년 11월 13일 수요일

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

댓글 8개:

  1. 좋은 글 잘 읽었습니다. ^^
    저라면 접속이 되니까 그냥 사용했을 겁니다. ;ㅅ;
    사소하다고 생각될 수 있는 부분에서도 의문을 가지고 탐구하는 모습이 저에게 많은 것들을 느끼고 생각하게 해 주었습니다. 감사합니다. ^^

    답글삭제
    답글
    1. 방문해 주셔서 감사합니다^^

      삭제
  2. 10초면 접속 안되네 하고 떠나 갈 시간인데, 이런 멋진 분석을 !!!

    답글삭제
  3. 안녕하세요 네트워크 패킷쪽은 어떤지 해서 공부하고 있는 학생입니다
    현재 책안사고 Rigel님이 올리신 글내용을 처음부터 보면서 모르는 것 인터넷에 찾아보면서 배우고 있는데요.(다 볼려면 멀었습니다.ㅋ) 책없이 해도 괜찮을가요?

    답글삭제
    답글
    1. 안녕하세요. 네트워크 패킷의 범위가 너무 넓다 보니 어떤방법이 정답이다라고 말씀드리기는 어려울것 같습니다. 만약 네트워크 패킷에 대해 처음 접해보신다면 관련 서적을 보시는게 우선 도움이 되실것 같습니다. 블로그 올린 내용들이 체계적으로 순서에 맞춰 작성된 것이 아니기 때문입니다.

      아니면 제가 5년 안에 한번 책을 출간해 보도록 하겠습니다 ^^;;;

      삭제
  4. 눈팅만 하다가 처음 댓글을 답니다 ^^:
    이번글은 더 재밌게 봤거든요.
    디버깅 과정/절차가 있으니 다른 분들도 큰 도움이 될꺼 같네요.
    고맙습니다-

    답글삭제
  5. 가능하시다면 -n 옵션 사용방법에 대해 자세히 설명해 주실 수 있으세요?

    답글삭제
  6. 안녕하세요. 이 댓글을 보실 지 모르겠지만 질문을 드려 봅니다.

    1. A서버->B서버로 FTP 접속 및 데이터전송 잘 됨
    2. A서버->B서버로 java web app에서 사용하는 FTP 라이브러리 통하면 접속은 되나 데이터전송 안 됨 (timeout)
    3. 2번은 오래전부터 A->기타 다른 서버들로는 잘 사용하고 있는 모듈임
    4. 2번이 안 돼서 passive 모드로 세팅 후 하니 접속 및 데이터전송 잘 됨

    이런 경우는 어떻게 원인을 찾을 수 있을까요?

    답글삭제