Amazon Aurora PostgreSQL 導入時に、フェイルオーバーのタイミングで、すでに接続しているコネクションがどうなるのか気になりました。
その際、実験した結果をまとめます。
何が知りたかったか
フェイルオーバー時の挙動を確認しているとき、そういえばTCPのレイヤでどういう動きになっているのか疑問に浮かびました。
具体的には以下の通りです。
- 障害発生時、サーバからfinパケットは送信されるのか
- finパケットが送信されない場合、すでに接続しているクライアントのコネクションは破棄されないのではないか
- 仮にコネクションが残るならば、MaxConnectionエラーになる可能性がでてくるのではないか
つまり、障害が発生した場合、クライアントはコネクションをちゃんと閉じて、ソケットが残るようなことはないのか、という話です。
構成
psql：クライアント
↓
pgbouncer：コネクションプール
↓
Amazon Aurora PostgreSQL：データベースサーバ
psqlとpgbouncerは同じインスタンスで動かす想定です。
以下ざっくり構築手順です。
- psql
# yum install postgresql96
# psql -V
psql (PostgreSQL) 9.6.10
- pgbouncer
# yum groupinstall "Development Tools"
# yum install libevent-devel
# yum install openssl-devel
# cd /usr/local/src
# wget http://pgbouncer.github.io/downloads/files/1.7.2/pgbouncer-1.7.2.tar.gz
# tar xf pgbouncer-1.7.2.tar.gz
# cd pgbouncer-1.7.2
# ./configure --prefix /usr/local/pgbouncer
# make
# make install
# mkdir /etc/pgbouncer
# mkdir /var/log/pgbouncer
# mkdir /var/run/pgbouncer
# useradd pgbouncer
# chown pgbouncer:pgbouncer /var/run/pgbouncer/
# chown pgbouncer:pgbouncer /var/log/pgbouncer/
# cp etc/pgbouncer.ini /etc/pgbouncer/pgbouncer.ini
# vim /etc/pgbouncer/pgbouncer.ini
[databases]
hogedb = host=hogehoge port=5432 user=postgres password=xxxxxxxxxxxxxxx
[pgbouncer]
logfile = /var/log/pgbouncer/pgbouncer.log
pidfile = /var/run/pgbouncer/pgbouncer.pid
listen_addr = 127.0.0.1
listen_port = 6432
auth_type = trust
auth_file = /etc/pgbouncer/userlist.txt
pool_mode = session
server_reset_query = DISCARD ALL
max_client_conn = 1
default_pool_size = 1
# /usr/local/pgbouncer/bin/pgbouncer -d -upgbouncer -q /etc/pgbouncer/pgbouncer.ini
- Amazon PostgreSQL Aurora
インスタンス台数：2台(それぞれ一つのクラスタに紐づける)
インスタンスタイプ：r4.large
パラメータグループ：statement_timeoutを0にしておく
デフォルトのDB：hogedb
実験前にTCPの状態がどう遷移するか調べる
そもそもTCPに関して分かっているつもりで分かってなかったので少し掘り下げて調べました。
ただ、RFCとカーネルの実装を調べるのは尻込みしたので、
こちらとこちらを参考にしました。
TCPがCLOSEDになるための条件を要約すると以下になるようです。
- finパケットを送受信する
- rstパケットを受信する
- 切断を検知する(keepaliveのタイムアウト)
Auroraの障害発生をテストしてみる
psqlコマンドでローカルのpgbouncerに接続し、プール経由でAuroraに接続します。
この間にAurora PostgreSQLをフェイルオーバーしてみます。
(マネジメントコンソールからフェイルオーバーボタンをﾎﾟﾁｯとしました)
$ psql -hlocalhost -Upostgres hogedb -p 6432 -c "select pg_sleep(1000);"
WARNING: terminating connection because of crash of another server process
DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT: In a moment you should be able to reconnect to the database and repeat your command.
ERROR: server conn crashed?
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
connection to server was lost
クライアントのコネクションが切断されました。
tcdumpを使って、切断されたタイミングのパケットの状態を見てみます。
# tcpdump port 5432
03:12:07.940806 IP 10.XX.XXX.X.postgres > 10.YY.YYY.Y.40066: Flags [P.], seq 814:1210, ack 147, win 105, options [nop,nop,TS val1249014 ecr 3608936989], length 396
03:12:07.940838 IP 10.YY.YYY.Y.40066 > 10.XX.XXX.X.postgres: Flags [.], ack 1210, win 252, options [nop,nop,TS val 3608993075 ecr1249014], length 0
03:12:07.942121 IP 10.XX.XXX.X.postgres > 10.YY.YYY.Y.40066: Flags [F.], seq 1210, ack 147, win 105, options [nop,nop,TS val1249014 ecr 3608993075], length 0
03:12:07.942307 IP 10.YY.YYY.Y.40066 > 10.XX.XXX.X.postgres: Flags [F.], seq 147, ack 1211, win 252, options [nop,nop,TS val3608993077 ecr 1249014], length 0
03:12:07.942489 IP 10.XX.XXX.X.postgres > 10.YY.YYY.Y.40066: Flags [.], ack 148, win 105, options [nop,nop,TS val 1249014 ecr3608993077], length 0
AuroraからのFlags [F.] があります！（finフラグがついたパケット)
わかったこと
RDSはフェイルオーバーするときfinを送ってくれる！
本当にfin送ってくれるの？
よし、安心！と思いましたが、今度はAuroraがfinを送らないことがあるのか気になりました。
Auroraインスタンスの障害とともに、finを送るはずのネットワーク機器に障害が発生したとかあるかもしれません。
というわけで、finがクライアントに届かない場合どうなるのかも確認してみます。
具体的には以下の場合を調べてみます。
- クライアントが接続要求(SYN-SENT)したとき、PostgreSQLからSYN/ACKを受信できない場合
- クライアントが接続確立(ESTABLISHED)しているとき、PostgreSQLからデータを受信できない場合
前者が、障害が発生したことを知らずに新規接続しようとする場合。
後者が、すでに接続しているコネクションからfinパケットが返ってこない場合の想定です。
PostgreSQLサーバから接続完了を受信できない場合
故障をシミュレートするためにiptablesで5432の戻りパケットを閉じます
(障害発生時、クライアントはパケットを受け取れなくなるわけじゃないので、このシミュレーションはそもそも障害の状況とは違うけど、どうしていいのか分からなかったのでiptablesでふさぎました)
# iptables -A INPUT -p tcp --sport 5432 -j DROP
# service iptables status
Table: filter
Chain INPUT (policy ACCEPT)
num target prot opt source destination
1 DROP tcp -- 0.0.0.0/0 0.0.0.0/0 tcp spt:5432
Chain FORWARD (policy ACCEPT)
num target prot opt source destination
Chain OUTPUT (policy ACCEPT)
num target prot opt source destination
psqlしてみます。
$ psql -hlocalhost -Upostgres hogedb -p6432 -c "select pg_sleep(100);"
psql: ERROR: client_login_timeout (server down)
60秒ほどでタイムアウトしました。
これはエラーに出ている通り、pgbouncerのclient_login_timeoutが関わっていそうです(デフォルトが60秒)。
tcpdumpで確認したときのパケットが以下で、１分ほどで閉じられています。
07:46:59.044743 IP 10.XX.XXX.X.40268 > 10.YY.YYY.Y.postgres: Flags [S], seq 3477421967, win 26883, options [mss 8961,sackOK$TS val 3625483887 ecr 0,nop,wscale 7], length 0
07:46:59.044992 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40268: Flags [S.], seq 3988907612, ack 3477421968, win 26844, options[mss 8960,sackOK,TS val 5371789 ecr 3625483887,nop,wscale 8], length 0
略
07:48:00.518435 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40272: Flags [S.], seq 3157488874, ack1214984228, win 26844, options[mss 8960,sackOK,TS val 5387158 ecr 3625514080,nop,wscale 8], length 0
07:48:15.622442 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40274: Flags [S.], seq 4189110072, ack2792284373, win 26844, options[mss 8960,sackOK,TS val 5390934 ecr 3625529197,nop,wscale 8], length 0
またmax_connectionを1にしているので、別のターミナルからクエリを実行するとエラーになります。
# psql -hlocalhost -Upostgres hogedb -p6432 -c "select pg_sleep(100);"
psql: ERROR: no more connections allowed (max_client_conn)
ちなみに、さらに別のターミナルを開いてpsqlしてる時のTCPの状態を見てみると、
目論見通りSYN_SENTの状態になっていました。
# netstat -aneetp | grep $(pgrep pgbouncer)
tcp 0 0 127.0.0.1:6432 0.0.0.0:* LISTEN 501 48548 18420/pgbouncer
tcp 0 1 10.XX.XXX.X:40268 10.YY.YYY.Y:5432 SYN_SENT 501 48559 18420/pgbouncer
tcp 0 0 127.0.0.1:6432 127.0.0.1:59986 ESTABLISHED 501 48557 18420/pgbouncer
- 新規接続はpgbouncerが60秒で諦める(調整が可能)
- リクエストはpgbouncerがタイムアウトするまで待たされる
- 別にリクエストを受け付け続け、コネクションがMAXに到達すると、リクエストはエラーとなる
ということが分かりました。
こういう障害があるとリクエストが詰まって、コネクションがMAXでエラーとなることが想定できます。
スループットを上げるのであればタイムアウトを短くしておいたほうが良いかもしれません。
PostgreSQLサーバからデータパケットを受信できない場合
ちょっと結論ありきな設定になりますが、OSのkeepaliveの時間を60秒に変更します。
(30 + 5 * 6)
# sysctl -a | grep keepalive
net.ipv4.tcp_keepalive_intvl = 5
net.ipv4.tcp_keepalive_probes = 6
net.ipv4.tcp_keepalive_time = 30
今度はiptablesをかける前に、psqlを実行し接続します。
$ psql -hlocalhost -Upostgres hogedb -p6432 -c "select pg_sleep(100);"
ERROR: server conn crashed?
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
connection to server was lost
クラッシュしていますが、エラーが出る前にiptablesを実行しています。
$ iptables -A INPUT -p tcp --sport 5432 -j DROP
psqlを実行しているときの、tcpdumpの結果が以下の通りです。
08:31:40.318841 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [S], seq 2127303927, win 26883, options [mss 8961,sackOK,TS val 3628165113 ecr 0,nop,wscale 7], length 0
08:31:40.319077 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40332: Flags [S.], seq 443007281, ack 2127303928, win 26844, options [mss 8960,sackOK,TS val 6042108 ecr 3628165113,nop,wscale 8], lengmss 8960,sackOK,TS val 6042108 ecr 3628165113,nop,wscale 8], length 0
08:31:40.319092 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [.], ack 1, win 211, options [nop,nop,TS val 3628165113 ecr 6042108], length 0
08:31:40.319274 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [P.], seq 1:48, ack 1, win 211, options [nop,nop,TS val 33628165114], length 0
略
08:32:21.193677 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40332: Flags [.], ack 150, win 105, options [nop,nop,TS val 6052327 ecr 3628165118], length 0
08:32:26.313470 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [.], ack 377, win 219, options [nop,nop,TS val 3628211107 ecr 6042119], length 0
08:32:26.313712 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40332: Flags [.], ack 150, win 105, options [nop,nop,TS val 6053607 ecr 3628165118], length 0
08:32:31.433463 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [.], ack 377, win 219, options [nop,nop,TS val 3628216227 ecr 6042119], length 0
08:32:31.433689 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40332: Flags [.], ack 150, win 105, options [nop,nop,TS val 6054887 ecr 3628165118], length 0
08:32:36.553426 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [.], ack 377, win 219, options [nop,nop,TS val 3628221347 ecr 6042119], length 0
08:32:36.553670 IP 10.YY.YYY.Y.postgres > 10.XX.XXX.X.40332: Flags [.], ack 150, win 105, options [nop,nop,TS val 6056167 ecr 3628165118], length 0
08:32:41.673452 IP 10.XX.XXX.X.40332 > 10.YY.YYY.Y.postgres: Flags [R.], seq 150, ack 377, win 219, options [nop,nop,TS val 3628226467 ecr 6042119], length 0
これも60秒ほどで閉じられました。
sleepしてる間は特に送信されるデータがないので、30秒後にOSのkeepaliveが発動します。
keepaliveが発生してから5秒置きに6回ほど再送されていました。(↑の結果はその一部です)
そしてauroraからデータが送られてこない(送られてはいるけどdropしている)ので、
最後にクライアント側から[R.]でリセットフラグを立ててauroraに向かって送信しているようです。
今回も別のターミナルで接続してみたら、max connectionエラーになりました。
# psql -hlocalhost -Upostgres hogedb -p6432 -c "select pg_sleep(100);"
psql: ERROR: no more connections allowed (max_client_conn)
コネクションの状態は以下の通りでした。
# netstat -aneetp | grep $(pgrep pgbouncer)
tcp 0 0 127.0.0.1:6432 0.0.0.0:* LISTEN 501 50027 18886/pgbouncer
tcp 0 0 10.XX.XXX.X:40332 10.YY.YYY.Y:5432 ESTABLISHED 501 50214 18886/pgbouncer
tcp 0 0 127.0.0.1:6432 127.0.0.1:60076 ESTABLISHED 501 50212 18886/pgbouncer
- 既存の接続はデータパケットが送られてこないので、OSのkeepalive時間待つことになる
- 別にリクエストを受け付け続け、コネクションがMAXに到達すると、リクエストはエラーとなる
ということが分かりました。
コネクションが解放されない場合は、再起動すればいいだけではありますが、
カーネルパラメータは調整しておいたほうが素早く再接続できそうです。
そもそもOSに頼らずアプリケーションにタイムアウトを設定しておくと良さそうです。
最後に
- フェイルオーバ時、Auroraはfinを送信するので、これまでのコネクションはすべてクローズされることが分かりました。
- finが送信できない場合を想定するなら、アプリケーション側のタイムアウトかkeepaliveの設定を変更しておくとよさそうです。
- プリミティブなところの知っていると、テストケースの幅が広がるように感じました。