Resolving Timeout
어느 날 APM에서 알람이 발생했습니다. 어떤 광고 콘텐츠를 노출하기 위해 호출하던 특정 외부 API에서 다량의 Timeout 에러가 발생하고 있다는 내용이었습니다.
당장 에러도 에러이지만, 그것보다 더 문제였던 것은 최장 15초에 달하는 지연이 발생하고 있다는 점이었습니다. 연결이 닫히지 않아 계속 응답을 기다린 것인데, 서버에서 렌더링되는 부분이었기 때문에 그대로 블로킹이 발생해 페이지 로딩이 늦어지는 사고가 벌어졌습니다.
그런데 의아한 점은, 경우에 따라 구체적인 수치는 조금씩 다르기는 해도 기본적으로 Connection timeout*과 Read timeout**이 꽤 짧게 설정돼 있었다는 것입니다.
* Connection timeout : TCP 연결에서 3-Way Handshake 구간에 적용되는 개념입니다. 클라이언트가 소켓을 열고
SYN패킷을 서버로 보냈지만, 서버가 일정 시간 내에SYN-ACK패킷을 응답하지 않았음을 의미합니다.
** Read timeout : 연결이 성립된 이후 서버의 응답을 대기하는 동안, 두 데이터 패킷 사이의 비활성 시간이 일정 시간을 초과하였음을 의미합니다.
일단 원인 자체는 금방 파악되었습니다. Resolving Timeout, 즉 DNS 쿼리에 대한 응답을 대기하다가 Timeout이 발생한 것이었습니다. 시스템 엔지니어가 파악한 내용에 따르면, 네임 서버의 문제로 쿼리 당 클라이언트 수(clients-per-query) 제한을 초과해 응답이 불가한 현상이었습니다.
하지만 이러한 과정에서 실제로는 15초만큼 지연되었음에도 불구하고, 막상 확인된 에러 메시지에서는 Connection timeout으로 설정했던 3초만 지연된 것으로 표시되었다는 점이 이상했습니다.
또한, 직관적으로 생각해보면 HTTP 클라이언트가 Timeout을 제어할 때 DNS 쿼리만 제어하지 못한다는 점도 잘 이해가 되지 않았습니다.
그래서, 어떤 이유로 Timeout이 작동하지 않은 것인지 원인을 찾아보았습니다.
Test
case cURL
먼저 간단히 cURL을 사용하여 문제를 재현해 보기로 하였습니다. /etc/resolv.conf를 수정하여 잘못된 DNS를 바라보게 하고, 아래와 같은 요청을 보내봤습니다.
$ time curl https://google.com/ --max-time 1 --verbose
* Resolving timed out after 1000 milliseconds
* Closing connection 0
curl: (28) Resolving timed out after 1000 milliseconds
real 0m10.016s
user 0m0.007s
sys 0m0.000s--max-time 수치대로 1초가 소요된 시점에 즉시 Resolving timed out 에러가 발생하긴 했지만, 실제로 요청이 종료된 건 10초가 지난 시점이었습니다. DNS Resolve 과정에서 지연된 시간은 제어하지 못한 것입니다.
그런데 여기서 잠깐 짚고 넘어갈 부분이 있습니다. 왜 하필 10초가 소요되었을까요?
/etc/resolv.conf에는 한 개의 네임서버만 명시했고, 그 외엔 아무것도 설정하지 않았습니다.
때문에 default option으로 적용되었고,timeout(RES_TIMEOUT)은 5초,attempt(RES_DFLRETRY)는 2회로 설정되어 5초씩 2번, 총 10초만큼 소요된 것입니다.
--max-time 옵션의 의미를 정확히 알아보기 위해, libcurl의 문서를 참고해 보았습니다.
Tell curl with -m / --max-time the maximum time, in seconds, that you allow the command line to spend before curl exits with a timeout error code (28). When the set time has elapsed, curl will exit no matter what is going on at that moment—including if it is transferring data. It really is the maximum time allowed.
curl 명령어에 -m / --max-time 옵션을 사용하여, 해당 명령줄이 타임아웃 에러 코드(28)와 함께 종료되기 전까지 소비할 수 있는 최대 시간(초)을 지정할 수 있습니다. 설정한 시간이 경과되면, curl은 데이터가 전송 중인지 여부를 포함해 그 순간 실행되고 있는 모든 작업과 관계없이 종료됩니다. 즉, 이것은 실제로 허용되는 최대 시간을 의미합니다.
인용한 내용에 따르면 --max-time 옵션은 curl이 작업을 실행할 수 있는 최대 시간(초)라고 했습니다. 특히 '어떤 일이 있더라도 종료된다'고 했으니, 어쨌든 설정한 시간을 초과하는 지연은 없을 것이라고 생각할 수 있습니다. 하지만 이미 직접 확인해 본 결과는 그렇지 않았습니다. 그 이유는 아래 이슈를 살펴보면 알 수 있습니다.
이미 같은 의문을 가진 사람이 있었으며, 연관된 이슈를 타고 가면서 내용을 정리해 보면 실마리가 잡힙니다. 요약하자면 내부적으로 resolver thread는 동기식으로 실행되고 있으며, getaddrinfo() 함수를 호출한 후 결과를 계속 기다리기 때문에, --max-time을 초과하는 지연이 발생할 수 있다는 것입니다.
if(data->mstate == CURLM_STATE_WAITRESOLVE) {
/* still waiting for the resolve to complete */
(void)Curl_resolver_wait_resolv(conn, NULL);
}case Axios
하지만 이는 어디까지나 cURL에 국한된 케이스이고, 어쩌면 다른 클라이언트에서는 문제가 없을 수도 있지 않을까 생각했습니다.
그래서 프론트엔드 개발자라면 익숙할 Axios 라이브러리로도 확인해 보기로 하였습니다. 마찬가지로 잘못된 DNS로 수정하고 아래와 같이 요청했습니다.
axios({
method: 'GET',
url: 'https://google.com/',
timeout: 1000,
})
.then((response) => {
console.log(response);
})
.catch((error) => {
console.error(error);
});ECONNABORTED 코드와 함께 Error: timeout of 1000ms exceeded 에러가 발생하였고, 정상적으로 1초만 소요되는 현상을 확인할 수 있었습니다.
Axios는 Node.js 환경에서 동작할 때 내부적으로 HTTP API를 사용합니다. cURL 때와 마찬가지로 DNS 쿼리시 getaddrinfo()를 호출하기 때문에, 응답이 지연된다면 그만큼 블로킹이 발생할 것이라고 예상하게 됩니다. 동기식으로 호출되기 때문입니다.
아래는 Node.js 공식 문서에서 DNS 섹션의 일부 내용을 인용한 것입니다.
Though the call to dns.lookup() will be asynchronous from JavaScript's perspective, it is implemented as a synchronous call to getaddrinfo that runs on libuv's threadpool.
JavaScript의 관점에서dns.lookup()호출은 비동기적으로 실행될 것이지만, 이것은libuv의 스레드 풀에서 실행되는 동기식 호출로 구현되어 있습니다.
분명 'libuv의 스레드 풀에서 getaddrinfo()가 동기식 호출로 구현된다'고 말하고 있습니다. 그도 그럴 것이, DNS 쿼리는 OS 커널에서도 비동기식 호출을 지원하지 않는 작업이기 때문입니다.
또한 Timeout 처리 방법에 관해 실험한 결과를 참고해보면, 실제로 Node.js의 내장 HTTP 클라이언트에서는 DNS 쿼리에 의해 Timeout이 트리거되지 않는 현상을 확인할 수 있습니다.
libuv provides asynchronous DNS resolution. For this it provides its own getaddrinfo replacement. In the callback you can perform normal socket operations on the retrieved addresses.
libuv는 비동기 DNS 조회를 제공합니다. 이를 위해 libuv는 자체적인 getaddrinfo 대체 함수를 제공합니다. 콜백에서는 검색된 주소에 대한 일반적인 소켓 작업을 수행할 수 있습니다.
하지만, libuv의 문서에서 Networking 섹션의 내용을 보면, getaddrinfo를 대체하여 자체적으로 비동기적인 DNS Resolution을 구현할 수도 있는 것으로 보입니다.
libuv는 Node.js의 코어를 구성하는 비동기 I/O 라이브러리이니, Event Loop, Thread Pool로 구현되는 특유의 동시성 구현 메커니즘을 연관지어 생각해보았을 때 별도의 스레드를 활용하여 커널에서 지원하지 않는 비동기 작업도 처리할 수 있는 것으로 추론할 수 있습니다.
따라서, 결국 Axios에서는 Node.js 덕분에(정확히는 libuv 덕분에) cURL과는 달리 블로킹이 발생하지 않고 비동기식으로 DNS를 쿼리할 수 있었다는 사실을 알 수 있습니다.
정리
정리하자면 Timeout이란 발생하는 상황 및 지점에 따라 DNS Resolve, Connection, Socket, Read, Write 등으로 세분될 수 있으며, 이것들을 각각 구체적으로 어떻게 제어하느냐에 따라 언어별, 라이브러리별로 동작의 차이가 발생할 수 있음을 알았습니다.
최소한의 방어 목적으로 Timeout을 설정했지만, 기본적으로 자신이 사용하고 있는 도구에 대한 이해 또한 기반적으로 갖춰져 있어야 한다는 사실을 배울 수 있었습니다.
