728x90
1. 들어가며
어느 순간부터 특정 배치 스케줄러가 돌면 RecoverableDataAccessException이 발생하기 시작하였다. RecoverableDataAccessException은 JDBC 커밋 도중에 문제가 있을 경우 예외를 발생시킨다. 커넥션을 반환해줄때 이미 끊어져버린 커넥션을 사용하도록 반환해주어 DB와 통신하지 못했기 때문에 발생한다고 한다. 그럼 해당 Exception을 해결해보자.
2. 소스 분석하기
먼저, 다음 1시간 동안 배치가 도는 예시 소스이다. 아래 예시 소스를 보면서 문제가 될만한 부분이 있는지 생각해보자.
# Controller
@PostMapping("/batch/example")
public ResponseEntity<ApiResponse<String>> fetchExample(
@RequestParam(value="currentDate", required = false) String currentDate
) {
String filePath = globalConfig.getBatchFilePath();
String fileName = EX_FILENAME;
batchService.batchByFile(FileType.EX_FILENAME, filePath, fileName, JSON_EXTENSION, currentDate, false);
return ResponseEntity.ok().body(ApiResponse.success());
}# BatchService
@Async
public void batchByFile(FileType fileType, String filePath, String fileName, String extensionName, String currentDate) {
if(currentDate == null || currentDate.isEmpty()) {
currentDate = DateUtils.localDateTimeToString(LocalDate.now(), DATE_NO_HYPHEN);
}
boolean isReady = fileService.pretreatmentFetchFile(filePath, fileName, extensionName, currentDate);
if(isReady){
int maxRetries = 2;
int retryCnt = 0;
boolean isSuccess = false;
while (retryCnt < maxRetries) {
isSuccess = fileService.fetchAndSave(fileType, filePath, fileName, currentDate);
if(isSuccess) {
break;
}else{
retryCnt++;
}
}
if(!isSuccess) sendProductBatchFailMessage(fileType.getName());
fileService.afterTreatmentFetchFile(filePath);
}
}# FileService
@Transactional
public boolean fetchAndSave(FileType fileType, String filePath, String fileName, String currentDate){
try {
FileBatchService fileBatchService = fileBatchFactory.getFileBatchService(fileType);
return fileBatchService.save(filePath, fileName, currentDate);
} catch (Exception e){
sendFileOperationFailMessage(e.getMessage());
return false;
}
}# Factory에서 가져온 FileBatchService의 한 로직
@Override
public boolean save(String filePath, String fileName, String currentDate) throws Exception {
return insertExampleFile();
}이때 insertUserLogFile는 대략 1시간 소요된다고 가정한다.
# 멀티 쓰레드에서 해당 메서드를 실행하는 insertExampleFile 로직 중 일부
batchDao.upsertList("db_name", list);# DB 접근 로직
public boolean upsertList(String mediaId, List<Example> exampleList) {
try{
BulkOperations bulkOperations = mongoFactory.getMongoTemplate(mediaId).bulkOps(BulkOperations.BulkMode.ORDERED, "exampleData");
for (Example exampleData : exampleList) {
Query query = new Query(Criteria.where("_id").is(exampleData.getUid()));
Update update = new Update()
.set("date", exampleData.getDate())
.set("prdtList", exampleData.getPrdtList());
bulkOperations.upsert(query, update);
}
bulkOperations.execute();
return true;
}catch (Exception e){
log.error(e.getMessage(), e);
return false;
}
}(불필요한 부분은 생략)
3. 에러 로그 분석하기
위 소스를 실행하게 되면 RecoverableDataAccessException이 발생하게 된다. 원인이 무엇인지 생각해보자. (실제로 경험했던 소스를 바탕으로 예시 소스 작성)
# 발생한 에러 메세지
[2024-04-11 15:04:02,149] [task-6] [ERROR] [JdbcTransactionManager:902] : Commit exception overridden by rollback exception
org.springframework.dao.RecoverableDataAccessException: JDBC commit; The last packet successfully received from the server was 1,342,328 milliseconds ago. The last packet sent successfully to the server was 1,342,328 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.; nested exception is com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 1,342,328 milliseconds ago. The last packet sent successfully to the server was 1,342,328 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at org.springframework.jdbc.support.SQLExceptionSubclassTranslator.doTranslate(SQLExceptionSubclassTranslator.java:100)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:70)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79)
at org.springframework.jdbc.support.JdbcTransactionManager.translateException(JdbcTransactionManager.java:184)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:336)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:637)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:390)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:134)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
at com.mobwith.mobtune.service.FileService$$EnhancerBySpringCGLIB$$af2f3629.fetchAndSave(<generated>)
at com.mobwith.mobtune.service.BatchService.batchByFile(BatchService.java:471)
at com.mobwith.mobtune.service.BatchService$$FastClassBySpringCGLIB$$d8033b7f.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)
at scouter.agent.wrapper.async.WrTaskCallable.call(WrTaskCallable.java:38)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 1,342,328 milliseconds ago. The last packet sent successfully to the server was 1,342,328 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
at com.mysql.cj.jdbc.ConnectionImpl.commit(ConnectionImpl.java:814)
at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:387)
at com.zaxxer.hikari.pool.HikariProxyConnection.commit(HikariProxyConnection.java)
at scouter.xtra.jdbc.DetectConnection.commit(DetectConnection.java:227)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:333)
... 21 common frames omitted
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: The last packet successfully received from the server was 1,342,328 milliseconds ago. The last packet sent successfully to the server was 1,342,328 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
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.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:544)
at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:708)
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:647)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:946)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:892)
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1073)
at com.mysql.cj.jdbc.ConnectionImpl.commit(ConnectionImpl.java:802)
... 25 common frames omitted
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:67)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:538)
... 31 common frames omitted
[2024-04-11 15:04:02,150] [task-6] [ERROR] [SimpleAsyncUncaughtExceptionHandler:39] : Unexpected exception occurred invoking async method: public void com.mobwith.mobtune.service.BatchService.batchByFile(com.mobwith.mobtune.enums.FileType,java.lang.String,java.lang.String,java.lang.String,java.lang.String,boolean)
org.springframework.transaction.TransactionSystemException: JDBC rollback failed; nested exception is java.sql.SQLException: Connection is closed
at org.springframework.jdbc.datasource.DataSourceTransactionManager.translateException(DataSourceTransactionManager.java:435)
at org.springframework.jdbc.support.JdbcTransactionManager.translateException(JdbcTransactionManager.java:188)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:351)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.doRollbackOnCommitException(AbstractPlatformTransactionManager.java:892)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:775)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:637)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:390)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:134)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
at com.mobwith.mobtune.service.FileService$$EnhancerBySpringCGLIB$$af2f3629.fetchAndSave(<generated>)
at com.mobwith.mobtune.service.BatchService.batchByFile(BatchService.java:471)
at com.mobwith.mobtune.service.BatchService$$FastClassBySpringCGLIB$$d8033b7f.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)
at scouter.agent.wrapper.async.WrTaskCallable.call(WrTaskCallable.java:38)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.sql.SQLException: Connection is closed
at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:515)
at com.sun.proxy.$Proxy222.rollback(Unknown Source)
at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:396)
at com.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java)
at scouter.xtra.jdbc.DetectConnection.rollback(DetectConnection.java:249)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:348)
... 22 common frames omitted
# TransactionAutoConfiguration 클래스에서 확인할 수 있는데 이 클래스는 @ConditionalOnClass (PlatformTransactionManager.class) 조건을 가지고 있다.
# PlatformTransactionManager의 구현체로 DataSourceTransactionManager를 상속 받은 JdbcTransactionManager가 결국 Transcational에 사용되는 것이다. 필자는 "어라? 분명 해당 로직에는 mysql을 사용하지 않고 mongoDB에만 적재하는 로직을 가지고 있는데 커넥션이 끊기는 RecoverableDataAccessException이 발생하는거지?" 라고 생각했다. mysql의 경우 wait_timeout동안 접속하지 않으면 커넥션을 종료시키는건 알겠어. 그러면 어느 시점에 connection을 시도하는거지..?
@Transactional이 그 원인이다(FileService.fetchAndSave에서 사용한). Spring의 Transactional은 간단히 다음과 같이 동작한다.
- Spring이 bean에 @Transactional이 있을 경우 동적 proxy를 만든다.
- proxy는 transaction manager에 접근할 수 있으며 connection을 열고 닫을 수 있다.
- Transaction manager는 jdbc 방식으로 관리한다.
- MongoDB Transaction을 사용하기 위해서는 MongoTransactionManager를 설정해줘야 한다.
따라서 @Transactional이 붙은 fetchAndSave 메서드는 다음과 같이 동작한다고 볼 수 있다.
public boolean fetchAndSave(FileType fileType, String filePath, String fileName, String currentDate){
Connection connection = dataSource.getConnection();
try (){
connection.setAutoCommit(false);
try {
FileBatchService fileBatchService = fileBatchFactory.getFileBatchService(fileType);
return fileBatchService.save(filePath, fileName, currentDate);
} catch (Exception e){
sendFileOperationFailMessage(e.getMessage());
return false;
}
connection.commit();
} catch (SQLException e) {
connection.rollback();
}
} fetchAndSave 메서드가 실행되는 시점에 jdbc 커넥션을 맺고 배치가 wait_timeout보다 길었기 때문에 발생하였던 것이다.
wait_timeout 동안 해당 커넥션이 활동을 하지않으면 강제로 끊어버립니다. 다만, 어플리케이션의 커넥션 풀은 그 행위를 알지 못하고 이미 끊어져버린 커넥션을 사용하도록 반환해주어 EOFException이 발생하였다. 이 내용은 로그를 통해서 확인할 수 있는데 순차적으로 EOFException, CJCommunicationsException,CommunicationsException, RecoverableDataAccessException으로 이어진 것을 확인할 수 있습니다.
- RecoverableDataAccessException : JDBC 커밋 도중에 발생
- CommunicationsException : JDBC 커넥션 통신 중에 문제
- CJCommunicationsException : MySQL 서버와의 통신 문제
- EOFException : MySQL 서버로부터 응답을 읽을 수 없는 상황에서 발생
4. 해결 방안
RecoverableDataAccessException를 해결할 수 있는 방법은 여러 가지 방안이 있었는데 필자는 아래의 3번을 선택하였습니다.
- wait_timeout을 늘려주거나 배치 시간 단축
- connectionTestQuery의 select 1로 풀에서 커넥션을 가져올때 헬스 체크로 사용
- 적절한 @Transactional 사용
가장 단순한 방법은 wait_timeout을 늘려주는 것인데 불필요하게 wait_timeout을 늘려줄 필요는 없다고 생각했으며 connectionTestQuery 방식은 JDBC4를 지원하는 경우 이 속성을 사용하지 않는 것이 좋다고 알려져 있으며 다른 대안이 있었기 때문에 사용하지 않았습니다.
적절한 Transactional 어노테이션 사용은 기본이며, 애초에 jdbc 연결이 필요없는 배치에서 발생한 에러입니다. 따라서 공통적으로 @Transactional이 붙어있는 로직에서 batch 서비스별 필요한 경우에만 사용하도록 수정하며 문제를 해결하였습니다.
5. 결론
앞으로 Transactional 어노테이션 사용에 주의하여 사용해야겠다.
728x90
'개발 > Spring' 카테고리의 다른 글
| [WebClientRequestException] Pending acquire queue has reached its maximum size of 40 해결한 경험 (1) | 2024.09.16 |
|---|---|
| [MongoDB] MongoInterruptedException 해결하기 (0) | 2024.06.02 |
| [Spring Security] SecurityContextHolder와 Authentication 알아보기 (0) | 2023.04.19 |
| Spring boot에 Swagger 적용하기 (0) | 2023.03.31 |
| Spring security + JWT 구현 방식 (0) | 2023.03.29 |
댓글