Amazon Auroraのフェイルオーバー時間を短くしたい
こんにちは、のんピ(@non____97)です。
皆さんはAmazon Auroraのフェイルオーバー時間を短くしたいなと思ったことはありますか? 私はあります。
Auroraのフェイルオーバー時間は60秒未満と言われています。しかし、「60秒では長すぎる。せめて10秒程度でフェイルオーバーは完了させたい。」といったこともあると思います。
フェイルオーバー時間を短くする方法はクライアント側でMariaDB Connector/JやPostgreSQL JDBC Driverなどのドライバーを使用したり、RDS ProxyやProxySQLなどプロキシを挟むパターンがあります。
他にもフェイルオーバー時間を短くする方法が何かないかと探しているとAWS公式ドキュメントにフェイルオーバー時間を短くするための方法がまとまっていました。
その中にAWS JDBC Driverなるドライバーが紹介されていました。
DevelopersIOではこちらのドライバーを使ってフェイルオーバー時間の短縮する方法を説明している記事がなかったので、検証をしてみます。
いきなりまとめ
- AWS JDBC Driver(
aws-advanced-jdbc-wrapper
)とはAWS謹製のJDBC Wrapper - 機能ごとに様々なプラグインが存在 (以下例)
- Failover Connection Plugin : フェイルオーバーの高速化
- AWS Secrets Manager Connection Plugin : Secrets Managerから認証情報を取得
- Read-Write Splitting Plugin : 読み取り/書き込みに応じてWriter/Readerインスタンスを切り替え
- Failover Connection Pluginを使う場合、例外が発生した際にConnectionオブジェクトを破棄しないようにする必要がある
- フェイルオーバー成功時の例外
FailoverSuccessSQLException
の場合は、Connectionオブジェクトを再利用してリトライしてあげる
- フェイルオーバー成功時の例外
strict-writer
の場合、DBインスタンスの数が3台以上だと15秒未満でフェイルオーバーできる- 検証した限りDBインスタンス4台で2-5秒ほどでフェイルオーバー
reader-or-writer
の場合、DBインスタンスの数が2台でも0.4秒ほどでフェイルオーバーできる- 以下に当てはまる場合は積極的に活用していきたい
- RDS ProxyやDBのプロキシのミドルウェア用のEC2インスタンス料金を抑えたい
- アプリケーションの改修が可能
- DBクラスターを3台以上で構成
AWS JDBC Driverとは
AWS JDBC Driver(aws-advanced-jdbc-wrapper
)とはAWS謹製のJDBC Wrapperです。
AWS JDBC Driverにはフェイルオーバーを高速化するFailover Connection Plugin以外にもSecrets Managerから認証情報を取得するAWS Secrets Manager Connection Plugin、読み取り/書き込みに応じてWriter/Readerインスタンスを切り替えるRead-Write Splitting Pluginなどもあります。
Plugin name | Plugin Code | Database Compatibility | Description |
---|---|---|---|
Failover Connection Plugin | failover | Aurora | Enables the failover functionality supported by Amazon Aurora clusters. Prevents opening a wrong connection to an old writer node dues to stale DNS after failover event. This plugin is enabled by default. |
Host Monitoring Connection Plugin | efm | Aurora | Enables enhanced host connection failure monitoring, allowing faster failure detection rates. This plugin is enabled by default. |
Aurora Host List Connection Plugin | auroraHostList | Aurora | Retrieves Amazon Aurora clusters information.
⚠️Note: this plugin does not need to be explicitly loaded if the failover connection plugin is loaded. |
Data Cache Connection Plugin | dataCache | Any database | Caches results from SQL queries matching the regular expression specified in the dataCacheTriggerCondition configuration parameter. |
Execution Time Connection Plugin | executionTime | Any database | Logs the time taken to execute any JDBC method. |
Log Query Connection Plugin | logQuery | Any database | Tracks and logs the SQL statements to be executed. Sometimes SQL statements are not passed directly to the JDBC method as a parameter, such as executeBatch(). Users can set enhancedLogQueryEnabled to true, allowing the JDBC Wrapper to obtain SQL statements via Java Reflection.
⚠️Note: Enabling Java Reflection may cause a performance degradation. |
IAM Authentication Connection Plugin | iam | Any database | Enables users to connect to their Amazon Aurora clusters using AWS Identity and Access Management (IAM). |
AWS Secrets Manager Connection Plugin | awsSecretsManager | Any database | Enables fetching database credentials from the AWS Secrets Manager service. |
Aurora Stale DNS Plugin | auroraStaleDns | Aurora | Prevents incorrectly opening a new connection to an old writer node when DNS records have not yet updated after a recent failover event.
⚠️Note: Contrary to failover plugin, auroraStaleDns plugin doesn't implement failover support itself. It helps to eliminate opening wrong connections to an old writer node after cluster failover is completed. ⚠️Note: This logic is already included in failover plugin so you can omit using both plugins at the same time. |
Aurora Connection Tracker Plugin | auroraConnectionTracker | Aurora | Tracks all the opened connections. In the event of a cluster failover, the plugin will close all the impacted connections to the node. This plugin is enabled by default. |
Driver Metadata Connection Plugin | driverMetaData | Any database | Allows user application to override the return value of DatabaseMetaData#getDriverName |
Read Write Splitting Plugin | readWriteSplitting | Aurora | Enables read write splitting functionality where users can switch between database reader and writer instances. |
AWS JDBC DriverでFailover Connection Pluginを使用している環境でフェイルオーバーが発生した場合の内部挙動は以下の通りです。
Failover Connection Pluginを使用するとDBへの物理接続と論理接続が分離されます。そして物理接続先のDBインスタンスに異常が見られる場合以下のステップで物理接続の切り替えが行われます。
- 内部のトポロジキャッシュからアクティブなAuroraレプリカに接続
- 接続したAuroraレプリカからWriterの情報を取得
- Writerの特定が完了したら、物理接続先を切り替え
Failover Connection Pluginの挙動はエムスリーさんのテックブログでも解説されており、非常に参考になります。
検証環境の準備
検証環境は以下の通りです。
EC2インスタンスでSpring Bootを起動させ、Aurora DBクラスターに接続させます。
各DBインスタンスのIPアドレスは以下の通りです。
$ dig db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com +short
10.1.1.93
$ dig db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com +short
10.1.1.116
各種AWSリソースはAWS CDKでデプロイします。デプロイ時に使用したリポジトリは本記事の終わりに記載しています。
EC2インスタンス起動後、Spring Bootのアプリケーションを作成します。
まずJavaのインストールをします。
$ sudo dnf install java
Last metadata expiration check: 0:02:23 ago on Wed Jun 21 05:06:39 2023.
Dependencies resolved.
========================================================================================================================
Package Architecture Version Repository Size
========================================================================================================================
Installing:
java-17-amazon-corretto x86_64 1:17.0.7+7-1.amzn2023.1 amazonlinux 188 k
Installing dependencies:
alsa-lib x86_64 1.2.7.2-1.amzn2023.0.2 amazonlinux 504 k
cairo x86_64 1.17.4-3.amzn2023.0.2 amazonlinux 674 k
dejavu-sans-fonts noarch 2.37-16.amzn2023.0.2 amazonlinux 1.3 M
dejavu-sans-mono-fonts noarch 2.37-16.amzn2023.0.2 amazonlinux 467 k
dejavu-serif-fonts noarch 2.37-16.amzn2023.0.2 amazonlinux 1.0 M
fontconfig x86_64 2.13.94-2.amzn2023.0.2 amazonlinux 273 k
fonts-filesystem noarch 1:2.0.5-5.amzn2023.0.2 amazonlinux 8.7 k
freetype x86_64 2.13.0-2.amzn2023.0.1 amazonlinux 422 k
giflib x86_64 5.2.1-9.amzn2023 amazonlinux 49 k
google-noto-fonts-common noarch 20201206-2.amzn2023.0.2 amazonlinux 15 k
google-noto-sans-vf-fonts noarch 20201206-2.amzn2023.0.2 amazonlinux 492 k
graphite2 x86_64 1.3.14-7.amzn2023.0.2 amazonlinux 97 k
harfbuzz x86_64 7.0.0-2.amzn2023.0.1 amazonlinux 868 k
java-17-amazon-corretto-headless x86_64 1:17.0.7+7-1.amzn2023.1 amazonlinux 91 M
javapackages-filesystem noarch 6.0.0-7.amzn2023.0.5 amazonlinux 13 k
langpacks-core-font-en noarch 3.0-21.amzn2023.0.4 amazonlinux 10 k
libICE x86_64 1.0.10-6.amzn2023.0.2 amazonlinux 71 k
libSM x86_64 1.2.3-8.amzn2023.0.2 amazonlinux 42 k
libX11 x86_64 1.7.2-3.amzn2023.0.2 amazonlinux 657 k
libX11-common noarch 1.7.2-3.amzn2023.0.2 amazonlinux 152 k
libXau x86_64 1.0.9-6.amzn2023.0.2 amazonlinux 31 k
libXext x86_64 1.3.4-6.amzn2023.0.2 amazonlinux 41 k
libXi x86_64 1.7.10-6.amzn2023.0.2 amazonlinux 40 k
libXinerama x86_64 1.1.4-8.amzn2023.0.2 amazonlinux 15 k
libXrandr x86_64 1.5.2-6.amzn2023.0.2 amazonlinux 28 k
libXrender x86_64 0.9.10-14.amzn2023.0.2 amazonlinux 28 k
libXt x86_64 1.2.0-4.amzn2023.0.2 amazonlinux 181 k
libXtst x86_64 1.2.3-14.amzn2023.0.2 amazonlinux 21 k
libbrotli x86_64 1.0.9-4.amzn2023.0.2 amazonlinux 315 k
libjpeg-turbo x86_64 2.1.4-2.amzn2023.0.2 amazonlinux 190 k
libpng x86_64 2:1.6.37-10.amzn2023.0.2 amazonlinux 128 k
libxcb x86_64 1.13.1-7.amzn2023.0.2 amazonlinux 230 k
pixman x86_64 0.40.0-3.amzn2023.0.3 amazonlinux 295 k
xml-common noarch 0.6.3-56.amzn2023.0.2 amazonlinux 32 k
Transaction Summary
========================================================================================================================
Install 35 Packages
Total download size: 100 M
Installed size: 261 M
Is this ok [y/N]: y
Downloading Packages:
(1/35): libXrender-0.9.10-14.amzn2023.0.2.x86_64.rpm 239 kB/s | 28 kB 00:00
(2/35): harfbuzz-7.0.0-2.amzn2023.0.1.x86_64.rpm 6.3 MB/s | 868 kB 00:00
.
.
(中略)
.
.
Verifying : langpacks-core-font-en-3.0-21.amzn2023.0.4.noarch 35/35
Installed:
alsa-lib-1.2.7.2-1.amzn2023.0.2.x86_64
cairo-1.17.4-3.amzn2023.0.2.x86_64
dejavu-sans-fonts-2.37-16.amzn2023.0.2.noarch
.
.
(中略)
.
.
libxcb-1.13.1-7.amzn2023.0.2.x86_64
pixman-0.40.0-3.amzn2023.0.3.x86_64
xml-common-0.6.3-56.amzn2023.0.2.noarch
Complete!
$ java --version
openjdk 17.0.7 2023-04-18 LTS
OpenJDK Runtime Environment Corretto-17.0.7.7.1 (build 17.0.7+7-LTS)
OpenJDK 64-Bit Server VM Corretto-17.0.7.7.1 (build 17.0.7+7-LTS, mixed mode, sharing)
続いて、Spring BootのビルドのためにMavenのインストールをします。
$ sudo dnf install maven
Last metadata expiration check: 0:19:31 ago on Wed Jun 21 05:06:39 2023.
Dependencies resolved.
========================================================================================================================
Package Architecture Version Repository Size
========================================================================================================================
Installing:
maven noarch 1:3.8.4-3.amzn2023.0.4 amazonlinux 18 k
Installing dependencies:
apache-commons-cli noarch 1.5.0-3.amzn2023.0.3 amazonlinux 76 k
apache-commons-codec noarch 1.15-6.amzn2023.0.3 amazonlinux 303 k
apache-commons-io noarch 1:2.8.0-7.amzn2023.0.4 amazonlinux 284 k
apache-commons-lang3 noarch 3.12.0-7.amzn2023.0.3 amazonlinux 559 k
atinject noarch 1.0.5-3.amzn2023.0.3 amazonlinux 23 k
cdi-api noarch 2.0.2-6.amzn2023.0.3 amazonlinux 54 k
google-guice noarch 4.2.3-8.amzn2023.0.6 amazonlinux 473 k
guava noarch 31.0.1-3.amzn2023.0.4 amazonlinux 2.5 M
httpcomponents-client noarch 4.5.13-4.amzn2023.0.4 amazonlinux 657 k
httpcomponents-core noarch 4.4.13-6.amzn2023.0.3 amazonlinux 632 k
jakarta-annotations noarch 1.3.5-13.amzn2023.0.3 amazonlinux 46 k
jansi x86_64 2.4.0-3.amzn2023.0.3 amazonlinux 113 k
java-17-amazon-corretto-devel x86_64 1:17.0.7+7-1.amzn2023.1 amazonlinux 149 k
jcl-over-slf4j noarch 1.7.32-3.amzn2023.0.4 amazonlinux 25 k
jsoup noarch 1.13.1-9.amzn2023.0.4 amazonlinux 377 k
jsr-305 noarch 3.0.2-5.amzn2023.0.4 amazonlinux 32 k
maven-amazon-corretto17 noarch 1:3.8.4-3.amzn2023.0.4 amazonlinux 9.7 k
maven-lib noarch 1:3.8.4-3.amzn2023.0.4 amazonlinux 1.5 M
maven-resolver noarch 1:1.7.3-3.amzn2023.0.4 amazonlinux 557 k
maven-shared-utils noarch 3.3.4-4.amzn2023.0.3 amazonlinux 152 k
maven-wagon noarch 3.4.2-6.amzn2023.0.4 amazonlinux 113 k
plexus-cipher noarch 1.8-3.amzn2023.0.3 amazonlinux 27 k
plexus-classworlds noarch 2.6.0-10.amzn2023.0.4 amazonlinux 61 k
plexus-containers-component-annotations noarch 2.1.0-9.amzn2023.0.4 amazonlinux 19 k
plexus-interpolation noarch 1.26-10.amzn2023.0.4 amazonlinux 80 k
plexus-sec-dispatcher noarch 2.0-3.amzn2023.0.3 amazonlinux 34 k
plexus-utils noarch 3.3.0-9.amzn2023.0.4 amazonlinux 254 k
publicsuffix-list noarch 20221208-60.amzn2023 amazonlinux 87 k
sisu noarch 1:0.3.4-9.amzn2023.0.4 amazonlinux 510 k
slf4j noarch 1.7.32-3.amzn2023.0.4 amazonlinux 70 k
Transaction Summary
========================================================================================================================
Install 31 Packages
Total download size: 9.6 M
Installed size: 13 M
Is this ok [y/N]: y
Downloading Packages:
(1/31): java-17-amazon-corretto-devel-17.0.7+7-1.amzn2023.1.x86_64.rpm 1.2 MB/s | 149 kB 00:00
(2/31): jsoup-1.13.1-9.amzn2023.0.4.noarch.rpm 2.7 MB/s | 377 kB 00:00
.
.
(中略)
.
.
Verifying : httpcomponents-core-4.4.13-6.amzn2023.0.3.noarch 30/31
Verifying : publicsuffix-list-20221208-60.amzn2023.noarch 31/31
Installed:
apache-commons-cli-1.5.0-3.amzn2023.0.3.noarch
apache-commons-codec-1.15-6.amzn2023.0.3.noarch
apache-commons-io-1:2.8.0-7.amzn2023.0.4.noarch
.
.
(中略)
.
.
publicsuffix-list-20221208-60.amzn2023.noarch
sisu-1:0.3.4-9.amzn2023.0.4.noarch
slf4j-1.7.32-3.amzn2023.0.4.noarch
Complete!
Spring Boot CLIをインストールします。
# Spring Boot CLIのダウンロード
$ wget https://repo.maven.apache.org/maven2/org/springframework/boot/spring-boot-cli/3.1.0/spring-boot-cli-3.1.0-bin.tar.gz
--2023-06-21 05:42:39-- https://repo.maven.apache.org/maven2/org/springframework/boot/spring-boot-cli/3.1.0/spring-boot-cli-3.1.0-bin.tar.gz
Resolving repo.maven.apache.org (repo.maven.apache.org)... 146.75.32.215, 2a04:4e42:78::215
Connecting to repo.maven.apache.org (repo.maven.apache.org)|146.75.32.215|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 5141514 (4.9M) [application/x-gzip]
Saving to: ‘spring-boot-cli-3.1.0-bin.tar.gz’
spring-boot-cli-3.1.0-bin.tar 100%[=================================================>] 4.90M --.-KB/s in 0.05s
2023-06-21 05:42:39 (104 MB/s) - ‘spring-boot-cli-3.1.0-bin.tar.gz’ saved [5141514/5141514]
# ダウンロードしたzipファイルを展開
$ tar zxvf spring-boot-cli-3.1.0-bin.tar.gz
spring-3.1.0/
spring-3.1.0/lib/
spring-3.1.0/lib/spring-boot-cli-3.1.0.jar
spring-3.1.0/shell-completion/
spring-3.1.0/shell-completion/bash/
spring-3.1.0/shell-completion/bash/spring
spring-3.1.0/shell-completion/zsh/
spring-3.1.0/shell-completion/zsh/_spring
spring-3.1.0/legal/
spring-3.1.0/legal/open_source_licenses.txt
spring-3.1.0/bin/
spring-3.1.0/bin/spring.bat
spring-3.1.0/LICENCE.txt
spring-3.1.0/INSTALL.txt
spring-3.1.0/bin/spring
# 展開されたファイルたちの確認
$ ls -lR spring-3.1.0/
spring-3.1.0/:
total 8
-rw-r--r--. 1 ec2-user ec2-user 1425 May 18 22:18 INSTALL.txt
-rw-r--r--. 1 ec2-user ec2-user 582 May 18 22:18 LICENCE.txt
drwxr-xr-x. 2 ec2-user ec2-user 38 Jun 21 05:43 bin
drwxr-xr-x. 2 ec2-user ec2-user 38 May 18 22:18 legal
drwxr-xr-x. 2 ec2-user ec2-user 39 May 18 22:21 lib
drwxr-xr-x. 4 ec2-user ec2-user 29 May 18 22:18 shell-completion
spring-3.1.0/bin:
total 8
-rwxr-xr-x. 1 ec2-user ec2-user 3367 May 18 22:18 spring
-rw-r--r--. 1 ec2-user ec2-user 1948 May 18 22:18 spring.bat
spring-3.1.0/legal:
total 12
-rw-r--r--. 1 ec2-user ec2-user 11103 May 18 22:18 open_source_licenses.txt
spring-3.1.0/lib:
total 5812
-rw-r--r--. 1 ec2-user ec2-user 5949256 May 18 22:21 spring-boot-cli-3.1.0.jar
spring-3.1.0/shell-completion:
total 0
drwxr-xr-x. 2 ec2-user ec2-user 20 May 18 22:18 bash
drwxr-xr-x. 2 ec2-user ec2-user 21 May 18 22:18 zsh
spring-3.1.0/shell-completion/bash:
total 4
-rw-r--r--. 1 ec2-user ec2-user 494 May 18 22:18 spring
spring-3.1.0/shell-completion/zsh:
total 4
-rw-r--r--. 1 ec2-user ec2-user 454 May 18 22:18 _spring
# spring コマンドが叩けられるように環境変数を設定
$ sudo vim /etc/profile
$ tail /etc/profile
if [ -f /etc/bashrc ] ; then
# Bash login shells run only /etc/profile
# Bash non-login shells run only /etc/bashrc
# Check for double sourcing is done in /etc/bashrc.
. /etc/bashrc
fi
fi
export SPRING_HOME=/home/ec2-user/spring-3.1.0/
export PATH=$SPRING_HOME/bin:$PATH
# 環境変数の再読み込み
$ source /etc/profile
# spring コマンドが叩けることを確認
$ which spring
~/spring-3.1.0/bin/spring
Spring Boot CLIから、Spring Initializr でプロジェクトの作成をします。
$ spring init \
-g=net.non-97.aurora \
-a=jdbc \
-n=jdbc \
-d=web,postgresql \
-j=17 \
-l=java \
--package-name jar \
--build=maven
Using service at https://start.spring.io
Content saved to 'jdbc.zip'
$ unzip jdbc.zip
Archive: jdbc.zip
creating: src/
creating: src/main/
creating: src/main/java/
creating: src/main/java/jar/
inflating: src/main/java/jar/JdbcApplication.java
creating: src/main/resources/
inflating: src/main/resources/application.properties
creating: src/test/
creating: src/test/java/
creating: src/test/java/jar/
inflating: src/test/java/jar/JdbcApplicationTests.java
inflating: HELP.md
inflating: .gitignore
inflating: mvnw
inflating: pom.xml
inflating: mvnw.cmd
creating: .mvn/
creating: .mvn/wrapper/
inflating: .mvn/wrapper/maven-wrapper.properties
inflating: .mvn/wrapper/maven-wrapper.jar
# 展開された pom.xml の確認
$ cat pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.1.0</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>net.non-97.aurora</groupId>
<artifactId>jdbc</artifactId>
<version>0.0.1-SNAPSHOT</version>
<name>jdbc</name>
<description>Demo project for Spring Boot</description>
<properties>
<java.version>17</java.version>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.postgresql</groupId>
<artifactId>postgresql</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-test</artifactId>
<scope>test</scope>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
動作確認のために/hello
にアクセスするとHello World!
を返すようなJavaアプリケーションに修正してみます。
$ vi src/main/java/jar/JdbcApplication.java
$ cat src/main/java/jar/JdbcApplication.java
package jar;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
@SpringBootApplication
@RestController
public class JdbcApplication {
public static void main(String[] args) {
SpringApplication.run(JdbcApplication.class, args);
}
@GetMapping("/hello")
String Hello(){
return "Hello World!";
}
}
修正後、Spring Bootを起動します。
$ mvn spring-boot:run
.
.
(中略)
.
.
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classes
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 1 source file with javac [debug release 17] to target/classes
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :dependency
[INFO] Compiling 1 source file with javac [debug release 17] to target/test-classes
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.1.0)
2023-06-21T07:23:09.968Z INFO 30857 --- [ main] jar.JdbcApplication : Starting JdbcApplication using Java 17.0.7 with PID 30857 (/home/ec2-user/target/classes started by ec2-user in /home/ec2-user)
2023-06-21T07:23:09.972Z INFO 30857 --- [ main] jar.JdbcApplication : No active profileset, falling back to 1 default profile: "default"
2023-06-21T07:23:10.864Z INFO 30857 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2023-06-21T07:23:10.874Z INFO 30857 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2023-06-21T07:23:10.874Z INFO 30857 --- [ main] o.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/10.1.8]
2023-06-21T07:23:10.983Z INFO 30857 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2023-06-21T07:23:10.985Z INFO 30857 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 937 ms
2023-06-21T07:23:11.271Z INFO 30857 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started onport(s): 8080 (http) with context path ''
2023-06-21T07:23:11.281Z INFO 30857 --- [ main] jar.JdbcApplication : Started JdbcApplication in 1.66 seconds (process running for 2.037)
localhost:8080/hello
にアクセスしてHello World!
が返ってくることを確認します。
$ curl http://localhost:8080/hello
Hello World!
Failover Pluginを使わない場合
それではFailover Pluginを使わない場合の動作確認からしてみます。
せっかくなので、DBに接続する際の認証情報はAWS Secrets Manager Pluginを使って取得してみたいと思います。
pom.xml
を修正してsecretsmanager
とaws-advanced-jdbc-wrapper
を依存関係に設定します。
pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.1.0</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>net.non-97.aurora</groupId>
<artifactId>jdbc</artifactId>
<version>0.0.1-SNAPSHOT</version>
<name>jdbc</name>
<description>Demo project for Spring Boot</description>
<properties>
<java.version>17</java.version>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.postgresql</groupId>
<artifactId>postgresql</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-test</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>software.amazon.jdbc</groupId>
<artifactId>aws-advanced-jdbc-wrapper</artifactId>
<version>2.2.1</version>
</dependency>
<dependency>
<groupId>software.amazon.awssdk</groupId>
<artifactId>secretsmanager</artifactId>
<version>2.20.89</version>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
準備したJavaのアプリケーションは以下の通りです。
./src/main/java/jar/JdbcApplication.java
package jar;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
public class JdbcApplication {
// User configures connection properties here
private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";
public static void main(String[] args) {
final Properties props = new Properties();
props.setProperty("wrapperPlugins", "awsSecretsManager");
props.setProperty("wrapperLoggerLevel", "FINE");
props.setProperty("secretsManagerRegion", "us-east-1");
props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");
try {
Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
while (true) {
DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
String date = dtformat.format(LocalDateTime.now());
System.out.print(date + " : ");
try {
Statement stmt = conn.createStatement();
ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");
if (rs.next()) {
System.out.println(rs.getString(1));
} else {
throw new SQLException("Failed to get IP address");
}
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
try {
Thread.sleep(800);
} catch (Exception e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
}
Spring Bootを起動して、動作中にマネジメントコンソールからAurora DBクラスターをフェイルオーバーさせます。
$ mvn spring-boot:run
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------------< net.non-97.aurora:jdbc >-----------------------
[INFO] Building jdbc 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] >>> spring-boot-maven-plugin:3.1.0:run (default-cli) > test-compile @ jdbc >>>
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classes
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 1 source file with javac [debug release 17] to target/classes
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :dependency
[INFO] Compiling 1 source file with javac [debug release 17] to target/test-classes
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
2023/06/22 07:18:17.570 : 10.1.1.93
2023/06/22 07:18:18.437 : 10.1.1.93
2023/06/22 07:18:19.239 : 10.1.1.93
2023/06/22 07:18:20.041 : 10.1.1.93
2023/06/22 07:18:20.843 : 10.1.1.93
2023/06/22 07:18:21.660 : 10.1.1.93
2023/06/22 07:18:22.461 : 10.1.1.93
2023/06/22 07:18:23.265 : 10.1.1.93
2023/06/22 07:18:24.067 : 10.1.1.93
2023/06/22 07:18:24.869 : 10.1.1.93
2023/06/22 07:18:25.671 : 10.1.1.93
2023/06/22 07:18:26.473 : 10.1.1.93
2023/06/22 07:18:27.275 : 10.1.1.93
2023/06/22 07:18:28.077 : 10.1.1.93
2023/06/22 07:18:28.879 : 10.1.1.93
2023/06/22 07:18:29.682 : 10.1.1.93
2023/06/22 07:18:30.485 : 10.1.1.93
2023/06/22 07:18:31.286 : 10.1.1.93
2023/06/22 07:18:32.088 : 10.1.1.93
2023/06/22 07:18:32.890 : 10.1.1.93
2023/06/22 07:18:33.692 : Error: An I/O error occurred while sending to the backend.
org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:395)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:498)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:415)
at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:335)
at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:321)
at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:297)
at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:246)
at software.amazon.jdbc.wrapper.StatementWrapper.lambda$executeQuery$0(StatementWrapper.java:47)
at software.amazon.jdbc.plugin.DefaultConnectionPlugin.execute(DefaultConnectionPlugin.java:101)
at software.amazon.jdbc.ConnectionPluginManager.lambda$execute$3(ConnectionPluginManager.java:337)
at software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$0(ConnectionPluginManager.java:276)
at software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:258)
at software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:334)
at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:219)
at software.amazon.jdbc.wrapper.StatementWrapper.executeQuery(StatementWrapper.java:41)
at jar.JdbcApplication.main(JdbcApplication.java:37)
Caused by: java.io.EOFException
at org.postgresql.core.PGStream.receiveChar(PGStream.java:467)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2155)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:368)
... 15 more
2023/06/22 07:18:34.505 : Error: This connection has been closed.
org.postgresql.util.PSQLException: This connection has been closed.
at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:993)
at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:1819)
at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:518)
at software.amazon.jdbc.wrapper.ConnectionWrapper.lambda$createStatement$9(ConnectionWrapper.java:281)
at software.amazon.jdbc.plugin.DefaultConnectionPlugin.execute(DefaultConnectionPlugin.java:101)
at software.amazon.jdbc.ConnectionPluginManager.lambda$execute$3(ConnectionPluginManager.java:337)
at software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$0(ConnectionPluginManager.java:276)
at software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:258)
at software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:334)
at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:219)
at software.amazon.jdbc.wrapper.ConnectionWrapper.createStatement(ConnectionWrapper.java:275)
at jar.JdbcApplication.main(JdbcApplication.java:36)
2023/06/22 07:18:35.306 : Error: This connection has been closed.
org.postgresql.util.PSQLException: This connection has been closed.
at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:993)
at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:1819)
at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:518)
at software.amazon.jdbc.wrapper.ConnectionWrapper.lambda$createStatement$9(ConnectionWrapper.java:281)
at software.amazon.jdbc.plugin.DefaultConnectionPlugin.execute(DefaultConnectionPlugin.java:101)
at software.amazon.jdbc.ConnectionPluginManager.lambda$execute$3(ConnectionPluginManager.java:337)
at software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$0(ConnectionPluginManager.java:276)
at software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:258)
at software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:334)
at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:219)
at software.amazon.jdbc.wrapper.ConnectionWrapper.createStatement(ConnectionWrapper.java:275)
at jar.JdbcApplication.main(JdbcApplication.java:36)
.
.
(以下略)
.
.
フェイルオーバーしたと思われるタイミングでDBに接続できなくなりました。
ステートメントの作成はループさせていますが、DBの接続はループさせていないので当然です。
Failover Pluginを使う場合 (DBインスタンス2台)
strict-writer
それではFailover Pluginを使ってみましょう。
Javaのアプリケーションは以下のようにしています。
./src/main/java/jar/JdbcApplication.java
package jar;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import software.amazon.jdbc.plugin.failover.FailoverFailedSQLException;
import software.amazon.jdbc.plugin.failover.FailoverSuccessSQLException;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
public class JdbcApplication {
// User configures connection properties here
private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";
public static void main(String[] args) {
final Properties props = new Properties();
props.setProperty("wrapperPlugins", "failover,awsSecretsManager");
props.setProperty("wrapperLoggerLevel", "FINE");
props.setProperty("secretsManagerRegion", "us-east-1");
props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");
try {
Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
while (true) {
DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
String date = dtformat.format(LocalDateTime.now());
System.out.print(date + " : ");
try {
Statement stmt = conn.createStatement();
ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");
if (rs.next()) {
System.out.println(rs.getString(1));
} else {
throw new SQLException("Failed to get IP address");
}
} catch (FailoverSuccessSQLException e) {
System.out.println("Failover succeeded, retrying query ...");
} catch (FailoverFailedSQLException e) {
System.out.println("Failover failed ...");
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
try {
Thread.sleep(800);
} catch (Exception e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
}
wrapperPlugins
でfailover
をロードするようにしています。そして、フェイルオーバーが成功(FailoverSuccessSQLException
)、失敗(FailoverFailedSQLException
)した場合はメッセージを出力するようにしています。
例外が発生した際にConnectionオブジェクトを破棄しないようにしています。もし例外発生時にConnectionオブジェクトを破棄する場合、物理接続を切り替えたとしても切り替え後の接続後も破棄してしまうためです。
Warnings About Proper Usage of the AWS Advanced JDBC Driver
A common practice when using JDBC drivers is to wrap invocations against a Connection object in a try-catch block, and dispose of the Connection object if an Exception is hit. If this practice is left unaltered, the application will lose the fast-failover functionality offered by the JDBC Driver. When failover occurs, the JDBC Driver internally establishes a ready-to-use connection inside the original Connection object before throwing an exception to the user. If this Connection object is disposed of, the newly established connection will be thrown away. The correct practice is to check the SQL error code of the exception and reuse the Connection object if the error code indicates successful failover. The PostgreSQL Failover Sample Code demonstrates this practice. See the section about Failover Exception Codes for more details.
それでは、実際に試してみましょう。
$ mvn spring-boot:run
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------------< net.non-97.aurora:jdbc >-----------------------
[INFO] Building jdbc 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] >>> spring-boot-maven-plugin:3.1.0:run (default-cli) > test-compile @ jdbc >>>
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classes
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 1 source file with javac [debug release 17] to target/classes
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :dependency
[INFO] Compiling 1 source file with javac [debug release 17] to target/test-classes
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
Jun 22, 2023 7:19:58 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINE: Node is no longer available in the topology: HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-22 07:19:56.938784887]
2023/06/22 07:19:58.718 : 10.1.1.116
2023/06/22 07:19:59.531 : 10.1.1.116
.
.
(中略)
.
.
2023/06/22 07:20:38.860 : 10.1.1.116
2023/06/22 07:20:39.664 : 10.1.1.116
2023/06/22 07:20:40.466 : Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandlercall
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINE, user=postgresAdmin}'
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@714bf77e
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:51 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:51 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE,weight=5, null]
Jun 22, 2023 7:20:51 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/22 07:20:52.076 : 10.1.1.93
2023/06/22 07:20:52.899 : 10.1.1.93
2023/06/22 07:20:53.703 : 10.1.1.93
2023/06/22 07:20:54.505 : 10.1.1.93
2023/06/22 07:20:55.307 : 10.1.1.93
12秒ほどで再接続していますね。DBへの接続はループさせていないため、論理接続は維持しながら物理接続が切り替わっていることが分かります。
続いて、もう少しFailover Pluginの動きを見たいのでログレベルをFINEST
に変更して、再度検証します。
$ mvn spring-boot:run
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------------< net.non-97.aurora:jdbc >-----------------------
[INFO] Building jdbc 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] >>> spring-boot-maven-plugin:3.1.0:run (default-cli) > test-compile @ jdbc >>>
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classesb-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.targetdriverdialect.TargetDriverDialectManager logDialect
FINEST: Target driver dialect set to: 'pgjdbc', software.amazon.jdbc.targetdriverdialect.PgTargetDriverDialect@136432db.
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin initHostProvider
FINER: failoverMode=STRICT_WRITER
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100,2023-06-22 07:24:21.390787883]
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.PluginServiceImpl getCurrentHostSpec
FINEST: Set current host to HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-22 07:24:21.390787883]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Cluster endpoint resolves to 10.1.1.116.
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINE: Node is no longer available in the topology: HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-22 07:24:21.390787883]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host: HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host address: 10.1.1.116
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
2023/06/22 07:24:22.613 : Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2023/06/22 07:24:23.424 : Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
.
.
(中略)
.
.
2023/06/22 07:25:14.893 : Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2030, 2023-06-22 07:24:51.0]
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=18, null]
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandlercall
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@7f4feaaf
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:16 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:18 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:20 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=5, null]
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:22 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:23 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:25:23 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2256, 2023-06-22 07:25:24.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE, weight=2256,2023-06-22 07:25:24.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINEST: Current reader connection is actually a new writer connection.
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE,weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE, weight=2256,2023-06-22 07:25:24.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_UP, NODE_CHANGED]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.PluginServiceImpl setAvailability
FINEST: There are no changes in the hosts availability.
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandlercall
FINER: [TaskA] Finished
2023/06/22 07:25:26.209 : Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:27.021 : Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:27.824 : Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:28.626 : Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
.
.
(中略)
.
.
2023/06/22 07:25:55.915 : Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:56.719 : Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:57.521 : Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:58.323 : Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:59.125 : Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
12秒でフェイルオーバーしました。
ログの内容からフェイルオーバー時に以下の処理を行っていることが分かります。
- ノードの状態が変化したことを検知
- 内部トポロジの状態を更新
- Writerへの再接続(Task A)
- 新しいWriterへの接続(Task B)
- 内部トポロジからAuroraレプリカへの接続
- 内部トポロジの状態を更新
- 接続完了後、現在接続しているAuroraレプリカが新しいWriterであることを確定
- 新しいWriterの接続が完了したタイミングで、フェイルオーバー成功と判定
その後、5回ほど再度フェイルオーバー時のダウンタイムを計測しましたが、いずれも10-13秒でした。
高速というほど高速ではありませんが、DNSを使ってフェイルオーバーした際に発生するIPアドレスのフラつきは発生せずに安定しています。
reader-or-writer
Failover Pluginのプロパティを眺めているとfailoverMode
に以下説明がありました。
Defines a mode for failover process. Failover process may prioritize nodes with different roles and connect to them. Possible values:
- strict-writer - Failover process follows writer node and connects to a new writer when it changes.
- reader-or-writer - During failover, the driver tries to connect to any available/accessible reader node. If no reader is available, the driver will connect to a writer node. This logic mimics the logic of the Aurora read-only cluster endpoint.
- strict-reader - During failover, the driver tries to connect to any available reader node. If no reader is available, the driver raises an error. Reader failover to a writer node will only be allowed for single-node clusters. This logic mimics the logic of the Aurora read-only cluster endpoint.
If this parameter is omitted, default value depends on connection url. For Aurora read-only cluster endpoint, it's set to reader-or-writer. Otherwise, it's strict-writer.
今まではクラスターエンドポイントに対して接続していたので、新しいWriterに接続しようとするstrict-writer
で実行されていたようです。
試しにReaderにアクセスできない場合はWriterにアクセスするreader-or-writer
の動作を確認してみます。
Javaのアプリケーションは以下の通りです。
./src/main/java/jar/JdbcApplication.java
package jar;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import software.amazon.jdbc.plugin.failover.FailoverFailedSQLException;
import software.amazon.jdbc.plugin.failover.FailoverSuccessSQLException;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
public class JdbcApplication {
// User configures connection properties here
private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";
public static void main(String[] args) {
final Properties props = new Properties();
props.setProperty("wrapperPlugins", "failover,awsSecretsManager");
props.setProperty("wrapperLoggerLevel", "FINEST");
props.setProperty("failoverMode", "reader-or-writer");
props.setProperty("secretsManagerRegion", "us-east-1");
props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");
try {
Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
while (true) {
DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
String date = dtformat.format(LocalDateTime.now());
System.out.print(date + " : ");
try {
Statement stmt = conn.createStatement();
ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");
if (rs.next()) {
System.out.println(rs.getString(1));
} else {
throw new SQLException("Failed to get IP address");
}
} catch (FailoverSuccessSQLException e) {
System.out.println("Failover succeeded, retrying query ...");
} catch (FailoverFailedSQLException e) {
System.out.println("Failover failed ...");
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
try {
Thread.sleep(800);
} catch (Exception e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
}
この状態でJavaアプリケーション実行中にAurora DBクラスターのフェイルオーバーを実行します。
$ mvn spring-boot:run
.
.
(中略)
.
.
[INFO] Attaching agents: []
Jun 23, 2023 8:25:48 AM software.amazon.jdbc.targetdriverdialect.TargetDriverDialectManager logDialect
FINEST: Target driver dialect set to: 'pgjdbc', software.amazon.jdbc.targetdriverdialect.PgTargetDriverDialect@136432db.
Jun 23, 2023 8:25:48 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin initHostProvider
FINER: failoverMode=READER_OR_WRITER
Jun 23, 2023 8:25:49 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-23 08:25:48.994994758]
Jun 23, 2023 8:25:49 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 23, 2023 8:25:49 AM software.amazon.jdbc.PluginServiceImpl getCurrentHostSpec
FINEST: Set current host to HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-23 08:25:48.994994758]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Cluster endpoint resolves to 10.1.1.93.
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINE: Node is no longer available in the topology: HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-23 08:25:48.994994758]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE,weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host address: 10.1.1.93
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
2023/06/23 08:25:50.206 : Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
.
.
(中略)
.
.
2023/06/23 08:26:28.806 : Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1853, 2023-06-23 08:26:20.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=18, null]
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/23 08:26:29.609 : Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1853, 2023-06-23 08:26:20.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=18, null]
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Starting reader failover procedure.
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.PluginServiceImpl setAvailability
FINEST: There are no changes in the hosts availability.
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@48da0960
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Connected to: HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:26:31.235 : Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2023/06/23 08:26:32.043 : Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2023/06/23 08:26:32.846 : Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2秒ほどでフェイルオーバーしました。これは速いですね。
100msec間隔でループするように修正して、再実行してみます。
./src/main/java/jar/JdbcApplication.java
package jar;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import software.amazon.jdbc.plugin.failover.FailoverFailedSQLException;
import software.amazon.jdbc.plugin.failover.FailoverSuccessSQLException;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
public class JdbcApplication {
// User configures connection properties here
private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";
public static void main(String[] args) {
final Properties props = new Properties();
props.setProperty("wrapperPlugins", "failover,awsSecretsManager");
props.setProperty("wrapperLoggerLevel", "FINER");
props.setProperty("failoverMode", "reader-or-writer");
props.setProperty("secretsManagerRegion", "us-east-1");
props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");
try {
Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
while (true) {
DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
String date = dtformat.format(LocalDateTime.now());
System.out.print(date + " : ");
try {
Statement stmt = conn.createStatement();
ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");
if (rs.next()) {
System.out.println(rs.getString(1));
} else {
throw new SQLException("Failed to get IP address");
}
} catch (FailoverSuccessSQLException e) {
System.out.println("Failover succeeded, retrying query ...");
} catch (FailoverFailedSQLException e) {
System.out.println("Failover failed ...");
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
try {
Thread.sleep(100);
} catch (Exception e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
} catch (SQLException e) {
System.err.println("Error: " + e.getMessage());
e.printStackTrace();
}
}
}
実行結果は以下の通りです。
2023/06/23 08:41:35.732 : 10.1.1.116
2023/06/23 08:41:35.833 : 10.1.1.116
2023/06/23 08:41:35.935 : 10.1.1.116
2023/06/23 08:41:36.037 : 10.1.1.116
2023/06/23 08:41:36.140 : Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Starting reader failover procedure.
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@1533f902
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1551, 2023-06-23 08:41:08.0]
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:41:36.571 : 10.1.1.93
2023/06/23 08:41:36.677 : 10.1.1.93
2023/06/23 08:41:36.779 : 10.1.1.93
2023/06/23 08:41:36.880 : 10.1.1.93
2023/06/23 08:41:36.981 : 10.1.1.93
0.4秒でフェイルオーバーしていますね。この後5回やっていずれも0.4秒でした。これはなかなか速いですね。
Failover Pluginを使う場合 (DBインスタンス3台)
先の検証からstrict-writer
を使用する場合、新しいWriterへの接続(Task B)の中で旧Writerへの接続がループしていることが気になりました。
具体的には以下です。
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:16 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:18 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:20 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=5, null]
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
旧Auroraレプリカでフェイルオーバー先であろうdb-instance-a
に接続して、db-instance-a
の状態がWRITER
であることが判明していることに関わらず、旧Writerdb-instance-b
に接続できるまで待っているのに疑問を持ちました。
もしかすると、複数台のDBインスタンスに接続して状態がWRITER
であるという確信を持てなければフェイルオーバーしない作りなのでしょうか。
[TaskB] Host {0} is not yet connected to a cluster. The cluster is still being reconfigured.
というメッセージを出力する箇所を調査すると
ClusterAwareWriterFailoverHandler.javaのrefreshTopologyAndConnectToNewWriter()
でトポロジサイズが1である場合は、「現在接続されているリーダーはフェイルオーバー中で、スタンドアロンノードとして動作している」として、何もしないようです。
aws-advanced-jdbc-wrapper/wrapper/src/main/java/software/amazon/jdbc/plugin/failover/ClusterAwareWriterFailoverHandler.java
/**
* Re-read topology and wait for a new writer.
*
* @return Returns true if successful.
*/
private boolean refreshTopologyAndConnectToNewWriter() throws InterruptedException {
while (true) {
try {
pluginService.forceRefreshHostList(this.currentReaderConnection);
final List<HostSpec> topology = pluginService.getHosts();
if (!topology.isEmpty()) {
if (topology.size() == 1) {
// The currently connected reader is in a middle of failover. It's not yet connected
// to a new writer adn works in as "standalone" node. The handler needs to
// wait till the reader gets connected to entire cluster and fetch a proper
// cluster topology.
// do nothing
LOGGER.finest(() -> Messages.get("ClusterAwareWriterFailoverHandler.standaloneNode",
new Object[]{this.currentReaderHost.getUrl()}));
} else {
this.currentTopology = topology;
final HostSpec writerCandidate = getWriter(this.currentTopology);
if (!isSame(writerCandidate, this.originalWriterHost)) {
// new writer is available, and it's different from the previous writer
LOGGER.finest(() -> Utils.logTopology(this.currentTopology, "[TaskB] "));
if (connectToWriter(writerCandidate)) {
return true;
}
}
}
}
} catch (final SQLException e) {
LOGGER.finer(
() -> Messages.get(
"ClusterAwareWriterFailoverHandler.taskBEncounteredException",
new Object[] {e}));
return false;
}
TimeUnit.MILLISECONDS.sleep(readTopologyIntervalMs);
}
}
つまりはDBインスタンスが3台以上いれば、strict-writer
であっても10秒未満でフェイルオーバーできるということでしょうか。
DBインスタンスを追加して検証してみます。追加したDBインスタンスのIPアドレスは以下の通りです。
$ dig db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com +short
10.1.1.77
DBインスタンス追加後の実行結果は以下の通りです。
2023/06/23 08:54:55.987 : 10.1.1.93
2023/06/23 08:54:56.789 : 10.1.1.93
2023/06/23 08:54:57.591 : 10.1.1.93
2023/06/23 08:54:58.393 : 10.1.1.93
2023/06/23 08:54:59.195 : Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@2ee47fbb
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@1ad2cc68
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=19, null]
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:55:02.413 : 10.1.1.77
2023/06/23 08:55:03.221 : 10.1.1.77
2023/06/23 08:55:04.023 : 10.1.1.77
2023/06/23 08:55:04.825 : 10.1.1.77
strict-writer
であっても3秒でフェイルオーバーしましたね。
100msec間隔でDBに接続するように修正して、再度検証してみます。
2023/06/23 08:57:46.484 : 10.1.1.77
2023/06/23 08:57:46.585 : 10.1.1.77
2023/06/23 08:57:46.687 : 10.1.1.77
2023/06/23 08:57:46.788 : Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@22224a7d
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@7daf864d
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINE: [TaskB] Trying to connect to a new writer: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-23 08:57:56.0]
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:57:57.274 : 10.1.1.93
2023/06/23 08:57:57.393 : 10.1.1.93
2023/06/23 08:57:57.495 : 10.1.1.93
次は11秒もかかってしまいました。
ログレベルをFINEST
に変更して再度確認します。
2023/06/25 21:28:32.106 : Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=805, 2023-06-25 21:28:09.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=803, 2023-06-25 21:28:09.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
2023/06/25 21:28:32.908 : Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=805, 2023-06-25 21:28:09.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=803, 2023-06-25 21:28:09.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@6c6a12eb
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@631f4046
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=24, null]
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:28:34 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINEST: Current reader connection is actually a new writer connection.
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 21:28:36.125 : Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/25 21:28:36.939 : Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
次は4秒でフェイルオーバーが完了しました。
もう一度やってみましょう。
2023/06/25 21:36:44.599 : Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2401, 2023-06-25 21:36:24.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=702, 2023-06-25 21:36:24.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, null]
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/25 21:36:45.402 : Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2401, 2023-06-25 21:36:24.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=702, 2023-06-25 21:36:24.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, null]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@20ee6e78
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=27, 2023-06-25 21:36:45.0]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@631f4046
Jun 25, 2023 9:36:47 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:47 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=21, 2023-06-25 21:36:47.0]
Jun 25, 2023 9:36:47 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:49 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:49 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=11, 2023-06-25 21:36:49.0]
Jun 25, 2023 9:36:49 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:51 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:51 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, 2023-06-25 21:36:51.0]
Jun 25, 2023 9:36:51 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:53 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:53 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, 2023-06-25 21:36:53.0]
Jun 25, 2023 9:36:53 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=74, 2023-06-25 21:36:53.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINE: [TaskB] Trying to connect to a new writer: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 21:36:56.527 : Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
2023/06/25 21:36:57.349 : Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
今度はフェイルオーバー完了までに11秒かかりました。
もしかすると、Auroraレプリカの再起動のタイミングによっては3台であっても同時に複数台のDBインスタンスに接続できていないのでしょうか。
Failover Pluginを使う場合 (DBインスタンス4台)
DBインスタンスを4台に増やすとどうでしょうか。
2023/06/25 22:27:30.766 : Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1204, 2023-06-25 22:26:59.0]
HostSpec[host=db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1202, 2023-06-25 22:26:59.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1208, 2023-06-25 22:26:59.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
2023/06/25 22:27:31.569 : Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1204, 2023-06-25 22:26:59.0]
HostSpec[host=db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1202, 2023-06-25 22:26:59.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1208, 2023-06-25 22:26:59.0]
HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@22224a7d
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@59ad88e5
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Host 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINEST: Current reader connection is actually a new writer connection.
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 22:27:32.859 : Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/25 22:27:33.667 : Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2秒でフェイルオーバーが完了しましたね。
もう一度やってみます。
2023/06/25 22:33:42.050 : 10.1.1.77
2023/06/25 22:33:42.151 : 10.1.1.77
2023/06/25 22:33:42.252 : 10.1.1.77
2023/06/25 22:33:42.354 : Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@6720c8fd
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@55763653
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINE: [TaskB] Trying to connect to a new writer: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=9, 2023-06-25 22:33:46.0]
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 22:33:46.763 : 10.1.1.93
2023/06/25 22:33:46.881 : 10.1.1.93
2023/06/25 22:33:46.983 : 10.1.1.93
次は4秒でフェイルオーバーが完了しました。
この後10回ほどリトライしましたが、いずれも2-5秒でした。
フェイルオーバー時のダウンタイムの許容時間がこのぐらいであれば、DBインスタンスが4台以上必要そうです。
RDS Proxy
おまけでRDS Proxy経由でアクセスした場合のダウンタイムを計測してみます。
RDS Proxyを追加して0.1秒間隔でRDS Proxyにアクセスした場合、通信できないタイミングがあるか確認します。
# シークレットから認証情報を取得
$ get_secrets_value=$(aws secretsmanager get-secret-value \
--secret-id 'rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082' \
--region us-east-1 \
| jq -r .SecretString)
# 環境変数に埋め込み
$ export PGHOST='db-proxy.proxy-cicjym7lykmq.us-east-1.rds.amazonaws.com'
$ export PGDATABASE=testDB
$ export PGUSER=$(echo "${get_secrets_value}" | jq -r .username)
$ export PGPASSWORD=$(echo "${get_secrets_value}" | jq -r .password)
# 0.1秒間隔でRDS Proxyにアクセス
$ while true; do
date +"%H:%M:%S.%3N " | tr -d "\n"
echo "SELECT inet_server_addr();" | psql -t
sleep 0.1
done
.
.
(中略)
.
.
08:16:14.997 10.1.1.93
08:16:15.151 10.1.1.93
08:16:15.303 10.1.1.93
08:16:15.462 10.1.1.77
08:16:16.003 10.1.1.77
08:16:16.175 10.1.1.77
0.15秒未満でフェイルオーバーしていますね。DBインスタンスを4台構成から2台構成にしても同じく0.15秒未満でフェイルオーバーしていました。
RDS Proxyの制約事項やコスト、レイテンシーが許容できるのであれば、RDS Proxyを使う方が幸せかもしれません。
AWS JDBC Driverを使うときは複数のプラグインを使いこなしたい
AWS JDBC Driver の Failover Plugin を使って3秒でWriterをフェイルオーバーしてみました。
3秒とは言っても検証した限りDBインスタンスが4台以上稼働している場合になります。AZ障害の場合は同時に複数台ダウンするでしょうから、その場合の動作が心配ではあります。
AWS JDBC DriverにはFailover Plugin以外にもプラグインが複数あるので、使うときは複数のプラグインを使いこなしたいですね。
以下に開発者ガイドやプラグインごとのプロパティなどがまとまっているので、ぜひご参照ください。
また、検証で使用したAWS CDKのコードは以下リポジトリに保存しています。
この記事が誰かの助けになれば幸いです。
以上、AWS事業本部 コンサルティング部の のんピ(@non____97)でした!