DNS issue

서비스 Timeout 이슈

nginx log

upstream_response_time 10초 발생

packet dump

해당 시간대 패킷 확인해보니 nginx -> 2번서버 으로 연결 nginx -> 2 POST Request 후 API#2에서 ACK 바로 수신됨 2번서버 -> nginx 대략 10초 있다가 200 ok Response

apm Log

APM 로그 확인해보니

총 422ms 애플리케이션은는 159 ms만에 처리되었다고 나옴

클라이언트 입장에서는 10초 이상 걸려서 timeout 발생 그 후 재시도 했는데 우리측 서버에서는 이미 처리된 입장이여서 500 error response 하는 상황 인 것 같음

여기서 중요한건 왜? 2번 서버는 바로 응답을 주지 않았을까?

다른 case

찾다보니 다른 클라이언트도해당 시간대에 동일한 현상을 확인했다.

찾아보니 2024.03.13 18:35:32 ~ 18:35:59 해당 시간대에 response_time이 굉장히 높음

동시간대 확인해보니 서버에 올라가있는 특정 애플리케이션만 발생함

서버#1

위 케이스는 2번서버에서 확인했을 때의 내용임

2024.03.13 18:35:32 ~ 18:35:59 시간대 1번도서버 확인해보니 동일하게 발생됨

왜 서버들이 Response를 느리게 주는걸까 ?

1. nginx 문제?

위 캡쳐들은 API 서버에서 캡쳐한 것 Request를 정상적으로 받고 ack도 날림. nginx 문제는 아닐 것 같음

2. 그럼 왜 어플리케이션에 찍힌 request 시간은 nginx request 시간과 다른가?

원인

실제로 어플리케이션 로그를 확인해보면 Mar 14, 2024 @ 13:43:51.497에 받았고 Mar 14, 2024 @ 13:43:56.531에 어플리케이션 Incoming request이 되었다고 한다.

이 공백의 5초는 무엇일까

strace

10109 16:27:30 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 113
10109 16:27:30 fstat(113, {st_mode=S_IFREG|0644, st_size=1305, ...}) = 0
10109 16:27:30 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5d0d371000
10109 16:27:30 read(113, "127.0.0.1\tlocalhost localhost.localdomain localhost4 localhost4.localdomain4\n::1         localhost localhost.localdomain localhost6 localhost6.localdomain6\n192.168.1.217\tiserveme.iremit-inc.com\n172.31.253.150\tgayo.finnet.co.id\n211.181.107.12\tdev.kjbank.com\n211.181.107.13\tapi.kjbank.com\n172.21.100.225\tspotcash.islamibankbd.com\n103.11.136.58\teremit-lv.dutchbanglabank.com\n192.168.77.150\twallet.hanpass.com\n192.168.77.71\tpg-zeropay-api.hanpass.com\n192.168.77.71\tpg-settlement-api.hanpass.com\n63.91.129.157\tws.moneygram.com\n192.168.77.35\tapi.hanpass.com\n192.168.77.35\tpaygate.hanpass.com\n192.168.77.35\topp.hanpass.com\n192.168.77.35\tapp.hanpass.com\n172.16.200.20\tworks.hanpass.com\n185.178.51.17\ttransfer.myuzcard.uz\n192.168.7.249\tmail.hanpass.com\n192.168.77.53\tapp-beta.hanpass.com\n192.168.77.37\tlivetest-opp.hanpass.com\n192.168.77.211  auth.hanpass.com\n103.11.172.104  vcbr\n192.168.77.60\tinbound.hanpass.com\n192.168.77.33\ttest-hpg.hanpass.com\n10.189.1.131\thpg.hanpass.com\n10.189.50.149\tdev-fleet.hanpass.com\n10.189.50.150\tprd-fleet.hanpass.com\n10.189.50.151\tLogstash-1\n10.189.50.152\tLogstash-2\n10.189.50.153\tES-1\n10.189.50.154\tES-2\n10.189.50.155\tES-3\n10.189.50.156\tKibana\n\n10.189.1.49 \tpsa.hanpass.com\n10.189.11.31\tdiscovery-a.hanpass.com\n10.189.11.32\tdiscovery-b.hanpass.com\n10.189.1.49\tcoupon.hanpass.com\n", 4096) = 1305
10109 16:27:30 read(113, "", 4096)      = 0
10109 16:27:30 close(113)               = 0
10109 16:27:30 munmap(0x7f5d0d371000, 4096) = 0
10109 16:27:30 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 113
10109 16:27:30 setsockopt(113, SOL_IP, IP_RECVERR, [1], 4) = 0
10109 16:27:30 connect(113, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
10109 16:27:30 poll([{fd=113, events=POLLOUT}], 1, 0) = 1 ([{fd=113, revents=POLLOUT}])
10109 16:27:30 sendto(113, ">\244\1\0\0\1\0\0\0\0\0\0\00210\00277\003168\003192\7in-addr\4arpa\0\0\f\0\1", 44, MSG_NOSIGNAL, NULL, 0) = 44
10109 16:27:30 poll([{fd=113, events=POLLIN}], 1, 5000 <unfinished ...>
10109 16:27:35 <... poll resumed>)      = 0 (Timeout)
10109 16:27:35 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP <unfinished ...>
10109 16:27:35 <... socket resumed>)    = 50
10109 16:27:35 setsockopt(50, SOL_IP, IP_RECVERR, [1], 4) = 0
10109 16:27:35 connect(50, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.4.4")}, 16) = 0
10109 16:27:35 poll([{fd=50, events=POLLOUT}], 1, 0) = 1 ([{fd=50, revents=POLLOUT}])
10109 16:27:35 sendto(50, ">\244\1\0\0\1\0\0\0\0\0\0\00210\00277\003168\003192\7in-addr\4arpa\0\0\f\0\1", 44, MSG_NOSIGNAL, NULL, 0) = 44
10109 16:27:35 poll([{fd=50, events=POLLIN}], 1, 5000 <unfinished ...>
10109 16:27:40 <... poll resumed>)      = 0 (Timeout)
10109 16:27:40 poll([{fd=113, events=POLLOUT}], 1, 0 <unfinished ...>
10109 16:27:40 <... poll resumed>)      = 1 ([{fd=113, revents=POLLOUT}])
10109 16:27:40 sendto(113, ">\244\1\0\0\1\0\0\0\0\0\0\00210\00277\003168\003192\7in-addr\4arpa\0\0\f\0\1", 44, MSG_NOSIGNAL, NULL, 0) = 44
10109 16:27:40 poll([{fd=113, events=POLLIN}], 1, 5000 <unfinished ...>
10109 16:27:45 <... poll resumed>)      = 0 (Timeout)
10109 16:27:45 poll([{fd=50, events=POLLOUT}], 1, 0) = 1 ([{fd=50, revents=POLLOUT}])
10109 16:27:45 sendto(50, ">\244\1\0\0\1\0\0\0\0\0\0\00210\00277\003168\003192\7in-addr\4arpa\0\0\f\0\1", 44, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
10109 16:27:45 <... sendto resumed>)    = 44
10109 16:27:45 poll([{fd=50, events=POLLIN}], 1, 5000 <unfinished ...>
9955  16:27:48 futex(0x7f5d046fcb04, FUTEX_WAIT_BITSET_PRIVATE, 1, {tv_sec=76717854, tv_nsec=510109998}, 0xffffffff) = -1 ETIMEDOUT (연결 시간 초과)
10109 16:27:50 <... poll resumed>)      = 0 (Timeout)
10109 16:27:50 close(113)               = 0
10109 16:27:50 close(50)                = 0
10109 16:27:50 socket(AF_NETLINK, SOCK_RAW|SOCK_CLOEXEC|SOCK_NONBLOCK, NETLINK_ROUTE) = 50

Strace를 조회 결과 Request 패킷을 받은 이후에 자신의 IP로 PTR 레코드 Lookup

API 서버에서 구글 DNS로 자신의 IP PTR 레코드를 지속적으로 조회 구글 DNS에서 응답이 없을 때 timeout 발생하는 것으로 확인 DNS Timeout 시간 기본 5초로 확인 됨

임시 해결책

# /etc/hosts
1.1.1.1 api-1.domain.com

ptr 레코드 lookup을 하지않게 hosts 파일에 임시로 작성

원인

어플리케이션 소스 코드에 dns lookup 하는 코드가 있어 제거 함.

그러나 서버들의 DNS 서버가 외부로 되어있어 timeout발생한 것이 2차적인 원인이라고 생각함

추후에 사이드 이펙트 확인해서 외부 dns를 내부 dns로 변경해야 겠다.

느낀점

1. 시스템콜의 중요성

트러블슈팅을하면서 어플리케이션의 시스템 콜을 분석하기 위해 strace 툴을 처음 써봤다. 보기가 쉽지않았지만 원인을 해결하는데 큰 도움을 줬다. 시스템 콜을 공부해야겠다.

2. 로그의 중요성

시스템콜을 분석하기 전까지 로그만 들여다 보면서 어떤 문제인지를 파악했다. 로그도 안찍혔었다면 원인을 찾는데 오래걸렸을 것 같다. 로그의 중요성을 다시한번 느꼈다.