[Spring] 서비스 운영간 발생한 DB Connection Closed 이슈

장애 발생 및 발견

8월 24일 서버 정기점검이 이루어지던 새벽

정기점검 대상이 아닌 서버의 특정 인스턴스에 인입된 요청들이 'SQLException : Connection Closed' 오류로 모두 500처리가 되는 이슈가 발생하였다. 

24일 3시 43분에 처음 발생한 이슈는 오전 9시 45분에 이슈사항으로 확인되었고 전사에 전파 및 담당자인 나에게 전달되게 되었다.

( 약 6시간의 장애 시간의 텀은 너무 부끄러운 장애대응이다.. )

 

장애 대응

오전 9시 45분, 전사 장애 대응 채널에 내이름이 멘션되어 호출되기 시작했고, 해당 시스템은 팀내에서 개발한것이 아닌 외주업체에서 관리하고 있었기에 담당 업체에 연락하여 원인 파악 및 조치를 요청하였다.

 

오전 10시 03분, 담당 외주 업체에서의 조치 이전에 인프라팀에서는 문제가 있는 서버를 로드밸런서에서 제외하였고 이로써 커머스 서비스에서 발생하던 오류는 모두 해소 되었다. (이 시점 로드밸런서에는 정상 서버 1대만 붙어 있고, 비정상 서버 1대는 제외된 상태)

오후 2시 40분, 담당 업체로부터 해당 서버가 정상적으로 동작한다는 피드백을 받은후 인프라팀에 해당 서버를 다시 로드밸런서 투입 요청하였다. 이후 서버 정상 동작 및 로그가 쌓이는 부분을 확인하며 1차적으로 장애 대응을 마칠 수 있었다.

 

진짜 문제의 시작, 장애 분석

급한 불은 껏으니, 장애가 발생한 원인을 분석할 차례이다.

해당 시스템은 사내에서 개발하여 운영하는 서버가 아닌 아주 오래전 외주업체를 통해 개발 되어진 레거시 시스템이었고, 운영또한 외주 업체에서 담당하고 있었다. 해당 시스템에 대한 담당자는 나였으나 외주업체를 관리하는 측면에서만 바라보았지 실제 서버내부와 코드레벨에서의 접근을 해본적은 없었다. 

 

해당 시스템의 외주 업체에 분석을 요청하였으나, DB Connection Closed 로그 외에는 확인할 수 있는 사항이 없어 분석이 어렵다는 답변을 받았으며, 이슈가 발생한 시간에 서버 정기점검을 진행했으니 인프라 문제가 아니냐는 조금은 당황스러운 답변을 받았다.

 

물론 나도 이슈가 발생한 시각이 인프라팀에서 진행한 정기점검과 맞닿아 있었기에 정기점검으로 인한 사이드이펙트로 의심하고 인프라팀에 문의 하였고, 더불어 이슈가 된 DB가 해당 시간에 문제가 있었는지에 대해 DB팀에 함께 문의 하며 자체적인 분석이 들어갔다.

 

문제가된 서버는 하나의 스위치에 두개의 서버가 붙어 로드밸런싱되고 있었고, 각각의 서버 내부에서는 Nginx로 유입된 요청을 Tomcat을 통해 다시 각각의 인스턴스로 전달하고 있는 구조로 파악했다.

 

 

1차 추측

이슈가 발생한 시각이 정기점검 대상 시간이었기 때문에 인프라팀에서 작업간 실수가 있지 않았을까 추측하였다.

인프라팀에 문의 한 답변은, 해당 시간 정기점검이 진행된 것은 맞으나 문제가 된 서버와 DB는 정기점검 대상이 아니었으며, 정기점검 대상 서버들 조차도 단순 재부팅만 진행했고 재부팅 이후 정상동작을 확인하였다.

또한 만약 네트워크나 방화벽 문제였다면 문제가 된 서버 전체에서 동일한 이슈가 발생되어야 하지만, 두개의 인스턴스중 하나의 인스턴스에서만 문제가 발생하였기에 인프라나 네트워크 문제는 제외되었다.

 

2차 추측

DB팀에서의 답변은, 해당 시간 Oracle DB 로그에 다수의 Timeout Log가 확인되었다고 전달 받았다. 이 답변을 통해 나는 해당 시간 DB 이슈가 있었다는 판단을 하였다. 판단의 근거로는, 만약 네트워크나 방화벽 문제였다면 DB로 통신자체가 유입되지 않아 Timeout 로그조차도 쌓이지 않았을 것이며, DB에 인입된 요청이 내부에서의 처리과정에서 발생한 Timeout으로 서버 Connection이 실패했겠다는 추측을 하였다. 결과적으로 답이 아니었다. 해당 시간 DB에 쌓인 Timeout Log는 정기점검 시간 서버가 재부팅되며 기존 서버와 맺고 있던 Connection Pool의 Connection들이 끊기게 되었고 무의미한 Connection들이 Timeout 로그를 남기며 정리된 것으로 확인 하였다.

 

3차 추측

남은 의심은 DB Connection Pool 설정 관련 이슈로 추측할 수 밖에 없었다.

다만 이 부분을 명확히 확인하기 어려웠던 이유는 해당 시스템에 Connection Pool 관련 로그가 쌓이지 않고 있었으며, 이슈가 발생한 시점에 스레드 덤프를 떠놓지 못했다. 장애를 분석하는 시점에는 이미 관련된 정보가 모두 사라진 후 였으며 단순 추측으로 고민할 수 밖에 없는 상황이었다. 다만 정황상 '어떤 일련의 문제로' 서버의 1번 인스턴스와 DB와의 연결이 끊기게 되었고 DB와의 통신이 끊기게 됨으로 Spring 서버가 가지고 있던 Connection Pool 내부의 커넥션이 모두 Garbage 커넥션이 되었으며 정상적이지 않은 커넥션으로 DB 통신을 시도함으로 Connection Closed( 커넥션이 이미 닫혀 버림 ) 에러가 발생한 것으로 보였다.

 

실제 해당 서버의 Connection Pool 설정을 보면, 풀에 유효하지 않은 커넥션이 존재할 경우 해당 커넥션을 제외하고 새로운 커넥션을 맺도록 하는 설정이 제외되어 있었다. 결국 '어떤 일련의 네트워크 문제로' DB와의 통신이 끊기게 됨으로 Connection Pool 전체에 영향이 발생되게 된것으로 판단하였다.

 

다만 '명확한 근거를 가진 원인'으로 판단할 수는 없었다.

관련 로그와 모니터링 데이터가 전무했기 때문에..

 

재발 방지 대책 수립

- 외부 업체에 할당된 시스템에 대해 APM 통한 모니터링

- 장애 발생시 즉시 인지할 수 있도록 서버 에러에 대한 알림 처리 (장애 발생 인지 시간이 10분을 넘기지 않도록)

- 이슈 서버별 Connection Pool 설정 변경 및 Thread Pool 설정도 함께 확인후 적절히 설정 변경