I have a spring batch job that reads from a DB2 instance, does a slight transformation, then inserts into a MySql instance on RDS using a JdbcBatchItemWriter. The job uses multi-thread step via a TaskExecutor to scale. I am setting hikari max pool size and step executor's throttle limit both at 32 which generates an overall throughput of about 700 items/sec. Things hum along nicely for what seems arbitrary amounts of time when I'm suddenly hit with...
Caused by: java.io.IOException: Socket is closed
at com.mysql.cj.protocol.AbstractSocketConnection.getMysqlInput(AbstractSocketConnection.java:72) ~[mysql-connector-java-8.0.26.jar:8.0.26]
in the writer. I am able to monitor connections on the MySql instance via workbench and everything seems fine. No stale connections (all 32 are busy 99% of the time) and if one or two do stay idle for 90 seconds hikari house keeping cleans them up as expected. I'm also able to check the MySql instance via AWS console and nothing looks out of the ordinary there either. Likewise MySql audit log shows nothing but ordinary operation at the time of the exception. I'm stumped on what is causing the socket closure. Any thoughts would be appreciated.
Datasource config...
@Configuration
public class OtlDbConfig {
@Value("${spring.datasource.otl.username}")
private String otlUser;
@Value("${spring.datasource.otl.password}")
private String otlPwd;
@Value("${spring.datasource.otl.url}")
private String otlUrl;
@Value("${spring.datasource.otl.driver-class-name}")
private String driver;
@Value("${spring.datasource.hikari.maximum-pool-size}")
private int maxPoolSize;
@Primary
@Bean(name = "OtlDataSource")
public DataSource dataSource() {
HikariDataSource dataSource = new HikariDataSource();
dataSource.setUsername(this.otlUser);
dataSource.setPassword(this.otlPwd);
dataSource.setJdbcUrl(this.otlUrl);
dataSource.setMaximumPoolSize(this.maxPoolSize);
dataSource.setMaxLifetime(90000);
dataSource.setDriverClassName(this.driver);
dataSource.setPoolName("HikariPool-OTL");
return dataSource;
}
@Primary
@Bean(name = "OtlJdbcTemplate")
public NamedParameterJdbcTemplate otlJdbcTemplate(@Qualifier("OtlDataSource") DataSource datasource) {
return new NamedParameterJdbcTemplate(datasource);
}
}
Step Config...
return stepBuilder.get("LonelyStep")
.<Statement,Statement>chunk(nonNull(chunkSize) ? chunkSize : DEFAULT_CHUNK_SIZE)
.reader(reader(null,null,null))
.writer(writer())
.listener(new ThroughputAwareChunkListener())
.taskExecutor(stepExecutor()).throttleLimit(throttleLimit)
.build();
Writer config...
public JdbcBatchItemWriter<Statement> writer() {
return new JdbcBatchItemWriterBuilder<Statement>()
.dataSource(otlDataSource)
.namedParametersJdbcTemplate(otlJdbcTemplate)
.itemPreparedStatementSetter((item, ps) -> {
ps.setLong(1, item.getXXX());
ps.setString(2, item.getYYY());
})
.sql("INSERT INTO sometable (xxx, yyy) VALUES (?,?)")
.build();
}
Executor config...
public TaskExecutor stepExecutor() {
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
executor.setThreadNamePrefix("step-worker-");
executor.setMaxPoolSize(this.maxPoolSize);
executor.setCorePoolSize(this.maxPoolSize);
return executor;
}
URL: jdbc:mysql://host:3306/db?useSSL=true&enabledTLSProtocols=TLSv1.2&autoReconnect=true
Log snippet with full stack trace...
2021-08-16 10:05:49.319 INFO 13032 --- [ step-worker-15] c.n.a.m.b.ThroughputAwareChunkListener : readCount=946400, writeCount=946400, filterCount=0, readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=9463, throughput=705.216/s
2021-08-16 10:05:49.406 INFO 13032 --- [ step-worker-14] c.n.a.m.b.ThroughputAwareChunkListener : readCount=946500, writeCount=946500, filterCount=0, readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=9465, throughput=705.291/s
2021-08-16 10:05:49.491 INFO 13032 --- [ step-worker-17] c.n.a.m.b.ThroughputAwareChunkListener : readCount=946600, writeCount=946600, filterCount=0, readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=9465, throughput=705.365/s
2021-08-16 10:05:49.538 WARN 13032 --- [ step-worker-2] com.zaxxer.hikari.pool.ProxyConnection : HikariPool-OTL - Connection com.mysql.cj.jdbc.ConnectionImpl@8a79487 marked as broken because of SQLSTATE(08S01), ErrorCode(0)
java.sql.BatchUpdateException: Communications link failure
The last packet successfully received from the server was 33 milliseconds ago. The last packet sent successfully to the server was 33 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_302]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_302]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_302]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_302]
at com.mysql.cj.util.Util.handleNewInstance(Util.java:192) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.util.Util.getInstance(Util.java:167) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.util.Util.getInstance(Util.java:174) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.exceptions.SQLError.createBatchUpdateException(SQLError.java:224) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchSerially(ClientPreparedStatement.java:853) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchInternal(ClientPreparedStatement.java:435) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.StatementImpl.executeBatch(StatementImpl.java:796) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:127) ~[HikariCP-4.0.3.jar:na]
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java) [HikariCP-4.0.3.jar:na]
at org.springframework.batch.item.database.JdbcBatchItemWriter$1.doInPreparedStatement(JdbcBatchItemWriter.java:193) [spring-batch-infrastructure-4.3.3.jar:4.3.3]
at org.springframework.batch.item.database.JdbcBatchItemWriter$1.doInPreparedStatement(JdbcBatchItemWriter.java:186) [spring-batch-infrastructure-4.3.3.jar:4.3.3]
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) [spring-jdbc-5.3.9.jar:5.3.9]
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:691) [spring-jdbc-5.3.9.jar:5.3.9]
at org.springframework.batch.item.database.JdbcBatchItemWriter.write(JdbcBatchItemWriter.java:186) [spring-batch-infrastructure-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.item.SimpleChunkProcessor.writeItems(SimpleChunkProcessor.java:193) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.item.SimpleChunkProcessor.doWrite(SimpleChunkProcessor.java:159) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.item.SimpleChunkProcessor.write(SimpleChunkProcessor.java:294) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.item.SimpleChunkProcessor.process(SimpleChunkProcessor.java:217) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.item.ChunkOrientedTasklet.execute(ChunkOrientedTasklet.java:77) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:407) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:331) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) [spring-tx-5.3.9.jar:5.3.9]
at org.springframework.batch.core.step.tasklet.TaskletStep$2.doInChunkContext(TaskletStep.java:273) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.core.scope.context.StepContextRepeatCallback.doInIteration(StepContextRepeatCallback.java:82) [spring-batch-core-4.3.3.jar:4.3.3]
at org.springframework.batch.repeat.support.TaskExecutorRepeatTemplate$ExecutingRunnable.run(TaskExecutorRepeatTemplate.java:262) [spring-batch-infrastructure-4.3.3.jar:4.3.3]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_302]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_302]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_302]
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure
The last packet successfully received from the server was 33 milliseconds ago. The last packet sent successfully to the server was 33 milliseconds ago.
at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1092) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeBatchSerially(ClientPreparedStatement.java:832) ~[mysql-connector-java-8.0.26.jar:8.0.26]
... 23 common frames omitted
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure
The last packet successfully received from the server was 33 milliseconds ago. The last packet sent successfully to the server was 33 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_302]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_302]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_302]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_302]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.protocol.a.NativeProtocol.clearInputStream(NativeProtocol.java:791) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:603) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:970) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:662) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:930) ~[mysql-connector-java-8.0.26.jar:8.0.26]
... 25 common frames omitted
Caused by: java.io.IOException: Socket is closed
at com.mysql.cj.protocol.AbstractSocketConnection.getMysqlInput(AbstractSocketConnection.java:72) ~[mysql-connector-java-8.0.26.jar:8.0.26]
at com.mysql.cj.protocol.a.NativeProtocol.clearInputStream(NativeProtocol.java:787) ~[mysql-connector-java-8.0.26.jar:8.0.26]
... 29 common frames omitted
2021-08-16 10:05:49.575 INFO 13032 --- [ step-worker-18] c.n.a.m.b.ThroughputAwareChunkListener : readCount=946700, writeCount=946700, filterCount=0, readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=9466, throughput=704.914/s
2021-08-16 10:05:49.669 INFO 13032 --- [ step-worker-27] c.n.a.m.b.ThroughputAwareChunkListener : readCount=946800, writeCount=946800, filterCount=0, readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=9467, throughput=704.989/s
2021-08-16 10:05:49.762 INFO 13032 --- [ step-worker-8] c.n.a.m.b.ThroughputAwareChunkListener : readCount=946900, writeCount=946900, filterCount=0, readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=9468, throughput=705.063/s