커넥션 풀(DBCP) 경고가 갑자기 쏟아질 때 (장애가 난 걸까, 이제야 보이는 걸까)

톰캣을 올린 뒤 새벽마다 쌓이는 커넥션 풀 경고의 정체와, 스택 한 장으로 영향 여부를 가르는 방법입니다.

톰캣 8.0 이하에서 8.5 이상으로 올리면 내장된 DBCP가 1 계열에서 2 계열로 교체되면서 커넥션 풀 구현도 같이 바뀝니다.

작업 자체는 조용히 끝났는데 며칠 뒤 로그를 열어 보니 새벽마다 같은 경고가 쌓여 있었고, 예전에는 한 번도 본 적 없는 문구라 당황스러웠습니다.

이럴 때 판단해야 하는 건 결국 하나인데, 장애가 새로 생긴 건지 아니면 원래 있던 일이 이제야 보이는 건지입니다. 결론부터 말하면 후자였고, 확인하는 데는 스택 트레이스 한 장이면 충분했습니다.

- 톰캣 8.5 부터 내장 DBCP가 1 계열에서 2 계열로 바뀐다

- 경고가 늘어난 이유는 DBCP 2가 로그를 새로 찍기 시작해서다

- 영향 여부는 스택의 호출 경로로 가른다(정리 중이냐, 빌려주는 중이냐)

- 원인은 DB가 아니라 네트워크 구간 유휴 타임아웃이었다

- 에러 문구가 Connection reset 이냐 연결 시간 초과 냐에 따라 범인이 다르다

1. 이 경고는 DBCP 2가 새로 만든 것이다

로그에 찍힌 클래스 이름은 SwallowedExceptionLogger 인데, 이름 그대로 풀이 삼킨 예외를 로그로 남겨 주는 리스너입니다.

DBCP 2의 데이터소스는 풀을 만들 때 이 리스너를 붙이며, 그래서 내부에서 조용히 버려지던 예외가 경고 한 줄로 올라옵니다.

DBCP 1에는 이 장치가 없어서 같은 상황이 벌어져도 아무 흔적 없이 지나갔으니, 이 경고는 없던 일이 생긴 게 아니라 있던 일이 드러난 것입니다.

이 사실을 먼저 잡고 가야 하는데, 안 그러면 업그레이드가 장애를 만들었다고 결론 내리고 롤백까지 검토하게 됩니다.

그러면 따라오는 질문이 내 톰캣은 어느 쪽인가인데, 경계는 8.5입니다.

- DBCP 1 계열 : 톰캣 7.0.x, 8.0.x - 패키지 org.apache.tomcat.dbcp.dbcp

- DBCP 2 계열 : 톰캣 8.5.x 부터 (9.0.x, 10.1.x, 11.0.x) - 패키지 org.apache.tomcat.dbcp.dbcp2

즉 7 -> 9, 8.0 -> 8.5, 8.0 -> 9 처럼 이 경계를 넘는 이관이면 해당되고, 반대로 8.5 -> 9 는 양쪽 다 2 계열이라 이 증상이 새로 생기지 않습니다.

버전을 외울 필요는 없고, 스택 첫 줄의 패키지 이름 끝에 dbcp2 가 붙어 있으면 2 계열입니다.

⚠️ 이름이 비슷한 톰캣 JDBC 풀(org.apache.tomcat.jdbc.pool)은 아예 다른 구현이라, 그쪽을 쓰고 계시면 이 글은 해당되지 않습니다.

2. 스택의 호출 경로가 영향 여부를 가른다

경고가 보인다고 다 같은 무게는 아니고, 어느 경로에서 났는지만 보면 사용자 영향이 있었는지 없었는지가 바로 나옵니다.

- evict / destroyObject 에서 났다 : 풀이 놀고 있던 커넥션을 정리하다 난 것. 사용자 요청과 무관

- borrowObject / validateObject 에서 났다 : 빌려주는 중에 난 것. 요청에 영향 있음

앞의 경우라면 애초에 "삼켜진" 예외라 애플리케이션까지 올라가지도 않지만, 뒤의 경우라면 삼켜지지 않고 던져지므로 화면 오류나 실패 건으로 이미 다른 곳에 흔적이 남아 있을 겁니다.

이번 건은 스택 중간에 정리 스레드가 그대로 찍혀 있었습니다.

여기까지 오면 서비스 영향 없음이 확정되고, 남은 건 왜 났느냐입니다.

3. Connection reset 과 연결 시간 초과 는 원인이 다르다

커넥션이 끊겼다는 사실은 같아도 끊긴 방식이 다르면 범인이 다르고, 여기서 어디를 들여다볼지가 갈립니다.

- Connection reset(RST 수신) : 상대가 능동적으로 끊었다는 뜻입니다. DB 서버가 세션을 정리했거나, 장비가 RST를 보내 준 경우입니다.

- 연결 시간 초과(소켓 read 타임아웃) : 보냈는데 아무 응답이 없다는 뜻입니다. 끊겼다는 통보조차 못 받았습니다.

후자는 중간 장비가 유휴 세션을 조용히 버린 전형적인 패턴입니다.

- 방화벽이나 NAT는 일정 시간 트래픽이 없는 세션을 세션 테이블에서 지웁니다

- 이때 RST를 보내 주는 장비도 있고, 아무 말 없이 지우는 장비도 있습니다

- 말없이 지우면 양쪽 다 세션이 살아 있다고 믿습니다. 그러다 뭔가를 보내는 순간 응답이 없어서 타임아웃을 만납니다

이번 스택도 그랬는데, 커넥션을 닫으려고 종료 패킷을 보낸 뒤 응답을 기다리다 걸렸습니다.

시각도 맞아떨어져서 트래픽이 없는 새벽 시간대에만 찍혔는데, 낮에는 커넥션이 계속 쓰이니 유휴 상태가 될 틈이 없기 때문입니다.

4. 처방은 하나다. 지워지기 전에 우리가 먼저 회수한다

원인이 유휴 타임아웃이라 고치는 방향도 단순한데, 중간 장비가 세션을 지우기 전에 풀이 먼저 커넥션을 정리하면 이 예외 자체가 생기지 않습니다.

핵심은 유휴 판정 시간을 장비의 타임아웃보다 짧게 잡는 것입니다.

장비 타임아웃 값을 모르면 15분 정도로 잡아도 대체로 안전한데, 흔한 설정이 30분이나 60분이라 그 안쪽으로 들어가기 때문입니다.

같이 보면 좋은 것들도 있습니다.

- 최대 유휴 개수를 낮춘다 : 노는 커넥션이 적을수록 문제 표면이 줄어듭니다

- 커넥션 최대 수명을 건다 : 오래된 커넥션을 주기적으로 갈아 끼웁니다

- 검증 쿼리에 타임아웃을 건다 : 검증 자체가 오래 매달리는 상황을 막습니다

로그 레벨을 올려서 경고를 안 보이게 만드는 방법도 있지만, 원인이 남아 있는 채로 눈만 가리는 것이고 나중에 같은 구간에서 진짜 문제가 생겼을 때 단서를 잃기 때문에 권하지 않습니다.

5. DBCP 1이 더 안전했던 게 아니다

경고가 안 보였다고 예전이 더 나았던 건 아니고, 오히려 반대입니다.

두 버전 모두 빌려줄 때 검증하기가 기본으로 켜져 있는데, 동작이 서로 다릅니다.

- DBCP 1 : 검증 쿼리를 지정하지 않으면 아무 검증도 하지 않습니다. 죽은 커넥션이 그대로 앱으로 나갑니다.

- DBCP 2 : 검증 쿼리가 없으면 드라이버의 유효성 확인 기능으로 대신 검증합니다.

즉 죽은 커넥션이 애플리케이션으로 넘어갈 확률은 DBCP 2 쪽이 더 낮으며, 로그가 늘어난 건 눈에 띄는 변화지만 실제로는 안전장치가 하나 늘어난 셈입니다.

6. 정리

정리하면 이렇습니다.

- 새 경고의 정체는 DBCP 2가 신설한 로그 리스너였다

- 스택이 정리 경로를 가리키면 사용자 영향은 없다

- 연결 시간 초과 는 DB가 아니라 중간 장비가 유휴 세션을 버린 것이다

- 해법은 장비보다 먼저 회수하도록 유휴 판정 시간을 줄이는 것

- 로그가 늘어난 게 곧 위험이 늘어난 건 아니다

버전을 올리면 그동안 안 보이던 것들이 한꺼번에 보이는데, 그때 필요한 건 보이는 것마다 놀라지 않는 기준이고 이번 경우엔 그 기준이 "스택이 어느 경로를 가리키는가" 하나였습니다.

같은 상황을 만나셨다면, 롤백을 검토하기 전에 스택 중간을 먼저 읽어 보시길 권합니다.

함께 보면 좋은 글:
- 톰캣(Tomcat) 6에서 9로 올릴 때 만나는 함정 5가지 (기동 실패, 한글 전멸, 400 에러) - 같은 톰캣 이관 편
- 메모리가 부족해서 힙을 늘렸더니 아예 안 뜰 때 (32비트 JVM의 4GB 벽) - 같은 전환 작업에서 나온 JVM 편

여기까지 커넥션 풀 경고의 정체와 원인 판별에 대해서 작성해봤습니다. 여기까지 읽어주셔서 감사합니다!