ピア・リカバリーの動作を確認

ピア・リカバリーの動作を確認するので、WebSphere Liberty を２つ起動し、一方の WebSphere Liberty が稼働するノードを停止させることで障害をシミュレートします。
検証で使用する環境は、下図のようになります。検証環境や WebSphere Liberty の構成は、前々回の記事を参照してください。

WebSphere Liberty を２つ起動

２つの WebSphere Liberty を起動すると、下記の５つのテーブルが DB tranlog 内に作成されました。前回の結果から予測される通りかと思います。

テーブル名	補足
WAS_LEASES_LOG	ドキュメントには説明がありません。下記参照。
WAS_PARTNER_LOGMYLIBERTYPVIBMWEBSPH0	パートナー・ログ (Pod my-liberty-pv-ibm-websph-0 用)
WAS_PARTNER_LOGMYLIBERTYPVIBMWEBSPH1	パートナー・ログ (Pod my-liberty-pv-ibm-websph-1 用)
WAS_TRAN_LOGMYLIBERTYPVIBMWEBSPH0	トランザクション・ログ (Pod my-liberty-pv-ibm-websph-0 用)
WAS_TRAN_LOGMYLIBERTYPVIBMWEBSPH1	トランザクション・ログ (Pod my-liberty-pv-ibm-websph-1 用)

テーブル WAS_LEASES_LOG 内の内容も、起動した Pod に応じて以下のようになっていました。

[db2inst1@db2-db2u-0 - Db2U db2inst1]$ db2 "select * from WAS_LEASES_LOG"

SERVER_IDENTITY           RECOVERY_GROUP     LEASE_OWNER               LEASE_TIME
------------------------- ------------------ ------------------------- --------------------
mylibertypvibmwebsph0     wlp1               mylibertypvibmwebsph0     1632723808420
mylibertypvibmwebsph1     wlp1               mylibertypvibmwebsph1     1632723833455

  2 record(s) selected.

LEASE_TIME を時刻(UTC)に変換すると、下記のようになります。今回は、約25秒の差になっていますが、これは起動のタイミング等によって変わるようです。

SERVER_IDENTITY           RECOVERY_GROUP            LEASE_OWNER               LEASE_TIME
------------------------- ------------------- ------------------------- --------------------
mylibertypvibmwebsph0     wlp1                mylibertypvibmwebsph0     9/27/21 6:23:28.420
mylibertypvibmwebsph1     wlp1                mylibertypvibmwebsph1     9/27/21 6:23:53.455

prepare 完了を記録した後にノードを停止

ノード worker-0 を停止させることで障害をシミュレートします。ノード worker-0 で稼働する WebSphere Liberty 上の検証用アプリにアクセスし、「トランザクション・ログに prepare 完了を記録」した後にスリープさせます。その間に、ノード worker-0 を停止することで、障害をシミュレートします。
Db2 と MQ は prepare が完了し、TM からの commit 指示を待つ状態となります。
尚、WebSphere Liberty を kubernetes の StatefulSet で起動していますので、他のノードで自動的に再起動されることはありません。

ノード worker-0 の停止は、WAS_LEASES_LOG テーブルの内容を select しつつ、ノード worker-0 で稼働する Pod の LEASE_TIME のカラムが更新されて直ぐに行いました。但し、手作業なので、更新されてから５秒程度の遅延はあったと思われます。
停止直前の LEASE_TIME の値は 1632724782007 (UTC で 9/27/21 6:39:42 ) でした。

ピア・リカバリーを確認

ノード worker-0 を停止した後に、別ノード worker-1 で稼働する WebSphere Liberty の messages.log を tail しました。しばらくすると、以下の出力があり、ピア・リカバリーが完了したことが確認できました。

一部編集

bash-4.4$ tail /logs/messages.log -f | grep RecoveryManager
[9/27/21 6:41:14:328 UTC] 00000055 com.ibm.tx.jta.impl.RecoveryManager  A WTRN0132I: Transaction recovery for mylibertypvibmwebsph0 initiated with server uuid 3079e6254db5d53cd44e9c346ebb63fc266a8b9a and restart epoch 1
[9/27/21 6:41:14:329 UTC] 00000055 com.ibm.tx.jta.impl.RecoveryManager  A WTRN0027I: Transaction service recovering 1 transaction.
[9/27/21 6:41:14:329 UTC] 00000055 com.ibm.tx.jta.impl.RecoveryManager  A WTRN0134I: Recovering 5 XA resource manager(s) from the transaction partner logs

当然ながら、Db2 と MQ にも in-doubt なトランザクションは残っておらず、正常にリカバリーされていました。

[db2inst1@db2-db2u-0 - Db2U db2inst1]$ db2 list indoubt transactions
SQL1251W  No data returned for heuristic query.  SQLSTATE=00000

bash-4.4$ dspmqtrn -e -m QM_TEST
There are no matching prepared or heuristically completed transactions.

また、リカバリーが完了すると、ノード worker-0 で稼働していた WebSphere Liberty 用のテーブル(WAS_PARTNER_LOG??? と WAS_TRAN_LOG???) は削除され、テーブル WAS_LEASES_LOG 内の該当行も削除されていました。

ピア・リカバリーに要した時間

上記の結果から、ピア・リカバリーに要した時間を確認してみると、約1分27秒となりました。

ノードの停止時刻： 9/27/21 6:39:42 ＋５秒程度より、おおよそ、9/27/21 6:39:47
ピア・リカバリー完了：9/27/21 6:41:14

今回は LEASE_TIME が更新されて直ぐに障害を発生させましたので、回復時間としては長い方になるではないかと思われますが、トランザクション・ログを引き継いだ側のチェック間隔にもよるので、リカバリー時間の単なる一例として扱うのが適切かと思います。

追記：テーブル WAS_LEASES_LOG への書き込み間隔やチェック間隔などは、server.xml の transaction タグで指定でき、以下のような設定項目があります。上記のテストはデフォルト設定で行ったものです。

leaseLength (デフォルト：60s)
leaseCheckInterval (デフォルト：60s)
leaseRenewalThreshold (デフォルト：90s)
leaseExpiryThreshold (デフォルト：1回)

参照：Liberty サーバー構成 > トランザクション・マネージャー (transaction)

終わりに

WebSphere Liberty 21.0.0.9 から利用可能となった、トランザクションのピア・リカバリーの正常な動作が確認できました。
気になる点は色々ありますので、機会があれば、もう少し調査してみたいところです。