탐정_3최근 고객에게 발생한 문제 해결 내용입니다. 다른 분들에게도 도움이 될 것 같아서 공유 합니다. 전혀 생각하지도 않았던 곳에서 타임 아웃의 원인을 제공하기 때문입니다. 원인도 중요하지만 어떤 문제에 대해 그 문제를 해결해 나가는 방법도 관심을 가지시면 좋을 듯합니다. (뻘쭘하긴 하네요.... ㅎㅎ)

신고 접수

피해자(고객)의 신고가 접수 되었다. 신고 내용은 간단했다. 1분이 넘는 응답 시간을 갖는 서버 호출에 대해, 개발 서버를 호출하면 잘 작동하는 WCF 서비스가 운영서버에 대해서 호출하면 타임아웃 오류가 난다는 것이었다. 타임 아웃 범죄는 흔히 발생하는 것들 중 하나이고 특히 WCF 서비스 호출 시 잘못된 서버 설정, 혹은 클라이언트 설정으로 흔히 발생하는 잡범 수준이었다.

구성 설정, 너냐?

피해자는 운영과 개발이 완전히 동일한 구성 설정을 가지고 있다고 했으나, 15년 넘게 이 짓을 하면서 배운 것들 중 하나는 피해자를 100%믿어서는 안 된다는 것이다. 필자는 즉시 운영 서버와 개발 서버의 .config 파일들, 그리고 클라이언트가 사용하는 .config 파일을 요청 했다.

피해자가 전송해 준 .config 파일을 살펴본 결과, 아쉽게도 의심할 만한 부분이 발견되지 않았다. 단순 잡범의 소행이 아니었던 것이다. 덴장... 사무실에서 원격으로 해결해 주고 생색이나 내려던 본인의 의도는 실패하고 현장으로 출동하게 된 것이다.

수사 방식

탐정_1현장에서 최소한의 시간으로 수사를 완료하기 위해서는 접근 방식을 미리 생각해 두어야 했다. 대개 이런 상황에서는 어플리케이션을 분리해서 생각하는 것이 좋다. 어플리케이션을 구성하는 각 계층(데이터베이스, 비즈니스 로직, 웹 서버, 클라이언트 등)에 대해 문제를 발생할만한 부분에 대한 가설을 세우고 그 가설을 검증해 나가는 것이다. 가설 검증에 실패하면 다른 가설에 대한 검증을 수행해 나가면서 원인을 찾는 것이다.

클라이언트, 넌 아니다...

현장에 도착해서 현상을 살펴보다가 클라이언트는 즉시 용의선상에서 배제하였다. 동일 클라이언트에 대해 동일 구성을 사용하여 운영 서버를 호출 했을 때는 타임 아웃이 발생했지만 개발 서버를 호출했을 때는 정상적으로 응답을 반환했기 때문이다. 두 상황에서 다른 부분은 오직 서버에 대한 IP(서버 이름)만이 다를 뿐이었다. 클라이언트는 간단한 조사 후 혐의를 벗고 곧바로 귀가했다.

DB 서버, 너냐?

현상을 살펴볼 때 서버 호출은 2분 이상 소요되는 상당히 느린 응답을 가졌었다. 피해자와의 인터뷰에서 알게 된 것은 이 서버 호출이 사용하는 쿼리가 Liked Server 기능을 사용해서 원래 느리다는 것이다. 그래서 DB 서버를 의심했다. DB 서버에서 타임 아웃이 걸릴 수도 있기 때문이다.

WCF 서비스가 사용하는 쿼리를 SQL Server Management Studio에서 직접 돌려보기로 했다. 피해자의 협조 하에 운영 환경에서 직접 쿼리를 수행해 보았다(조회이므로 안전했었음). 쿼리는 약 2분 정도 소요되었지만 정상적으로 쿼리 결과를 반환했다. DB가 정상적으로 쿼리를 반환했다면, DB 호출을 수행하는 데이터 액세스 컴포넌트 혹은 비즈니스 로직 컴포넌트의 문제일 가능성이 있다. DB 서버를 귀가 조치시키고 곧바로 비즈니스 계층의 두 용의자를 참고인 신분으로 소환하였다.

혹시, 비즈니스 계층 너냐?

image사실, 이 두 용의자는 조사 대상에 포함되지 말았어야 한다. 개발 서버와 운영 서버가 다른 코드를 사용하지 않는 한 현상이 다르게 나타나지 않을 것이기 때문이다. 그럼에도 불구하고 ‘참고인’ 자격으로 소환하여 코딩 형태를 살펴볼 필요는 있었다.

먼저 조사한 것은 데이터 액세스 컴포넌트이다. ADO.NET 기반의 코드는 명령을 수행할 때 CommandTimout 설정이 있으며 이 값이 1분 이하로 지정되어 있다면 1분 이상을 소요하는 쿼리를 타임아웃이 발생할 것이기 때문이다. 하지만 짧은 조사 결과, 데이터 액세스 컴포넌트에는 CommandTimeout을 자그마치 6000초로 지정해 놓은 코드를 발견하였다. 따라서 이 아이는 범인이 아니었다.

비즈니스 로직 컴포넌트도 타임아웃을 유발할 수 있었다. 비즈니스 로직 컴포넌트는 트랜잭션에 대한 제어를 하기 때문에 트랜잭션 타임아웃이 충분히 발생할 수 있기 때문이다. 하지만 이 경우는 아니었다. 단순 조회이기 때문에 트랜잭션을 사용하지 않았던 것이다. 따라서 이 아이도 용의 선상에서 제외했다.

그럼, 웹 서버 너냐?

image다음으로 의심한 대상은 웹 서버이다. 사실, 타임 아웃 범죄에서 가장 많은 혐의점을 가지고 있는 것이 웹 서버(IIS)인데 그 이유는 타임아웃을 유발할 만한 설정을 많이 가지고 있기 때문이다. 스크립트 타임아웃(executionTimeout) 설정, WCF 타임아웃 설정 등 다양한 타임아웃 설정을 web.config에 보유하고 있기 때문이다.

Web.config의 내용은 현장 출동 전에 살펴보았고, 피해자가 이미 executionTimeout 설정을 시도해 보았다고 증언 했기 때문에, IIS에 관련된 설정 대신 IIS의 로그를 살펴보았다. 만약 서버 측에서 타임아웃이 발생했다면 HTTP 결과 값이 200이 아닌 5xx일 것이기 때문이었다.

IIS를 로그를 살펴본 결과, 해당 서비스(.svc)에 대한 HTTP 응답은 모두 HTTP 200 OK 이었다. 다시 말해, 클라이언트의 WCF 서비스 호출은 DB 서버, 비즈니스 로직 계층, 웹 서버가 모두 성공적으로 작동하였고 비록 약 140여 초라는 오랜 수행 시간에도 불구하고 성공적으로 응답을 클라이언트에게 반환했다는 얘기가 된다.

그렇다면 대체 누구냐?

정리를 해보자. 문제점을 가지고 있지 않은 클라이언트가 개발 서버를 호출하면 매우 잘 작동한다. 하지만 1분 이상의 수행 시간을 갖는 WCF 서비스를 운영 서버에 대해 호출하면 타임아웃이 발생한다는 것이다. 운영 환경의 웹 서버는 1분 이상의 수행 시간이 소요되는 WCF 서비스 호출에 대해서도 정상적으로 응답하고 있다!

이 상황이라면 클라이언트에서 개발 서버까지의 네트워크 환경과 운영 서버까지의 네트워크 환경이 같지 않다는 얘기 밖에 되지 않는다. 피해자는 두 환경이 같다고 강변하였으나 필자는 확인을 떠야 했다. Tracert 명령을 통해 클라이언트로부터 개발 서버까지 어떤 호스트 들을 거치는 살펴 보았다. 게이트웨이(라우터)를 통과하여 개발 서버로 직접 연결 되고 있었다. 다음은 클라이언트로부터 운영 서버까지의 경로를 살펴보았다. 게이트웨이에서 추가적으로 호스트를 하나 더 경유 한 이후에 운영서버에 도달했다. 두 네트워크 환경은 같지 않았던 것이다. 피해자를 추궁한 끝에 의문의 호스트는 L4 스위치로 파악되었다.

과거 필자가 이와 유사한 문제를 경험하지 못했다면 이 문제도 졸라 풀기 어려운 난제로 남을 뻔한 상황이었다. 과거 필자가 P 피해자(고객사)에서 겪었던 문제는 연결 풀링에 포함된 데이터베이스 연결이 가끔씩 오류를 일으키는 현상으로써 원인은 방화벽이 4분 동안 비 활성화되어 있는(패킷을 주고 받지 않는) TCP 연결을 강제로 끊어 버리는 것이 원인이었다.

필자는 범인으로 L4 스위치를 지목하였고 피해자로 하여금 L4 스위치를 납품한 업체를 불러 관련 설정이 존재하는지 확인해 달라고 부탁하였다. 그리고 필자는 1시간여의 현장 수사를 마치고 복귀하였다.

사건의 결말과 충고 사항

약 1-2시간 후 피해자로부터 연락이 왔다. 범인을 찾았고 문제를 해결했다는 것이다. 범인은 역시 L4 스위치였고 이 L4 스위치는 1분 동안 활동이 없는 TCP 연결을 강제로 끊어 버린 것이다. L4 스위치가 끊어버린 TCP 연결은 L4 스위치와 운영 서버 사이의 TCP 연결 이었기에 클라이언트는 하염없이 응답을 기다리다가 WCF 타임아웃이 발생한 것이다. 피해자는 이 설정 값을 1시간으로 바꾸고도 분이 풀리지 않았다는 후문이…

타임 아웃 류의 사건이 발생하면 가장 높은 비율로 .config 파일 설정이 잘못되었는지 살펴보아야 한다. 하지만 이런 잡범이 아니라면 단계 별로 타임 아웃을 일으킬 만한 요소들에 대해 검증을 해 나가는 것이 좋다. 필자처럼 DB부터 살펴보는 것 보다는 IIS 로그에서 성공적으로 응답을 보냈는지 먼저 살펴보는 것이 더 좋다. IIS 로그에서 오류가 발견되었다면 IIS 이후의 단계를 들을 살펴보아야 하겠지만, IIS 로그 상에서 오류가 없다면 클라이언트 혹은 클라이언트와 IIS 사이에서 타임아웃을 유발했을 가능성이 매우 높기 때문이다. 아무쪼록 유사한 타임아웃 문제로 고생하는 독자들이 있다면 이 글을 통해 해결을 위한 단서를 찾기 바란다.

이상 사건 보고서 끝~

경고 : 이 글을 무단으로 복제/스크랩하여 타 게시판, 블로그에 게시하는 것은 허용하지 않습니다.