はじめに
以前、Qレプリケーション（以降、QREP）に関わり、その中で、QREP構築中に出たエラーを思い出して、再現と対応方法を再確認してみました。
本記事では、MQメッセージ・キューがロストしてQアプライの処理が停止してしまった時のことを記載します。
※おおまかな流れの説明となっているため、詳細なコマンド等は割愛しております。
Qアプライ・ログのエラー
キャプチャー側の起動は問題なかったのですが、アプライ・プロセスを起動した際に次のようなエラーが出てしまっていました。
エラー概要 ： アプライの待っていたメッセージIDが違った件
# 以下のようなメッセージがセットで出ていました。
<browser::readNextDenseMsg> ASN7551E "Q Apply" : "ASN" : "BR00000" : Q アプライ・プログラム は、 受信キュー "QREP.RECVQ" (レプリケーション・キュー・マップ "SAMPLE_ASN_TO_TARGETDB_ASN") 上のメッセージ番号がスキップしているのを検出しました。 メッセージ ID "5152455068C26B93000000000000000000000000000001BB" が見つかると予想していましたが、メッセージ ID "5152455068C26B93000000000000000000000000000001E1" を読み取りました。 Q アプライ・プログラムは、予想したメッセージが見つかるまではどのメッセージも処理できません。
~~~
<browser::readNextDenseMsg> ASN7552W "Q Apply" : "ASN" : "BR00000" : Q アプライ・プログラム が、 メッセージ ID "5152455068C26B93000000000000000000000000000001BB" の受信キュー "QREP.RECVQ"、レプリケーション・マップ "SAMPLE_ASN_TO_TARGETDB_ASN" をポーリングしています。
これは、アプライ側が「次はこのメッセージIDのメッセージが来るぞ」と期待して待っていたが、違うメッセージIDが来てしまったというエラーでした。そのため２つ目のログでは期待しているメッセージIDを探し続けている状態であることがわかります。これにより、アプライが処理を進められていません。
起こりうるケースとしては以下が考えられます。
- MQキュー上でメッセージが欠落または順序不整合
- Applyの状態とキューの状態が一致していない
- 手動でキューをクリアした、またはMQメッセージ保持期間が切れた
再現してみる
ここでは手動でキューをクリアする流れで再現してみました。
前提：キャプチャーとアプライが正常に稼働していること。
①アプライ・プロセスを停止
→これによりアプライの処理がされず、ソース側から送られてきたメッセージ・キューが受信・キューに溜まり続けます。
この停止時にアプライのログに次のような出力がありました。
<browser::~browser> ASN8999D browser for queue 'QREP.RECVQ' found max msgID '51524550690C7EF40000000000000000000000000000003B' after cleaning IBMQREP_DONEMSG table on shutdown.
受信・キュー内で処理した最大のメッセージIDが"...003B"であると読み取れます。
②受信キューをクリア（送信チャネル停止→受信キュークリア→送信チャネル再度起動）
③適当なデータ更新（INSERT、UPDATE、DELETE等）
④アプライ・プロセス起動
正常であれば、③の更新内容もアプライの処理により反映されますが、このケースの場合、ログに以下のメッセージを出力してエラーとなります。
<browser::readNextDenseMsg> ASN7551E "Q Apply" : "ASN" : "BR00000" : Q アプライ・プログラ ムは、 受信キュー "QREP.RECVQ" (レプリケーション・キュー・マップ "SAMPLE_ASN_TO_TARGETDB_ASN") 上のメッセージ番号がスキップしているのを検出しました。メッセージ ID "51524550690C7EF40000000000000000000000000000003C" が見つかると予想していましたが、メッセージ ID "51524550690C7EF400000000000000000000000000000040" を読み取りました。 Q アプライ・プログラムは、予想したメッセージが見つかるまではどのメッセージも処理できません。
<browser::readNextDenseMsg> ASN7552W "Q Apply" : "ASN" : "BR00000" : Q アプライ・プログラ ムが、 メッセージ ID "51524550690C7EF40000000000000000000000000000003C" の受信キュー "QREP.RECVQ"、レプリケーション・マップ "SAMPLE_ASN_TO_TARGETDB_ASN" をポーリングしています。
想定した結果と同じになりました。確かに①の停止時にメッセージID"...003B"まで処理したということでしたので、次は"...003C"が来るというのは予想がつきます。
そして、②でキュークリアしてしまったため、"...003C"のメッセージ・キューは削除されて、アプライはエラーとなり、処理が停止してしまいます。
対応例
この状況になってしまった場合は以下の対応が考えられます。
対応①：フルリフレッシュ
MQメッセージ・キューが失われたことにより、ソース-ターゲット表間で不整合の状態になるため、すべてのソース・データを使用してターゲット表を再ロード（フルリフレッシュ）することにより同期させます。
対応②：キュー削除＆コールドスタート
QREPのプロセスを停止し、滞留しているキューを削除(clear)、キャプチャーをコールドスタートさせます。
注意
ロストした未処理のメッセージはスキップされてしまうため、データの不整合が発生する可能性があります。
対応③：LSN番号を使用して、過去の指定したポイントから再読み込みを実施
ログ内の再読み取りを開始するポイントを指定し、キャプチャー・プログラムを再始動させます。※ただし、指定する位置のDb2ログ自体が既に無い場合は不可能
キャプチャー・プログラム開始時のオプションとして以下を指定します。
maxcmtseq
lsn
公式の手順を参考にして、流れを整理しました。
-
キャプチャー・プログラムを停止させる
-
エラー前の一番最後にターゲットで適用されたトランザクションのコミット・タイム・スタンプを入手
ターゲットのIBMQREP_APPLYMON 表の OLDEST_COMMIT_LSN の値を確認します。
例として下図の場合、OLDEST_COMMIT_LSN が"...8648B"（黄色部分）より前のトランザクションは適用済みということになるので、およそ20:45以前のポイントから再開すればよいと考えます。
-
キャプチャーを再始動するポイントを指定
ソースのIBMQREP_CAPMON 表から RESTART_SEQ の値を確認します。（緑色部分）
下図の例の場合、20:45より少し余裕をもった時間に（10分ほど）遡る RESTART_SEQ を確認します。
※必要以上に遡った時間としても、ログの読み取り時間以外に影響はありません。
-
受信・キューをクリアする
アプライが起動していれば、アプライを停止し、送信チャネルを停止して滞留している受信・キューをクリアしておきます。
送信チャネルを再開させてアプライを起動させておきます。 -
キャプチャー・プログラムを起動する
maxcmtseqに"２"で確認したOLDEST_COMMIT_LSNを、lsnに"３"で確認したRESTART_SEQを指定します。
asnqcap capture_server=SAMPLE capture_schema=ASN logstdout=Y maxcmtseq=0000000000006EE2000000000008648B lsn=0000000000006ED50000000000086461
これにより、過去の指定したポイントから再読み込みされるため、ロストしてしまったメッセージ・キューの変更内容もターゲット表で取り込めます。
そしてこの時の動作としてはconflict_action=Fとなり競合エラーとはならずに、強制適用されるとのことです。