갑자기 프로젝트가 터져버린 이유?

 

결론부터 두괄식으로 이야기를 하자면, OSIV = true 설정으로 인하여 SSE으로 구현한 알람 기능에서 커넥션 풀을 반환하지 않아 생긴 문제였습니다.

문제상황

프로젝트를 배포한지 오랜 시간이 흘렀는데 그 전에는 아무런 문제가 없다가 최근에 개발 서버와 운영 서버 모두가 터졌다는 연락을 받았습니다.  원인을 찾기 위해 그라파나에서 디버깅을 시도했는데, 해당 에러 메세지가 눈에 띄었습니다.

2025-02-09 17:08:44.225
[ERROR] [balancetalk.global.utils.LoggingAspect] [http-nio-8082-exec-19]
- [RESPONSE] 200 Unable to acquire JDBC Connection [HikariPool-1 - Connection is not available, request timed out after 30000ms.]

 

API를 수행하는데 있어서 30초가 넘어 DB가 터졌고, 이로 인해서 작업이 불가능한 상황이였습니다. `connection-timeout`을 일단 임시로 길게 설정하면 어떨까 싶어서 50초로 설정을 했지만, 결과는 여전했습니다.

connection-timeout: pool에서 커넥션을 얻어오기전까지 기다리는 최대 시간.

 

HikariPool-1 - Connection is not available, request timed outafter 50000ms.

 

ec2에서 서버를 다시 실행해도 로그인을 몇번 반복한 후에 여전히 DB가 터져있었고, 현재 로그 상태로는 추적이 힘들어 `Hikari Pool DEBUG` 설정 코드를 추가했습니다.

logging:
  level:
    com.zaxxer.hikari.HikariConfig: DEBUG
    com.zaxxer.hikari: TRACE

 

ec2에서 프로젝트를 다시 실행시켜보니,

2025-02-16 17:04:47.826 [DEBUG] [com.zaxxer.hikari.pool.HikariPool] [HikariPool-1 housekeeper]- HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0).

2025-02-16 17:04:48.0782025-02-16 17:04:47.826 [DEBUG] [com.zaxxer.hikari.pool.HikariPool] [HikariPool-1 housekeeper]- HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)

 

이런식으로 현재 `connection pool`에 대한 정보를 보다 명확하게 로그로 파악이 가능했습니다.

total: 전체 커넥션 풀 갯수
active: 현재 사용되고 있는 커넥션 풀 갯수
idle: 사용되지 않고 있는 풀 갯수
waiting: 대기중인 요청 갯수

 

소셜 로그인이 문제?

로그인을 시도했을 때, 커넥션 풀이 다음과 같이 변화하는 것을 로그에서 확인했습니다.

[DEBUG] [com.zaxxer.hikari.pool.HikariPool] [HikariPool-1 housekeeper]
- HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)

 

로그인으로 인해서 커넥션 풀 하나가 사용되고 있는데, 문제는 시간이 아무리 흘러도 요청이 끝나지 않고 계속해서 점유를 하고 있었습니다. 

이로 인해서 단 10번의 로그인 요청 API만 보내도 서버가 터져버리는 상황이 발생했던 것 입니다.

 

제가 프로젝트에서 소셜 로그인 및 로그아웃 관련해서 개발을 진행했기 때문에, 그 부분을 중점적으로 디버깅을 진행했습니다.

현재 JWT를 사용하여 리프레시 토큰을 관리하고 있는데, `Local Cache`를 사용하여 리프레시 토큰을 보관하고 있었습니다. 따라서 캐시 정합성 문제인가 의심하며 문제 해결을 시도했지만, 답을 찾을 수 없었습니다.

 

그렇게 로그만 계속해서 추적하던 중에, 로그인 후 생기는 또 다른 로그 메세지가 눈에 띄었습니다.

 

알람 API에서 문제 발생

[INFO ] [balancetalk.global.utils.LoggingAspect] [http-nio-8082-exec-5]- [RESPONSE] 200 SseEmitter@22755301

 

매번 로그인이 성공한 후에, 해당 로그가 출력되었고 `SseEmitter` 관련해서 아는 바가 없었기에 같은 백엔드 팀원에게 문의하니 

알람 기능이 SSE (Server-Sent-Events)로 구현되었다는 것을 알았습니다.

 

알람관련 Swagger 문서

 

프론트 팀원에게도 문의하니, 로그인 한 후에 매번 `/notifications` API가 실행됐었고 개발서버에서 해당 API를 테스트 해보니 서버쪽에서 커넥션 풀을 반환시켜주지 않아 문제가 발생했습니다. 

 

따라서, 현재 이슈는 실시간 알림 스트리밍 API에서 발생하고 있었고 이로 인해서 커넥션 풀이 고갈되고 있었습니다. 

 

서버 알림 기능 뜯어보기 🔎

알림 기능 관련해서 제가 개발을 진행하지 않았고, 전혀 아는 바가 없었기에 트러블슈팅도 할 겸 공부해보기로 했습니다.

 

SSE (Server-Sent Event)

서버와 클라이언트 간에 통신을 하는 방식 중에 하나로, 서버에서 클라이언트로 `실시간 이벤트`를 전송하는 방법중에 하나입니다.

단방향 통신이기 때문에 실시간 알림 작업에 유용하게 쓰입니다.

 

 

해결방법

OSIV 설정

jpa:
  open-in-view: false

 

`open-in-view` 설정을 `false`로 바꿔줌에 따라 커넥션 풀 반환 문제는 해결했지만, (default가 `true`) 이제 이러한 에러 메세지를 띄워주고 있었습니다.

 

 

[ERROR] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: org.hibernate.LazyInitializationException: could not initialize proxy [balancetalk.talkpick.domain.TalkPick#12] - no Session]

 

 

OSIV에 대한 내용을 공부하면서 스프링 기본 동작 원리에 대해서 많이 몰랐던 것을 느꼈고 내용이 더 길어질 것 같아 다음 포스트에서 설명하겠습니다. 

 

 

 

 

참고자료:

https://velog.io/@zini9188/%EC%98%A4%EB%A5%98-connection-is-not-available-request-timed-out-after-30000ms

HikariCP Connection 고갈 문제

https://velog.io/@baekgom/SSE-Server-Sent-Event-%EC%95%8C%EB%A6%BC-%EA%B8%B0%EB%8A%A5#1-http-%ED%86%B5%EC%8B%A0

SSE (Server-Sent Event) - 실시간 알림 기능