Node Express API가 두 번 호출되는 현상

한 달 전쯤, Node 서버가 응답을 주지 않아 UI에서 조회가 끝나지 않는다는 문의가 들어왔습니다. 평소와 다른점은 MongoDB에 수십억 단위의 데이터가 평소보다 훨씬 많이 저장되었다는 점입니다. 현상 파악을 위해 Node 서버쪽에 로깅 코드를 강화하여 돌려봤습니다.

헌데..현상이 매우 이상합니다. REST API가 최초로 호출 되고 얼마 뒤에 REST API가 다시 호출되었습니다. UI에서 timeout이 발생하면 두 번 호출하나? 라는 의문이 들어 fiddler로 패킷을 살펴보았으나 해당 문제도 아니였습니다.

그럼 누가 API를 다시 호출하는거지? Express 서버가 특정 조건 하에서 API를 다시 호출하나 싶어서 1시간 정도의 검색 후 찾을 수 있었습니다.

Yes, I’ve experienced this plenty of times. It is, in fact, your browser making a second request (i.e. retrying the failed request). Node.js has a default timeout on all incoming requests, and if you don’t change the timeout (as you did in your update), then Node.js will kill the TCP connection if you don’t respond to the client in that amount of time. Most web browsers will see this sudden TCP connection termination as a failure and retry the request (sadly, even if it’s a POST :( ).

정리하면, Node는 모든 request에 대해 default timeout을 가지고 있고, 이 시간동안 client에게 response를 주지 않으면 TCP 연결을 끊어 버리게 됩니다. 대부분의 browser들은 갑작스런 TCP 종료가 될 경우 retry를 하게되고 fiddler에서 이를 탐지 못하는 이유는 해당 패킷을 탐지할 수 있는 설정이 disabled되어 있다고 합니다.

제 경우, MongoDB에 많은 데이터를 aggregation 하다보니 응답을 default timeout 내에 주지 않아서 발생하게 되었습니다.

그럼 아래 현상을 재현해봅시다.

express 로 3000번 포트를 listen하고 sendResponseAfter2Min API를 제공하는 코드입니다. sendResponseAfter2Min API에서는 setTimeout 함수로 2분 뒤에 응답을 주도록 되어 있습니다. 이제 해당 API로 요청을 하게 될 경우 Node 서버 쪽 console.log 결과입니다. 물론 UI는 응답을 받지 못했습니다.

그렇다면 해당 현상은 어떻게 해결할까요? Node의 default timeout 을 바꿔주면 됩니다.

위 코드에서 req.connection.setTimeout 함수로 default timeout 값을 3분으로 변경하였습니다. setTimeout 함수가 2분뒤에 응답을 주므로 정상적으로 동작해야 합니다. 결과는 아래와 같이 정상적입니다.

그렇다면 실제 제품에 적용할 때, req.connection.setTimeout 함수를 모든 API에 적용해줘야 할까요? 아래 코드를 봅시다.

anotherSendResponseAfter2Min API를 하나 더 만들었고 여기에는 default timeout 값을 바꾸는 코드가 없습니다. 이 때, 두 API를 호출해보면 결과는 아래와 같습니다.

req.connection.setTimeout 함수는 특정 API만 timeout 값을 변경합니다. 만약 제품의 모든 API의 timeout을 바꾸고자 하면 아래와 같은 코드를 추가합니다.

바뀐 코드는 app.listen 부분에서 server.setTimeout을 3분으로 변경했습니다. 이 후 코드를 수행하면 두 API 모두 정상적으로 timeout 값이 3분으로 변경되었습니다. ^^