개요
- DB MMM 구성 적용 이후부터 API 서버에서 간헐적으로 다음과 같은 에러 로그 발생.
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed. at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73) at com.mysql.cj.jdbc.ConnectionImpl.setNetworkTimeout(ConnectionImpl.java:2485) at net.sf.log4jdbc.sql.jdbcapi.ConnectionSpy.setNetworkTimeout(ConnectionSpy.java:1120) at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:566) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:137) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed. at jdk.internal.reflect.GeneratedConstructorAccessor239.newInstance(Unknown Source) at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499) at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480) at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:761) at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:568) at com.mysql.cj.jdbc.ConnectionImpl.setNetworkTimeout(ConnectionImpl.java:2481) ... 7 common frames omitted - 확인 결과 1분 이상 서버에 아무런 요청이 없을 경우(DB 커넥션이 생성되고 1분 이상 idle 인 경우) 다음 API 요청에 지연(5~10초)이 발생하면서 해당 로그 발생.
원인분석1
java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.오류는 DBCP에 생성해두었던 db 커넥션을 사용하려고 하는데, 이미 close 된 경우 발생하는 오류.- 보통 이런 오류는 DBCP에서 커넥션을 유지하는 시간 > DB에서 커넥션을 유지하는 시간 일 경우 발생한다고 함.
- close 되어있는 커넥션들을 정리하고, 새로 커넥션을 생성하는 과정에서 지연이 발생.
- 관련 설정 확인
- DBCP: MAX_LIFETIME = 30분
- DB: interactive_timeout = 28800(8시간), wait_timeout = 28800(8시간)
- 확인가능한 커넥션 설정값은 문제가 없는것으로 확인됨....
원인분석2
- DBCP를 걷어내고, JDBC 만으로
커넥션 생성 -> N초 딜레이 -> 커넥션 유효성 검사이런 과정으로 테스트를 진행.- 대략 60초 전후로 커넥션이 종료되는 오류를 확인함.
- DB Connection 내에서 사용되는 통신, TCP소켓 연결이 끊긴 상황을 의심.
- 확인 결과 TCP 소켓에는
tcp_keepalive_time값이 있으며, 해당 대기 시간 이상으로 통신이 없을 경우 TCP 연결을 종료한다는 점을 확인. - 새로 구성된 DB서버, MMM L4서버에서 해당 값이 1분으로 설정되어있어서 커넥션이 닫히는것으로 결론.
- 확인 결과 TCP 소켓에는
문제해결
- 해결방안 1: DB 서버의
tcp_keepalive_time설정 수정.- 현재 60초로 설정되있는걸로 추정되는데, 이를 hikaricp의
max_lifetime설정보다 높게 설정. - 그러나 DB서버, MMM L4서버 모두 설정값을 확인해야하고, 또한 MMM의 서버의 권한이 없는데다, 내가 모르는 다른 이유가 있을수도 있으므로 기각.
- 현재 60초로 설정되있는걸로 추정되는데, 이를 hikaricp의
- 해결방안 2: hikaricp
keepaliveTime설정 추가.- keepaliveTime
- keepaliveTime 주기로 커넥션에 isValid 요청을 보냄으로서 tcp 연결을 계속 유지시킬 수 있음. 채택.
출처
