이게 대체 무슨 에러인가요?

Question

안녕하세요.요즘 스프링 배치 &#43; 스케줄러로 주기적인 DB 테이블 갱신 프로그램을 작성하고 있는데요.이게 잘 돌아가다가 가끔씩 아래 두개의 WARNING 또는 ERROR를 비정기적으로 뿜습니다. // 1분 마다 동작하는 배치(10초 가량 소요)2018-11-02 15:14:00.273 INFO 11724 --- [taskScheduler-1] o.s.b.c.l.support.SimpleJobLauncher : Job: [SimpleJob: [name&#61;MyRealtimeJob]] launched with the following parameters: [{time&#61;1541139240039}] 2018-11-02 15:14:00.463 INFO 11724 --- [taskScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [truncateTempMyRealtimeStep] 2018-11-02 15:14:00.979 INFO 11724 --- [taskScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [saveTempMyRealtimeStep] 2018-11-02 15:14:03.730 INFO 11724 --- [taskScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [insertAndUpdateMyRealtimeStep] 2018-11-02 15:14:04.116 INFO 11724 --- [taskScheduler-1] o.s.b.c.l.support.SimpleJobLauncher : Job: [SimpleJob: [name&#61;MyRealtimeJob]] completed with the following parameters: [{time&#61;1541139240039}] and the following status: [COMPLETED] 2018-11-02 15:15:05.250 INFO 11724 --- [taskScheduler-1] o.s.b.c.l.support.SimpleJobLauncher : Job: [SimpleJob: [name&#61;MyRealtimeJob]] launched with the following parameters: [{time&#61;1541139300008}] 2018-11-02 15:15:08.261 INFO 11724 --- [taskScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [truncateTempMyRealtimeStep] 2018-11-02 15:15:13.777 INFO 11724 --- [taskScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [saveTempMyRealtimeStep] 2018-11-02 15:15:45.617 INFO 11724 --- [taskScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [insertAndUpdateMyRealtimeStep] 2018-11-02 15:15:45.978 INFO 11724 --- [taskScheduler-1] o.s.b.c.l.support.SimpleJobLauncher : Job: [SimpleJob: [name&#61;MyRealtimeJob]] completed with the following parameters: [{time&#61;1541139300008}] and the following status: [COMPLETED] 2018-11-02 15:15:59.268 WARN 11724 --- [taskScheduler-3] com.zaxxer.hikari.pool.ProxyConnection : HikariPool-1 - Connection org.postgresql.jdbc.PgConnection&#64;54e13f4d marked as broken because of SQLSTATE(08006), ErrorCode(0) java.sql.BatchUpdateException: Batch entry 767 /* 실행중이던 쿼리 하나 쫘악 나오고... */ was aborted. Call getNextException to see the cause. 2018-11-02 15:15:59.275 INFO 11724 --- [taskScheduler-3] o.s.b.f.xml.XmlBeanDefinitionReader : Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml] 2018-11-02 15:15:59.306 INFO 11724 --- [taskScheduler-3] o.s.jdbc.support.SQLErrorCodesFactory : SQLErrorCodes loaded: [DB2, Derby, H2, HSQL, Informix, MS-SQL, MySQL, Oracle, PostgreSQL, Sybase, Hana] 2018-11-02 15:15:59.306 WARN 11724 --- [taskScheduler-3] o.s.jdbc.support.SQLErrorCodesFactory : Error while extracting database name - falling back to empty error codes /* 스택 쫘악 나오고 */ org.springframework.jdbc.support.MetaDataAccessException: Error while extracting DatabaseMetaData; nested exception is java.sql.SQLException: Connection is closed Caused by: java.sql.SQLException: Connection is closed // 10분 마다 동작하는 배치(5분가량 소요)2018-11-01 10:30:05.660 INFO 26108 --- [taskScheduler-3] o.s.batch.core.job.SimpleStepHandler : Executing step: [insertLogMyAverageStep] 2018-11-01 10:30:06.113 INFO 26108 --- [taskScheduler-3] o.s.batch.core.job.SimpleStepHandler : Executing step: [updateMyAverageStep] 2018-11-01 10:30:06.852 INFO 26108 --- [taskScheduler-3] o.s.batch.core.job.SimpleStepHandler : Executing step: [loggingTargetTableStep] 2018-11-01 10:30:22.312 INFO 26108 --- [taskScheduler-3] o.s.batch.core.job.SimpleStepHandler : Executing step: [updateTargetTableStep] 2018-11-01 10:31:30.037 ERROR 26108 --- [taskScheduler-5] o.s.s.s.TaskUtils$LoggingErrorHandler : Unexpected error occurred in scheduled task. org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:289) ~[spring-jdbc-4.3.9.RELEASE.jar!/:4.3.9.RELEASE] /* 스택 쫘악 나오고 */ Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. Caused by: org.postgresql.util.PSQLException: The connection attempt failed. Caused by: java.net.NoRouteToHostException: No route to host: connect 보면 100번을 잘 되다가도 항상 같은 배치 작업중에 하루 두 세번 꼴로 에러가 발생합니다.혹시 무슨 경우인지 짐작이 가시면 조언 좀 부탁드립니다. 개발환경은 아래와 같습니다.JDK 7PostgreSQL 9.3PostgreSQL 커넥터 9.4.1207.jre7HikariCP 2.4.7Spring Boot 1.4.7Spring Batch 3.0.9 Datasource설정은 아래와 같습니다.import javax.sql.DataSource; import org.apache.ibatis.session.SqlSessionFactory; import org.mybatis.spring.SqlSessionFactoryBean; import org.mybatis.spring.SqlSessionTemplate; import org.mybatis.spring.annotation.MapperScan; import org.springframework.beans.factory.annotation.Qualifier; import org.springframework.boot.autoconfigure.jdbc.DataSourceBuilder; import org.springframework.boot.context.properties.ConfigurationProperties; import org.springframework.context.ApplicationContext; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import org.springframework.context.annotation.Primary; import org.springframework.jdbc.datasource.DataSourceTransactionManager; import org.springframework.transaction.PlatformTransactionManager; import com.zaxxer.hikari.HikariDataSource; &#64;Configuration &#64;MapperScan( basePackages &#61; &#34;com.batch.my.**.dao.openapi&#34;, sqlSessionFactoryRef &#61; &#34;openAPISqlSessionFactory&#34; ) public class OpenAPIDatabaseConfiguration{ &#64;Bean(name &#61; &#34;openAPIDataSource&#34;) &#64;Primary &#64;ConfigurationProperties(prefix &#61; &#34;spring.openapi.datasource.hikari&#34;) public DataSource openAPIDataSource(){ HikariDataSource hikariDataSource &#61; new HikariDataSource(); hikariDataSource.setMaximumPoolSize(3); hikariDataSource.setMinimumIdle(1); hikariDataSource.setMaxLifetime(180000); return hikariDataSource; } &#64;Bean(name &#61; &#34;openAPISqlSessionFactory&#34;) &#64;Primary public SqlSessionFactory openAPISqlSessionFactory( &#64;Qualifier(&#34;openAPIDataSource&#34;) DataSource openAPIDataSource, ApplicationContext applicationContext ) throws Exception{ SqlSessionFactoryBean sqlSessionFactoryBean &#61; new SqlSessionFactoryBean(); sqlSessionFactoryBean.setDataSource(openAPIDataSource); sqlSessionFactoryBean.setConfigLocation(applicationContext.getResource(&#34;classpath:sql/mybatis-config.xml&#34;)); sqlSessionFactoryBean.setMapperLocations(applicationContext.getResources(&#34;classpath:sql/mapper/openapi/*.xml&#34;)); return sqlSessionFactoryBean.getObject(); } &#64;Bean(name &#61; &#34;openAPISqlSessionTemplate&#34;) &#64;Primary public SqlSessionTemplate openAPISqlSessionTemplate( &#64;Qualifier(&#34;openAPISqlSessionFactory&#34;) SqlSessionFactory openAPISqlSessionFactory ) throws Exception{ return new SqlSessionTemplate(openAPISqlSessionFactory); } &#64;Bean(name &#61; &#34;openAPITransactionManager&#34;) public PlatformTransactionManager openAPITransactionManager( &#64;Qualifier(&#34;openAPIDataSource&#34;) DataSource openAPIDataSource){ return new DataSourceTransactionManager(openAPIDataSource); } } 어떨때 연결이 끊기는것인지, 끊겼다면 왜 재연결하지 않는 것인지 조언 좀 부탁드립니다.감사합니다.

강남길 · Answer

저도 저거랑 비슷한 에러 있었는데,톰캣 다시 빌드할때 제대로 shutdown이 안되면 나더라구요. 배치 돌릴때 가끔 shutdown을 해도 shutdown이 안될때가 있어요.

아야로 · Answer

잡채밥냠냠제 경우 jar파일을 실행하는 것으로, 톰캣은 사용하지 않습니다. 스프링 부트 내장 톰캣도 제거하였구요.으음... 디비 타임아웃이 관련된것 같은데 도통 모르겠네요.답글 감사합니다.

seka · Answer

정확히는 모르겠는데 찾아보니까 이런게 있네요.도움이됐음 좋겠네요 https://github.com/brettwooldridge/HikariCP/issues/1007https://github.com/RWTH-i5-IDSG/steve/issues/57

zepinos · Answer

종료할 때 어떤 방식으로 끄시나요? kill -9 나 개발툴에서의 stop , break 등으로 끌 경우 문제가 발생항 수 있는데 그 부분도 염두에 두시길...

아야로 · Answer

zepinos리눅스 서버에 올리기전에 윈도우10 로컬 환경에서 테스트 하고 있습니다.cmd창 열어서 java -jar mybatch1.0.jar 쳐서 6~9시간씩 실행해보고끌때는 같은 창에서 Ctrl &#43; C 두 번 따닥 쳐서 종료합니다. 리눅스 서버에서는 역시 java -jar 명령어로 실행 후 백그라운드로 돌려두었다가, 끌때는 kii -9 사용합니다.으으 그렇게 공부를 해도 데이터베이스만 얽히면 가슴이 갑갑하네요 ㅠㅠ

zepinos · Answer

kill -9 가 문제가 되는게 graceful 하게 종료가 되지 않고 즉시 중단이 되어버리기 때문입니다. 그럼 데이터가 꼬이는 일까지 발생합니다. 증상이 혹시 윈도에서도 발생하나요? 그리고 db pool 에서 정말 커넥션을 실패하고 있는지도 보셔야 할 것 같습니다.

아야로 · Answer

zepinos예, 윈도우에서 발생합니다. 1분짜리 배치는 warning 정도이고 다음번 배치때 잘 실행되기에 긴급하지 않지만, 10분 주기 배치는 A테이블의 내용을 B테이블에 pk 비교해 업데이트 하는것으로 쿼리 한 번에 2~3분이 소요되는데는요. 작업중에 가끔씩 저 error가 발생하면 그대로 해당 job이 죽어버리고 jar 재실행 할때까지 회복되지 않습니다.(로그보면 updateTargetTableStep 수행 68초 후에 HikariPool에서 30000ms가 지나 커넥션 사용이 불가하다고 나오지요)하여 쿼리가 너무 오래 걸리면 커넥션이 끊어지는게 아닐까하는 추측으로 접근해보고 있습니다.리눅스 쪽은 오랫동안 켜놓은 적이 없어 확인해보지 못했습니다만, kill -9 대신 배치 작업 완료 후 종료되도록 찾아봐야겠네요.답글 정말 감사합니다. &#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;&#61;https://github.com/brettwooldridge/HikariCP/issues/1199여기를 보니 다중 데이타소스 환경에서 동일 트랜젝션 내에 두 개의 데이타소스 접근 시 생기는 일이 아닌가 추측하네요.아무래도 제 스프링 배치에서 step 단위 트랜젝션이 아니라 job단위로 트랜젝션이 걸려있는 것 같으니 코드를 다시 한 번 뜯어봐야겠습니다.

이게 대체 무슨 에러인가요?

7개의 답변

Q&A 목록