PostgreSQLサーバの冗長構成を検討することになりました。

AWSなどのクラウドサービスで運用するなら、そのようなPaaSが提供されているので、ほぼ、それ一択なんでしょうが、今のところVPSを使う案件が中心なので、候補の対象外です。

また約5年前に、Pacemakerを使ったPostgreSQLサーバの評価に関わったことがあるのですが、PacemakerがいろいろなMWの制御ができるだけに、覚えることも多かったので、今回はちょっと敬遠。

そして見つかったのがpg_auto_failoverでした。

以下の内容は多分に推測が混ざってますので、ご注意ください。

評価環境の準備

まずは簡単に動作を確認したいので、リポジトリにある docker-compose.yml を使います。
そのままの設定だと、

PostgreSQLサーバのコンテナ3台 (以下、DBノード1, DBノード2のように表記)
PostgreSQLクラスタを監視するコンテナ1台 (以下、監視ノード)
デモ用アプリケーションのコンテナ1台 (以下、デモアプリ)

の計5台のコンテナが起動しますが、PostgreSQLコンテナは3台もいらないので、node3はコメントアウトしました。

デモ用アプリケーションはドキュメントとdocker-compose.ymlで指定されている環境変数から、以下のように動作するようです。

10個のPostgreSQLクライアントが、１２５秒間クラスタにアクセスする。
45秒経ったら最初のフェールオーバーを実施する。それ以降、30秒間隔にフェールオーバーを実施。
読み書き可能なPostgreSQLサーバへの接続時間を計測する。

評価環境の実行

さっそくdocker composeで動かして、ログを見ると以下のような流れでした。

デモアプリは、監視ノードから接続URIを取得し、プライマリのDBノードへ接続所要時間を計測する。

★ デモアプリが監視ノードに接続。でも、接続URIが取れない。
pg_auto_failover-demo-app-1  | 08:36:10 1 INFO  Successfully connected to "postgres://autoctl_node@monitor:/pg_auto_failover?" after 3 attempts in 3475 ms.
pg_auto_failover-demo-app-1  | 08:36:10 1 ERROR Failed to grab the Postgres URI to connect to formation "default", see above for details
pg_auto_failover-demo-app-1  | 08:36:10 1 INFO  Retrying to grab formation "default" URI in 749ms

★ DBノード2が監視ノードに接続。
pg_auto_failover-node2-1     | 08:36:10 9 INFO  Registered node 1 "node_1" (ee34f3f0f896:5432) in formation "default", group 0, state "single"

★ DBノード1が監視ノードに接続。
pg_auto_failover-node1-1     | 08:36:11 9 INFO  Registered node 2 "node_2" (ddb0a4b628c2:5432) in formation "default", group 0, state "wait_standby"

★ デモアプリが接続URIを取得できたが、まだ読み書き可能なDBノードには繋がらない。
pg_auto_failover-demo-app-1  | 08:36:11 1 INFO  Using application connection string "postgres://ee34f3f0f896:5432,ddb0a4b628c2:5432/analytics?target_session_attrs=read-write&sslmode=prefer"
pg_auto_failover-demo-app-1  | 08:36:11 1 WARN  Failed to connect to "postgres://@ee34f3f0f896,ddb0a4b628c2:5432,5432/analytics?sslmode=prefer&target_session_attrs=read-write", retrying until the server is ready

★ デモアプリがDBノードに接続。今から45秒後にフェールオーバー。
pg_auto_failover-demo-app-1  | 08:36:17 1 INFO  Successfully connected to "postgres://@ee34f3f0f896,ddb0a4b628c2:5432,5432/analytics?sslmode=prefer&target_session_attrs=read-write" after 26 attempts in 5606 ms.
pg_auto_failover-demo-app-1  | 08:36:17 7 INFO  Failover client is started, will failover in 45s and every 30s after that

監視ノードに、最初接続できたDBノードがプライマリ、次に接続できたのがセカンダリになり、ストリーミングレプリケーションが行われる。

pg_auto_failover-node2-1     | 08:36:10 9 INFO  FSM transition from "init" to "single": Start as a single node
pg_auto_failover-node1-1     | 08:36:11 9 INFO  FSM transition from "init" to "wait_standby": Start following a primary

★ DBノード2がレプリケーションスロット作成。
pg_auto_failover-node2-1     | 08:36:17 102 INFO  Creating replication slot "pgautofailover_standby_2"
pg_auto_failover-node2-1     | 08:36:17 102 INFO  FSM transition from "single" to "wait_primary": A new secondary was added
pg_auto_failover-node1-1     | 08:36:17 9 INFO  FSM transition from "wait_standby" to "catchingup": The primary is now ready to accept a standby

* DBノード1のpg_basebackupが完了
pg_auto_failover-node1-1     | 08:36:32 9 INFO  pg_basebackup: base backup completed
pg_auto_failover-node1-1     | 08:36:34 9 INFO  FSM transition from "catchingup" to "secondary": Convinced the monitor that I'm up and running, and eligible for promotion again

* ストリーミングレプリケーション開始
pg_auto_failover-node2-1     | 08:36:34 102 INFO  FSM transition from "wait_primary" to "primary": A healthy secondary appeared
pg_auto_failover-node2-1     | 08:36:35 102 INFO  Standby reached LSN 0/3013DD0, thus advanced past LSN 0/300BBA0

デモアプリは、DBノードに接続して45秒経過するとフェールオーバーを実施する。
- フェールオーバーして、デモアプリとの接続は1〜２秒で復活。
- ストリーミングレプリケーションの再開までは約10秒。

★ デモアプリからフェールオーバーを実施。
pg_auto_failover-demo-app-1  | 08:37:02 7 INFO  pg_autoctl perform failover
pg_auto_failover-demo-app-1  | 08:37:02 7 WARN  Lost connection.
pg_auto_failover-node1-1     | 08:37:02 9 INFO  FSM transition from "secondary" to "prepare_promotion": Stop traffic to primary, wait for it to finish draining.
pg_auto_failover-node2-1     | 08:37:02 102 INFO  FSM transition from "primary" to "draining": A failover occurred, stopping writes
pg_auto_failover-node1-1     | 08:37:02 9 INFO  FSM transition from "prepare_promotion" to "stop_replication": Prevent against split-brain situations.
pg_auto_failover-node2-1     | 08:37:02 102 INFO  FSM transition from "draining" to "demote_timeout": Secondary confirms it’s receiving no more writes
pg_auto_failover-node1-1     | 08:37:03 9 INFO  FSM transition from "stop_replication" to "wait_primary": Confirmed promotion with the monitor
pg_auto_failover-node2-1     | 08:37:03 102 INFO  FSM transition from "demote_timeout" to "demoted": Demote timeout expired

★ デモアプリのDBノードへの接続復活
pg_auto_failover-demo-app-1  | 08:37:03 8 INFO  Successfully connected to "postgres://@ee34f3f0f896,ddb0a4b628c2:5432,5432/analytics?sslmode=prefer&target_session_attrs=read-write" after 6 attempts in 1854 ms.
pg_auto_failover-demo-app-1  | 08:37:03 8 INFO  Client 1 attempted to connect during a failover, and had to attempt 6 times which took 1855.487 ms with the current retry policy

* DBノード2のpg_basebackupが完了
pg_auto_failover-node2-1     | 08:37:09 102 INFO  pg_basebackup: base backup completed
pg_auto_failover-node2-1     | 08:37:12 102 INFO  FSM transition from "catchingup" to "secondary": Convinced the monitor that I'm up and running, and eligible for promotion again

★ ストリーミングレプリケーションが再開。
pg_auto_failover-node1-1     | 08:37:12 9 INFO  FSM transition from "wait_primary" to "primary": A healthy secondary appeared
pg_auto_failover-node1-1     | 08:37:13 9 INFO  Standby reached LSN 0/5015E40, thus advanced past LSN 0/500E000

Javaアプリケーションでの動作確認

次にJDBCではどうなるかを確認します。

DBノード1を5433ポート、DBノード2を5434ポートにマッピング。
- pg_hba.cnfを、PostgreSQLのオフィシャルイメージと同様に、どこからでも接続可に修正してpg_ctl reload。
- 接続用のアカウントや、データベース(sample)およびテーブルを追加。
Javaアプリケーションはホスト側で実行。
- 1秒間に１レコードずつ追加。
- JDBC　URLに jdbc:postgresql://localhost:5433,localhost:5434/sample?targetServerType=master を指定。

実際の障害を想定して、pg_autoctl perform failoverコマンドではなく、DBノードのコンテナを停止。以下は監視ノードのログの抜粋です。

★ 15:15:23頃に、DBノード2を停止。

★ 監視ノードが、DBノード2(pg_auto_failoverではnod_1)の以上を検知。
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  Node node 1 "node_1" (ee34f3f0f896:5432) is marked as unhealthy by the monitor
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  New state for node 2 "node_2" (ddb0a4b628c2:5432): secondary ➜ prepare_promotion
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  New state for node 2 "node_2" (ddb0a4b628c2:5432): prepare_promotion ➜ stop_replication
pg_auto_failover-monitor-1  | 15:15:42 27 INFO  New state for node 1 "node_1" (ee34f3f0f896:5432): primary ➜ demote_timeout

★ DBノード２のデモート(降格)がタイムアウトし、DBノード1がwait_primary、DBノード2がdemotedに状態遷移。
pg_auto_failover-monitor-1  | 15:16:13 27 INFO  Setting goal state of node 2 "node_2" (ddb0a4b628c2:5432) to wait_primary and node 1 "node_1" (ee34f3f0f896:5432) to demoted after the demote timeout expired.
pg_auto_failover-monitor-1  | 15:16:13 27 INFO  New state for node 2 "node_2" (ddb0a4b628c2:5432): stop_replication ➜ wait_primary
pg_auto_failover-monitor-1  | 15:16:13 27 INFO  New state for node 1 "node_1" (ee34f3f0f896:5432): primary ➜ demoted

この時のJavaアプリケーション側のログの抜粋が以下になります。

★ 書き込み成功
2022-09-15 15:15:22.904 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:15:22.904 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('14', timestamp '2022-09-15 15:15:22.903612')
2022-09-15 15:15:22.912 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Affected row(s)          : 1

★ ここでPostgreSQLがダウンし応答待ち
2022-09-15 15:15:23.917 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:15:23.917 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('15', timestamp '2022-09-15 15:15:23.917026')

★ コネクションプールの接続確認でエラー
2022-09-15 15:15:23.931  WARN 22674 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@2d7a9786 (このコネクションは既にクローズされています。). Possibly consider using a shorter maxLifetime value.
  〜 割愛 〜
2022-09-15 15:15:23.945  WARN 22674 --- [           main] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Failed to validate connection org.postgresql.jdbc.PgConnection@25673087 (このコネクションは既にクローズされています。). Possibly consider using a shorter maxLifetime value.

★ 応答待ちタイムアウトして例外発生。
2022-09-15 15:15:53.925 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Exception                

org.jooq.exception.DataAccessException: SQL [insert into sample (text, insert_at) values (?, cast(? as timestamp))]; HikariPool-1 - Connection is not available, request timed out after 30002ms.
	at org.jooq_3.14.16.POSTGRES.debug(Unknown Source) ~[na:na]
	at org.jooq.impl.Tools.translate(Tools.java:2903) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:757) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:389) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractDelegatingQuery.execute(AbstractDelegatingQuery.java:119) ~[jooq-3.14.16.jar:na]
	at jp.co.supportas.samplemysql.SamplePostgreSQLApplication.run(SamplePostgreSQLApplication.kt:32) ~[main/:na]
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:771) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:755) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:315) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1306) ~[spring-boot-2.7.2.jar:2.7.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1295) ~[spring-boot-2.7.2.jar:2.7.2]
	at jp.co.supportas.samplemysql.SamplePostgreSQLApplicationKt.main(SamplePostgreSQLApplication.kt:49) ~[main/:na]
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30002ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-4.0.3.jar:na]
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159) ~[spring-jdbc-5.3.22.jar:5.3.22]
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117) ~[spring-jdbc-5.3.22.jar:5.3.22]
	at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:223) ~[spring-jdbc-5.3.22.jar:5.3.22]
	at jdk.proxy2/jdk.proxy2.$Proxy54.prepareStatement(Unknown Source) ~[na:na]
	at org.jooq.impl.ProviderEnabledConnection.prepareStatement(ProviderEnabledConnection.java:109) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.SettingsEnabledConnection.prepareStatement(SettingsEnabledConnection.java:73) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractQuery.prepare(AbstractQuery.java:442) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractDMLQuery.prepare0(AbstractDMLQuery.java:847) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractDMLQuery.prepare(AbstractDMLQuery.java:830) ~[jooq-3.14.16.jar:na]
	at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:342) ~[jooq-3.14.16.jar:na]
	... 8 common frames omitted
Caused by: org.postgresql.util.PSQLException: 指定された targetServerType のサーバーが見つかりません: primary
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:346) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:223) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.Driver.makeConnection(Driver.java:402) ~[postgresql-42.3.6.jar:42.3.6]
	at org.postgresql.Driver.connect(Driver.java:261) ~[postgresql-42.3.6.jar:42.3.6]
	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:364) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:476) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool.access$100(HikariPool.java:71) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:726) ~[HikariCP-4.0.3.jar:na]
	at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:712) ~[HikariCP-4.0.3.jar:na]
	at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

  〜 割愛 〜

★ 接続は復活したが応答は遅い
2022-09-15 15:15:55.012 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:15:55.013 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('16', timestamp '2022-09-15 15:15:55.012116')
2022-09-15 15:16:23.686 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Affected row(s)          : 1
★ ここから元通り
2022-09-15 15:16:24.690 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Executing query          : insert into sample (text, insert_at) values (?, cast(? as timestamp))
2022-09-15 15:16:24.690 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : -> with bind values      : insert into sample (text, insert_at) values ('17', timestamp '2022-09-15 15:16:24.690208')
2022-09-15 15:16:24.722 DEBUG 22674 --- [           main] org.jooq.tools.LoggerListener            : Affected row(s)          : 1

DBノードがダウンしてから、約１分でフェールオーバーできました。

所感

まずは良さそうな感じです。

DBノードがダウンしてからフェールオーバーするまで約1分というのは、心情的にちょっと長い気もしますが、チューニングの余地もあると思います。

ストリーミングレプリケーションを行うもろもろを自動的にやってくれるので、現段階でまだ知識の足りてない自分には助かります。
もちろん、実際に運用していくには、これを元にちゃんと理解していく必用はあるでしょう。
特に、pg_auto_failoverでフェールオーバーに失敗したような場合に、手動で復旧させるノウハウは必須です。

あと評価に使用したコンテナのPostgreSQLはバージョン10が使われていることから、バージョン13か14にした環境を自前で構築してみて、評価する必用もありますね。