はじめに

Azureが提供しているデータベースには、下記のドキュメントにあるように一時的な接続エラーに対処する必要があります。

この対処方法をSpring Bootで実装してみることにしました。

参考サイト

以下のサイトに参考となりそうな記事がありましたので、それを元に実装してみます。

www.linkedin.com

ライブラリの追加

Spring Boot向けのリトライを実装するライブラリとしてSpring Retryというものがあるのでこれを利用します。

github.com

Gradleではbuild.gradleにてdependenciesの中に以下の記述を追加すれば良いようです。

implementation 'org.springframework.retry:spring-retry:1.3.1'
runtimeOnly 'org.springframework.boot:spring-boot-starter-aop'

リトライ処理の実装

getConnectionメソッドに対して@Retryableでリトライするようにします。

public class RetryableDataSource extends AbstractDataSource {
    private final DataSource dataSource;

    public RetryableDataSource(DataSource dataSource) {
        this.dataSource = dataSource;
    }

    @Override
    @Retryable(maxAttempts = 12, backoff = @Backoff(delay = 5_000, maxDelay = 10_000))
    public Connection getConnection() throws SQLException {
        return dataSource.getConnection();
    }

    @Override
    @Retryable(maxAttempts = 12, backoff = @Backoff(delay = 5_000, maxDelay = 10_000))
    public Connection getConnection(String username, String password) throws SQLException {
        return dataSource.getConnection(username, password);
    }
}

上記のClassを使うようにします。

@Order(value = Ordered.HIGHEST_PRECEDENCE)
@Component
public class RetryableDatabasePostProcessor implements BeanPostProcessor {
    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        if (bean instanceof DataSource) {
            return new RetryableDataSource((DataSource) bean);
        }
        return bean;
    }

    @Override
    public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
        return bean;
    }
}

アプリの実装

Spring BootのCommandLineRunnerを使って簡単なバッチ処理を実装します。1件ずつレコードをinsertして1秒スリープします。

@Service
public class MyService {
    private static final Logger log =
            LoggerFactory.getLogger(MyService.class);
    @Value("${app.records.num:100}")
    private int RECORDS_NUM;

    @Autowired
    JdbcTemplate jdbcTemplate;

    public void insert() {
        log.info("Start insert method...");
        for (int i = 0; i < RECORDS_NUM; i++) {
            String first_name = String.format("Josh%05d", i);
            String last_name = String.format("hogehoge%05d", i);
            log.info("Insert record. i = [" + i + "], first_name = [" + first_name + "], last_name = [" + last_name + "]");
            jdbcTemplate.update("INSERT INTO customers(first_name, last_name) VALUES (?, ?)", first_name, last_name);
            try {
                Thread.sleep(1_000);
            } catch (InterruptedException e) {
                log.info("Thread.sleep occurs InterruptedException. i = [" + i + "]");
            }
        }
        log.info("End insert method...");
    }
}

確認方法

一時的な接続エラーを確認する方法として、上記のドキュメントには、

たとえば、Azure Database for PostgreSQL サーバーのコンピューティングリソースをスケールアップまたはスケールダウンしているときに、実際のコードを実行してみましょう。

とあるので、プログラムが動いているときにスケールアップ／スケールダウンしてみます。ここではvCoreを変更します。

f:id:miyohide:20211024145323p:plain

確認（リトライ処理なし）

リトライ処理を実装していないプログラムにおいて、スケールアップ／スケールダウンしてみます。スケールアップ／スケールダウンしたタイミングでHikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@xxxxxxxx (This connection has been closed.). Possibly consider using a shorter maxLifetime value.が出力されます。以下のように異常終了してしまいました。

2021-10-24 04:40:06.573  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [40], first_name = 
2021-10-24 04:40:07.590  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [41], first_name = 
2021-10-24 04:40:08.620  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [42], first_name = 
2021-10-24 04:40:09.635  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [43], first_name = 
2021-10-24 04:40:09.650  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.668  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.670  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.677  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.680  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.685  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.686  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.688  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.689  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:09.697  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate conn
2021-10-24 04:40:39.649  INFO 18 --- [           main] ConditionEvaluationReportLoggingListener : "
Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled."
    at org.postgresql.core.PGStream.receiveChar(PGStream.java:445) ~[postgresql-42.2.23.jar:42.2.23]"
Caused by: org.postgresql.util.PSQLException: The connection attempt failed."
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-4.0.3.jar:na]"
    at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:223) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.Driver.connect(Driver.java:264) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at java.base/java.util.concurrent.FutureTask.run(Unknown Source) ~[na:na]"
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:na]"
    at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.run(SpringBootRetryDbApplication.java:19) ~[classes/:na]"
    at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:161) ~[postgresql-42.2.23.jar:42.2.23]"
    ... 15 common frames omitted"
    at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na]"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:315) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at com.zaxxer.hikari.pool.HikariPool.access$100(HikariPool.java:71) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.10.jar:5.3.10]"
java.lang.IllegalStateException: Failed to execute CommandLineRunner"
    at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.Driver.makeConnection(Driver.java:465) ~[postgresql-42.2.23.jar:42.2.23]"
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138) ~[HikariCP-4.0.3.jar:na]"
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:364) ~[HikariCP-4.0.3.jar:na]"
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206) ~[HikariCP-4.0.3.jar:na]"
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:na]"
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[workspace/:na]"
    at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:598) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:213) ~[postgresql-42.2.23.jar:42.2.23]"
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:794) ~[spring-boot-2.5.5.jar:2.5.5]"
Caused by: java.io.EOFException: null"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.main(SpringBootRetryDbApplication.java:14) ~[classes/:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:345) ~[spring-boot-2.5.5.jar:2.5.5]"
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:476) ~[HikariCP-4.0.3.jar:na]"
2021-10-24 04:40:39.738 ERROR 18 --- [           main] o.s.boot.SpringApplication               : Application run failed"
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    ... 20 common frames omitted"
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:88) ~[workspace/:na]"
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:726) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:775) ~[spring-boot-2.5.5.jar:2.5.5]"
Caused by: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQL
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1025) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[workspace/:na]"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[workspace/:na]"
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:646) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:712) ~[HikariCP-4.0.3.jar:na]"
    at com.github.miyohide.springbootretrydb.MyService.insert(MyService.java:30) ~[classes/:na]"
    ... 13 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms.
2021-10-24 04:40:39.748  INFO 18 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2021-10-24 04:40:40.631  INFO 18 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

確認（リトライ処理あり）

リトライ処理を実装しているプログラムにおいて、スケールアップ／スケールダウンしてみます。スケールアップ／スケールダウンしたタイミングでHikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@xxxxxxxx (This connection has been closed.). Possibly consider using a shorter maxLifetime value.が出力されます。ですが、リトライ処理が行われ以下のように正常終了しました。

2021-10-24 04:50:41.404  INFO 18 --- [           main] c.g.m.s.config.RetryableDataSource       : getting connection ..."
2021-10-24 04:50:42.452 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0"
2021-10-24 04:50:42.452  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [40], first_name = [Josh00040], last_name = [hogehoge00040]"
2021-10-24 04:50:42.454  INFO 18 --- [           main] c.g.m.s.config.RetryableDataSource       : getting connection ..."
2021-10-24 04:50:42.472  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@40a72e
2021-10-24 04:50:44.535  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@59c70c
2021-10-24 04:50:44.538  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@46f902
2021-10-24 04:50:44.544  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@64f981
2021-10-24 04:50:44.546  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@361abd
2021-10-24 04:50:44.548  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@575b5f
2021-10-24 04:50:44.550  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@59bbb9
2021-10-24 04:50:44.556  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@7165d5
2021-10-24 04:50:44.568  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@12f49c
2021-10-24 04:50:44.571  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@1fd989
2021-10-24 04:51:21.001  INFO 18 --- [           main] c.g.m.s.config.RetryableDataSource       : getting connection ..."
2021-10-24 04:51:21.001 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1"
2021-10-24 04:51:21.001 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1"
2021-10-24 04:51:26.592 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0"
2021-10-24 04:51:26.592  INFO 18 --- [           main] c.g.m.s.config.RetryableDataSource       : getting connection ..."
2021-10-24 04:51:26.591  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [41], first_name = [Josh00041], last_name = [hogehoge00041]"
2021-10-24 04:51:27.603  INFO 18 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [42], first_name = [Josh00042], last_name = [hogehoge00042]"

トランザクションをかけてみる

これでOKかなと思いましたが、insertメソッドに@Transactionalをつけて動かし、PostgreSQLのスケールアップ／スケールダウンをすると異常終了してしまいました。

2021-10-24 05:02:50.882  INFO 20 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [47], first_name = [Josh00047],
2021-10-24 05:02:51.976  INFO 20 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [48], first_name = [Josh00048],
2021-10-24 05:02:52.981  INFO 20 --- [           main] c.g.m.springbootretrydb.MyService        : Insert record. i = [49], first_name = [Josh00049],
    at java.base/java.io.BufferedOutputStream.flushBuffer(Unknown Source) ~[na:na]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791) ~[spring-boot-2.5.5.jar:2.5.5]"
    at java.base/java.io.BufferedOutputStream.flush(Unknown Source) ~[na:na]"
    at com.github.miyohide.springbootretrydb.MyService.insert(MyService.java:30) ~[classes/:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.5.jar:2.5.5]"
    at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(Unknown Source) ~[na:na]"
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.10.jar:5.3.10]"
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.10.
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.run(SpringBootRetryDbApplication.java:21) ~[classes/:na]"
    at com.github.miyohide.springbootretrydb.MyService$$FastClassBySpringCGLIB$$4d334926.invoke(<generated>) ~[classes/:na]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[workspace/:na]"
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]"
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481) ~[postgresql-42.2.23.jar:42.2.23]"
2021-10-24 05:02:53.020  WARN 20 --- [           main] com.zaxxer.hikari.pool.ProxyConnection   : HikariPool-1 - Connection org.postgresql.jdbc.PgCo
Caused by: java.net.SocketException: Connection reset by peer (Write failed)"
    at java.base/java.net.SocketOutputStream.write(Unknown Source) ~[na:na]"
    at org.postgresql.core.PGStream.flush(PGStream.java:665) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401) ~[postgresql-42.2.23.jar:42.2.23]"
    at java.base/java.net.SocketOutputStream.socketWrite(Unknown Source) ~[na:na]"
    at java.base/sun.security.ssl.SSLSocketOutputRecord.deliver(Unknown Source) ~[na:na]"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.main(SpringBootRetryDbApplication.java:13) ~[classes/:na]"
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:775) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:349) ~[postgresql-42.2.23.jar:42.2.23]"
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.10.jar:5.3.10]"
    at java.base/java.net.SocketOutputStream.socketWrite0(Native Method) ~[na:na]"
    at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1025) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[workspace/:na]"
    at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na]"
    at com.github.miyohide.springbootretrydb.MyService$$EnhancerBySpringCGLIB$$df81f8ea.insert(<generated>) ~[classes/:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:1469) ~[postgresql-42.2.23.jar:42.2.23]"
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:320) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.10.jar:5.3.10]"
org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend."
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[workspace/:na]"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:345) ~[spring-boot-2.5.5.jar:2.5.5]"
    ... 39 common frames omitted"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.10.jar:5.3.10]"
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:88) ~[workspace/:na]"
2021-10-24 05:02:53.606  INFO 20 --- [           main] c.g.m.s.config.RetryableDataSource       : getting connection ..."
2021-10-24 05:02:53.606 DEBUG 20 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0"
2021-10-24 05:02:53.613  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.626  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.631  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.640  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.643  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.644  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.646  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.654  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:02:53.656  WARN 20 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.p
2021-10-24 05:03:31.336 DEBUG 20 --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1"
2021-10-24 05:03:31.339 DEBUG 20 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1"
2021-10-24 05:03:31.340  INFO 20 --- [           main] c.g.m.s.config.RetryableDataSource       : getting connection ..."
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[workspace/:na]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at java.base/java.io.BufferedOutputStream.flush(Unknown Source) ~[na:na]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:70) ~[spring-jdbc
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:345) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791) ~[spring-boot-2.5.5.jar:2.5.5]"
    at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(Unknown Source) ~[na:na]"
    at java.base/java.io.BufferedOutputStream.flushBuffer(Unknown Source) ~[na:na]"
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[postgresql-42.2.23.jar:42.2.23]"
    ... 31 common frames omitted"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79) ~[spring-jdbc
    at java.base/java.net.SocketOutputStream.socketWrite0(Native Method) ~[na:na]"
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79) ~[spring-jdbc
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779) ~[spring-aop-5.3.10.jar:5.3.10]"
    ... 39 common frames omitted"
    at java.base/sun.security.ssl.SSLSocketOutputRecord.deliver(Unknown Source) ~[na:na]"
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]"
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.10.
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[workspace/:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.10.jar:5.3.10]"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.run(SpringBootRetryDbApplication.java:21) ~[classes/:na]"
    at java.base/java.net.SocketOutputStream.write(Unknown Source) ~[na:na]"
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:775) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[workspace/:na]"
    at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at com.github.miyohide.springbootretrydb.MyService$$FastClassBySpringCGLIB$$4d334926.invoke(<generated>) ~[classes/:na]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:349) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:1469) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.core.PGStream.flush(PGStream.java:665) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:88) ~[workspace/:na]"
    at com.github.miyohide.springbootretrydb.MyService$$EnhancerBySpringCGLIB$$df81f8ea.insert(<generated>) ~[classes/:na]"
org.springframework.dao.DataAccessResourceFailureException: PreparedStatementCallback; SQL [INSERT INTO customers(first_name, last_name) VALUES (?, 
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.10.jar:5.3.10]"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.main(SpringBootRetryDbApplication.java:13) ~[classes/:na]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:320) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1025) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:107) ~[spring-jdbc-5.3.10.jar:5
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar:na]"
    at com.github.miyohide.springbootretrydb.MyService.insert(MyService.java:30) ~[classes/:na]"
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481) ~[postgresql-42.2.23.jar:42.2.23]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.10.jar:5.3.10]"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.10.jar:5.3.10]"
Caused by: java.net.SocketException: Connection reset by peer (Write failed)"
2021-10-24 05:03:36.548 ERROR 20 --- [           main] o.s.t.i.TransactionInterceptor           : Application exception overridden by rollback excep
    at java.base/java.net.SocketOutputStream.socketWrite(Unknown Source) ~[na:na]"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]"
    at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1541) ~[spring-jdbc-5.3.10.jar:5.3.10]"
Caused by: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend."
Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled."
2021-10-24 05:03:36.581  INFO 20 --- [           main] ConditionEvaluationReportLoggingListener : "
    at com.sun.proxy.$Proxy53.rollback(Unknown Source) ~[na:na]"
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:88) ~[workspace/:na]"
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.10.jar:5.3.10]"
2021-10-24 05:03:36.758 ERROR 20 --- [           main] o.s.boot.SpringApplication               : Application run failed"
    at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:396) ~[HikariCP-4.0.3.jar:na]"
java.lang.IllegalStateException: Failed to execute CommandLineRunner"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[workspace/:na]"
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[workspace/:na]"
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:835) ~[sprin
    at com.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java) ~[HikariCP-4.0.3.jar:na]"
    at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.10.jar:5.3.10]"
    at com.github.miyohide.springbootretrydb.MyService$$EnhancerBySpringCGLIB$$df81f8ea.insert(<generated>) ~[classes/:na]"
Caused by: org.springframework.transaction.TransactionSystemException: JDBC rollback failed; nested exception is java.sql.SQLException: Connection i
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.5.jar:2.5.5]"
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]"
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:775) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:794) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:392) ~[spring-tx-5.3
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    ... 24 common frames omitted"
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:348) ~[spring-jdbc-5.3.10.jar:5.3
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:809) ~[spring-tx-5.
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na]"
    at org.springframework.jdbc.support.JdbcTransactionManager.translateException(JdbcTransactionManager.java:188) ~[spring-jdbc-5.3.10.jar:5.3.10]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:345) ~[spring-boot-2.5.5.jar:2.5.5]"
Caused by: java.sql.SQLException: Connection is closed"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.main(SpringBootRetryDbApplication.java:13) ~[classes/:na]"
    ... 13 common frames omitted"
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.5.jar:2.5.5]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.10.jar:5.3.10]"
    at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:672) ~[spri
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.translateException(DataSourceTransactionManager.java:435) ~[spring-jdbc-5.3.10
    at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:515) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:351) ~[spring-jdbc-5.3.10.jar:5.3
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[workspace/:na]"
    at com.github.miyohide.springbootretrydb.SpringBootRetryDbApplication.run(SpringBootRetryDbApplication.java:21) ~[classes/:na]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791) ~[spring-boot-2.5.5.jar:2.5.5]"
2021-10-24 05:03:36.767  INFO 20 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated..."
2021-10-24 05:03:37.197  INFO 20 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed."

この対応についてはもう少し検討してみたいと思います。~~とりあえず今日はここまで。~~ 続きを書きました。

miyohide.hatenablog.com

miyohide's blog

Azure Database for PostgreSQLの一時的な接続エラーに対処する