WebSphere Liberty でトランザクションのピア・リカバリーを試してみる(3/3)

WebSphere Liberty 21.0.0.9 からトランザクションのピア・リカバリーが利用できるようになったので、早速、動作を確認してみました。

[前々回の記事](https://qiita.com/splendormy/items/d1d6d76de43e32a7d553) と [前回の記事](https://qiita.com/splendormy/items/e74dd478faba00c8c715)では、下記の内容を記載しました。

- ２フェーズ・コミット(2 phase commit)
- ピア・リカバリー
- 検証環境
- ピア・リカバリーできない状態での動作を確認 (再起動によるリカバリーの確認)

この記事では、最終目的である、ピア・リカバリーの動作を確認します。

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

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

![環境.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/555650/bffabbfb-7754-21c2-1e9a-cd8e5b2aaec1.png)

### 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 しました。しばらくすると、以下の出力があり、ピア・リカバリーが完了したことが確認できました。

```text:一部編集
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)](https://www.ibm.com/docs/ja/was-liberty/base?topic=configuration-transaction) 


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