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

はじめに

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

以下の記事で簡単なリトライ処理については確認しましたが、トランザクションをかけた場合はうまくリトライできませんでした。

miyohide.hatenablog.com

今回はその対応をします。

実装

@Transactionalをつけているメソッドに対して@Retryableをつけてあげます。以下のような感じです。

    @Retryable(maxAttempts = 12, backoff = @Backoff(delay = 5_000, maxDelay = 10_000))
    @Transactional
    public void insert() {
        log.info("Start insert method...");
        // 省略
        log.info("End insert method...");
    }

maxAttemptsやdelayなどの値は適宜調整してください。調整のためのヒントとしては、マイクロソフトが公開している上記のドキュメントがあります。マイクロソフトのドキュメントには以下のように書かれています。

初回再試行の前には 5 秒間待機します。

以降再試行するたびに、60 秒を上限として、待ち時間を指数関数的に増やします。

操作が失敗したとアプリケーションで見なされる最大再試行回数を設定します。

これを元に5秒x12回のリトライをするようにしています。

確認

動作を確認してみます。

（省略）
2021-10-26 11:46:08.567  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [38], first_name = [Josh00038], last_name = [hogehoge00038]"
2021-10-26 11:46:09.571  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [39], first_name = [Josh00039], last_name = [hogehoge00039]"
    at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(Unknown Source) ~[na:na]"
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:93) ~[spring-retry-1.3.1.jar:na]"
    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.12.jar:5.3.12]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:119) ~[spring-retry-1.3.1.jar:na]"
    at com.github.miyohide.retry.RetryApplication.run(RetryApplication.java:22) ~[classes/:na]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:349) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791) ~[spring-boot-2.5.6.jar:2.5.6]"
    at com.github.miyohide.retry.MyService$$EnhancerBySpringCGLIB$$30791361.insert(<generated>) ~[classes/:na]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1025) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:329) ~[spring-retry-1.3.1.jar:na]"
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:163) ~[spring-retry-1.3.1.jar:na]"
org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend."
    at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:1482) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:775) ~[spring-boot-2.5.6.jar:2.5.6]"
2021-10-26 11:46:09.592  WARN 18 --- [           main] com.zaxxer.hikari.pool.ProxyConnection   : HikariPool-1 - Connection org.postgresql.jdbc.PgConnection@575b5f7d marked as broke
    at java.base/java.io.BufferedOutputStream.flushBuffer(Unknown Source) ~[na:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481) ~[postgresql-42.2.24.jar:42.2.24]"
    at java.base/java.io.BufferedOutputStream.flush(Unknown Source) ~[na:na]"
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) ~[spring-aop-5.3.12.jar:5.3.12]"
    ... 38 common frames omitted"
    at java.base/java.net.SocketOutputStream.socketWrite0(Native Method) ~[na:na]"
Caused by: java.net.SocketException: Connection reset by peer (Write failed)"
    at com.github.miyohide.retry.MyService$$FastClassBySpringCGLIB$$a8112c7.invoke(<generated>) ~[classes/:na]"
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:209) ~[spring-retry-1.3.1.jar:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]"
    at com.github.miyohide.retry.RetryApplication.main(RetryApplication.java:14) ~[classes/:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.6.jar:2.5.6]"
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3.12.jar:5.3.12]"
    at java.base/java.net.SocketOutputStream.socketWrite(Unknown Source) ~[na:na]"
    at com.github.miyohide.retry.MyService.insert(MyService.java:33) ~[classes/:na]"
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]"
    at org.postgresql.core.PGStream.flush(PGStream.java:665) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.12.jar:5.3.12]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:320) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:345) ~[spring-boot-2.5.6.jar:2.5.6]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at java.base/sun.security.ssl.SSLSocketOutputRecord.deliver(Unknown Source) ~[na:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.6.jar:2.5.6]"
    at java.base/java.net.SocketOutputStream.write(Unknown Source) ~[na:na]"
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.12.jar:5.3.12]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.12.jar:5.3.12]"
2021-10-26 11:46:10.168  INFO 18 --- [           main] c.g.m.retry.config.RetryableDataSource   : getting connection ..."
2021-10-26 11:46:10.168 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0"
2021-10-26 11:46:10.170  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@1b134
2021-10-26 11:46:10.171  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@7bd96
2021-10-26 11:46:10.172  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@64dae
2021-10-26 11:46:10.178  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@1e4c6
2021-10-26 11:46:10.177  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@1fedf
2021-10-26 11:46:10.179  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@2ee48
2021-10-26 11:46:10.180  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@1d901
2021-10-26 11:46:10.181  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@6d08b
2021-10-26 11:46:10.181  WARN 18 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@1015a
2021-10-26 11:46:49.206  INFO 18 --- [           main] c.g.m.retry.config.RetryableDataSource   : getting connection ..."
2021-10-26 11:46:49.206 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1"
2021-10-26 11:46:49.206 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1"
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]"
    at com.github.miyohide.retry.MyService$$EnhancerBySpringCGLIB$$30791361.insert(<generated>) ~[classes/:na]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:107) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1541) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at java.base/java.io.BufferedOutputStream.flush(Unknown Source) ~[na:na]"
    ... 30 common frames omitted"
    at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:1482) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.6.jar:2.5.6]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.postgresql.core.PGStream.flush(PGStream.java:665) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:349) ~[postgresql-42.2.24.jar:42.2.24]"
    ... 38 common frames omitted"
    at java.base/java.net.SocketOutputStream.socketWrite0(Native Method) ~[na:na]"
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:119) ~[spring-retry-1.3.1.jar:na]"
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at java.base/java.net.SocketOutputStream.socketWrite(Unknown Source) ~[na:na]"
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:329) ~[spring-retry-1.3.1.jar:na]"
Caused by: java.net.SocketException: Connection reset by peer (Write failed)"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1025) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[postgresql-42.2.24.jar:42.2.24]"
    at com.github.miyohide.retry.RetryApplication.main(RetryApplication.java:14) ~[classes/:na]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:345) ~[spring-boot-2.5.6.jar:2.5.6]"
    at java.base/sun.security.ssl.SSLSocketOutputRecord.deliver(Unknown Source) ~[na:na]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:320) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.12.jar:5.3.12]"
    at java.base/java.io.BufferedOutputStream.flushBuffer(Unknown Source) ~[na:na]"
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:70) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79) ~[spring-jdbc-5.3.12.jar:5.3.12]"
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.6.jar:2.5.6]"
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:209) ~[spring-retry-1.3.1.jar:na]"
    at com.github.miyohide.retry.RetryApplication.run(RetryApplication.java:22) ~[classes/:na]"
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar:na]"
    at java.base/java.net.SocketOutputStream.write(Unknown Source) ~[na:na]"
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401) ~[postgresql-42.2.24.jar:42.2.24]"
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481) ~[postgresql-42.2.24.jar:42.2.24]"
Caused by: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend."
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:93) ~[spring-retry-1.3.1.jar:na]"
    at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(Unknown Source) ~[na:na]"
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791) ~[spring-boot-2.5.6.jar:2.5.6]"
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:163) ~[spring-retry-1.3.1.jar:na]"
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.12.jar:5.3.12]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]"
2021-10-26 11:46:51.627 ERROR 18 --- [           main] o.s.t.i.TransactionInterceptor           : Application exception overridden by rollback exception"
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.12.jar:5.3.12]"
    at com.github.miyohide.retry.MyService$$FastClassBySpringCGLIB$$a8112c7.invoke(<generated>) ~[classes/:na]"
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3.12.jar:5.3.12]"
org.springframework.dao.DataAccessResourceFailureException: PreparedStatementCallback; SQL [INSERT INTO customers(first_name, last_name) VALUES (?, ?)]; An I/O error occurred while 
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]"
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:775) ~[spring-boot-2.5.6.jar:2.5.6]"
    at com.github.miyohide.retry.MyService.insert(MyService.java:33) ~[classes/:na]"
2021-10-26 11:46:59.489 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0"
2021-10-26 11:46:59.490  INFO 18 --- [           main] c.g.m.retry.config.RetryableDataSource   : getting connection ..."
2021-10-26 11:46:59.488 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1"
2021-10-26 11:46:59.488 DEBUG 18 --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1"
2021-10-26 11:46:59.498  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [0], first_name = [Josh00000], last_name = [hogehoge00000]"
2021-10-26 11:46:59.497  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Start insert method..."
2021-10-26 11:47:01.033  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [1], first_name = [Josh00001], last_name = [hogehoge00001]"
2021-10-26 11:47:02.038  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [2], first_name = [Josh00002], last_name = [hogehoge00002]"
2021-10-26 11:47:03.042  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [3], first_name = [Josh00003], last_name = [hogehoge00003]"
2021-10-26 11:47:04.048  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [4], first_name = [Josh00004], last_name = [hogehoge00004]"
2021-10-26 11:47:05.052  INFO 18 --- [           main] com.github.miyohide.retry.MyService      : Insert record. i = [5], first_name = [Josh00005], last_name = [hogehoge00005]"

org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.が発生したり、java.net.SocketException: Connection reset by peer (Write failed)が発生したりしていますが、2021-10-26 11:46:59.498時点で再度0からInsert処理が始まりました。無事リトライ処理が行われているようです。

無事、一時的な接続エラーに対処することができました。

実装ソース

ソースは以下に置いてあります。

github.com

non_retryフォルダにあるものはリトライ処理を実装していないもの、retryフォルダにあるのがリトライ処理を実装したものになります。