에러 로그
[2024-05-20 00:27:15:244642169] INFO 1 --- [nio-8080-exec-1] [221.133.55.106] c.d.e.common.aop.LoggingAspect : [IP: 221.133.55.106] Request Start - Method: ProjectController.createProject
[2024-05-20 00:27:20:244647175] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.Connection@731f5def ((conn=1414) Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
[2024-05-20 00:27:25:244652182] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.Connection@510f71b4 ((conn=1415) Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
[2024-05-20 00:27:30:244657188] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.Connection@7a458a8a ((conn=1416) Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
[2024-05-20 00:27:35:244662190] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.Connection@40f9f5da ((conn=1417) Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
[2024-05-20 00:27:40:244667193] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.Connection@71af060 ((conn=1418) Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
[2024-05-20 00:27:45:244672197] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.Connection@6fab1304 ((conn=1419) Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
[2024-05-20 00:27:45:244672202] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] o.h.e.jdbc.spi.SqlExceptionHelper : SQL Error: 0, SQLState: 42000
[2024-05-20 00:27:45:244672202] ERROR 1 --- [nio-8080-exec-1] [221.133.55.106] o.h.e.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30024ms.
00:27:45,712 |-INFO in c.q.l.co.rolling.helper.RenameUtil - Renaming file [logs/err.log] to [logs/err.2024-05-17_0.log]
00:27:45,713 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - first clean up after appender initialization
[2024-05-20 00:27:45:244672204] WARN 1 --- [nio-8080-exec-1] [221.133.55.106] o.h.e.jdbc.spi.SqlExceptionHelper : SQL Error: -1, SQLState: 42000
00:27:45,713 |-INFO in c.q.l.core.rolling.helper.TimeBasedArchiveRemover - Multiple periods, i.e. 32 periods, seem to have elapsed. This is expected at application start.
[2024-05-20 00:27:45:244672204] ERROR 1 --- [nio-8080-exec-1] [221.133.55.106] o.h.e.jdbc.spi.SqlExceptionHelper : (conn=1419) Connection.setNetworkTimeout cannot be called on a closed connection
[2024-05-20 00:27:45:244672207] ERROR 1 --- [nio-8080-exec-1] [221.133.55.106] c.d.e.common.aop.LoggingAspect : [IP: 221.133.55.106] Error Msg: Could not open JPA EntityManager for transaction
[2024-05-20 00:27:45:244672213] ERROR 1 --- [nio-8080-exec-1] [] o.a.c.c.C.[.[.[.[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction] with root cause
java.sql.SQLSyntaxErrorException: (conn=1419) Connection.setNetworkTimeout cannot be called on a closed connection
에러 원인
HikariCP 커넥션 풀에서 커넥션이 닫힌 상태에서 Connection.setNetworkTimeout 메서드를 호출하려고 했기 때문에 발생한 에러
HikariCP의 maxLifetime 설정이 데이터베이스의 wait_timeout 설정보다 길기 때문에 발생할 수 있음
maxLifetime
HikariCP 커넥션 풀에서 개별 커넥션이 풀에 유지될 수 있는 최대 시간
커넥션이 이 시간보다 오래되면 사용 중이든 유휴 상태이든 상관없이 커넥션 풀에서 제거되고 새 커넥션으로 대체됨
maxLifetime을 설정하여 커넥션이 오래 지속됨에 따라 발생할 수 있는 잠재적인 문제를 예방할 수 있음
설정단위: 밀리초(ms)
기본값: 30분(1800000ms)
wait_timeout
MariaDB에서 유휴 상태의 연결이 종료되기까지의 최대 대기 시간
데이터베이스 서버에서 설정
클라이언트가 유휴 상태로 연결을 유지할 수 있는 최대 시간 정의
설정된 시간이 지나면 데이터베이스 서버는 유휴 연결을 자동으로 닫음
설정단위 : 초(s)
기본값: 8시간(28800초)
설정 권장 사항
maxLifetime을 wait_timeout값 보다 작게 설정해야함
HikariCP가 MariaDB가 커넥션을 닫기 전에 커넥션을 갱신할 수 있음
maxLifetime 설정
# application.properties
# 30분 설정
spring.datasource.hikari.maxLifetime=1800000
wait_timeout 확인
mariadb 를 도커 컨테이너로 실행하고 있기 때문에 컨테이너 진입해서 확인
# 도커 컨테이너 진입
docker exec -it maiadb /bin/bash
# 설정파일 편집
nano etc/mysql/my.cnf
설정 파일을 확인해보니 wait_timeout 설정이 명시되어 있지 않았음
설정이 명시되어있지 않다면 MariaDB의 wait_timeout 기본 설정값인 28800초(8시간)으로 설정됨
wait_timeout 을 1시간으로 설정
maxLifetime, wait_timeout 기본값이 이미 maxLifetime의 값이 wait_timeout값 보다 작아서 이 설정은 에러를 해결할 수 없었음
Azure Load Balancer가 유휴 연결을 4분(기본값) 후에 닫기 때문에, 그보다 더 긴 시간 동안 유휴 상태로 있는 연결은 닫힐 수 있고 이로 인해 HikariCP가 MariaDB 연결을 사용하려 할 때 해당 연결이 이미 닫혀 있는 상황이 발생할 수 있다는 것을 알게됨
Azure VM 구성에서 유휴시간을 변경할 수 있음
기본값이 4분이기 때문에 설정을 변경하기로함
최대 생존 시간을 3분으로 설정하여 3분마다 새 커넥션으로 대체하도록 하여 에러 발생을 해결함
# 3m
spring.datasource.hikari.maxLifetime=180000