外部サービスからのデータ取り込み処理は二度走る

この記事は、Magic Moment Advent Calendar 2023 24日目の記事です。

こんにちは、Magic Moment で Software Engineer をやっている onishi です。
本記事では、実在の問い合わせチケットの調査をもとに問い合わせが来た際のエンジニアの調査の流れをまとめさせていただこうと思います。

MMPというサービスについて

Magic Moment Playbook(以下MMPと称する)は営業組織の出力を最大化するSaaSです。
営業活動量を圧倒的に増やし、全ての営業活動から優れた顧客体験を生み出すことができます。

弊社のセールスオペレーションクラウドMagic Moment Playbookでは、サービス間で大量の営業データをやりとりする処理を行うシーンがあります。
今回はバッチ処理で大量のデータを取り込む処理の話をします。

エンタープライズ企業のお客様においては日々多くのスタッフの入力により大量のレコードが更新されることも珍しくありません。
当然その更新情報は時間差を置かずに連携先のサービスにも取り込まれる必要があり、それはMMPもまた例外ではありません。
バッチ処理で連携先サービスから更新された情報を取り込む必要があります。
MMPでは Cloud Run をベースとした **Event-Driven Architecture (EDA) ** による並列分散処理により大量の取り込みデータ処理を高速に行うことができます。
詳細は先日のAdventCalendar2023投稿記事Cloud Run × Event-Driven Architecture の並列分散処理によるデータ処理高速化への取り組みをご覧ください。

問い合わせチケットが来た背景

お客様より一部のデータが重複しているという連絡がありました。
データそのものは手動で削除されましたが、同様の問題が再発しないよう原因調査をする必要があります。
お客様から報告を受けたCustomer Successから問い合わせチケットが上がり、プロダクトマネージャから高優先度の調査チケットとしてエンジニアチームに引き継がれました。

事象

特定のお客様の環境である種類のレコードが複数件重複していた。
作成時刻はほぼ同時だった。

影響範囲

お客様：1社
範囲：レコード複数件が重複
時刻：2023-10-05 10:35~10:36の間にレコードが作成された。

調査の開始

この日出勤していたエンジニアのonishiが2次調査からチケットを引き継ぎました。

この手の問い合わせチケットの調査とはシャーロック・ホームズの推理のようなものです。
可能性の中から起こらなかったことを全て取り除いた時、真実だけが残ります。

1次調査の開始

前日の1次調査でいくつかのことが分かりました。
ひとつは重複が発生していた対象は問い合わせのあったお客様のレコードだけです。
今のところ同様の事象は他にありません。

もうひとつは回収されたログから問題が起きた時刻にAPI経由でサービス間のリクエストが同じ内容で2回叩かれていることが分かりました。
これは手がかりになります。
通常検索クエリはバッチを実行するJobに対して1度の実行で1度しか叩かれません。
2度走ったということはその前に何かが起きていたということを表しています。

2次調査の開始

サービス間リクエストの二重実行の手がかりを中心に調査が進められました。

最初に疑われたのはバッチを実行するJobレコードの二重生成です。
バッチを実行するJobレコードはデータ取り込みが有効なMMPのObjectと連携先のObjectの連携設定1つにつき、バッチ実行ごとに1つ作られるジョブです。
今回の場合10:35のバッチ実行で作られた「連携先サービスのデータ」と「MMPのエンゲージメント」の連携設定に紐づいたバッチを実行するJobレコードが疑われます。
エンゲージメントはMMPにおけるセールスとお客様との関係を表す最も根幹的なデータ概念であり、それをシステム上で実装したレコードを意味します。

もしDB上で10:35ごろ、「連携先サービスのデータ」と「MMPのエンゲージメント」の連携設定の連携設定に対して1つではなく2つのバッチを実行するJobレコードが作られていたなら該当レコードを作る以前の処理が疑われなければなりません。
調査のため本番DBに対してSQLを叩き、本番のデータを調査します。
結果、バッチを実行するJobレコードは1件だけでした。

つまりバッチを実行するJobレコードを作ってから、データ展開処理が起動して連携先サービスに対して検索クエリを叩くまでの間に問題があることになります。
この図で言う右上のあたりが疑われる箇所です。

次に調査すべきはデータ展開処理です。
データ展開処理はバッチを実行するJobレコード1件につき連携先サービスに対して検索クエリを叩き、戻ってきた検索クエリの結果を分割単位件数ごとに処理の実行単位である分散処理Jobレコードに分割する処理です。

本来であればバッチを実行するJobレコード1件につき分散処理Jobレコードが生成されるはずです。
その数は今回本来連携先サービスから取り込まれるべきだった件数を分割単位件数(1回あたりの実行件数)により割った数で推計できます。
調査のため本番DBに対してSQLを叩きます。
結果、分散処理レコードは本来生成されるべき件数の2倍でした。
やはりここで異常が起きていたことが分かります。
二重に分散処理レコードが作られてしまったため、それ以降の処理も二重に走った結果エンゲージメントのレコードが重複して取り込まれてしまったのです。
なぜ二重にエンゲージメントのレコードが重複取り込みされたのかは分かりました。

問題はなぜそれが起きたか、なぜ本来1度だけ呼ばれるはずのデータ展開処理が2度呼ばれ、重複してエンゲージメントのレコードが取り込まれたのでしょうか？

Pub/Sub処理(非同期メッセージ送信)を呼び出す関数であるデータ展開処理が2度呼ばれた可能性も考えられます。
Pub/SubはGoogleが作ったサービス間をつなぐ非同期のスケーラブルなメッセージングサービスです。
GCPにおいてマイクロサービス間の通信に広く使われています。

非同期メッセージ送信を呼び出すデータ展開処理が、呼び出し元のデータ展開起動処理から二重に呼ばれたのでしょうか？
つまり呼び出し元側のコードの書き方や条件判定が悪く、何らかの条件を満たすとループ処理によって先ほどのデータ展開起動処理の呼び出しを2回行なってしまったのかもしれません。
Cloud TraceのTraceエクスプローラを使えばデータ展開起動処理が本当に2回呼ばれたか分かるはずです。
Cloud TraceはGCPのサービスの1つでtrace_idによりリクエストがどのようにアプリケーションの中で処理されていったかを追うことができます。
調査のため先ほどの検索クエリを二度叩いたログエクスプローラからtrace_idを取得します。
次にTraceエクスプローラからtrace_idをもとにデータ展開起動処理が2回呼ばれたかを調べてみます。
データ展開起動処理までは1度しか呼ばれず、データ展開処理の非同期メッセージ送信がなぜか2度呼ばれていることが分かりました。
これで異常が起きた箇所を絞り込むことができました。

ではデータ展開起動処理関数内でデータ展開処理を呼ぶときの非同期メッセージ送信処理の呼び出しロジックが悪いのでしょうか？
コードの書き方や条件判定が悪く、何らかの条件を満たすとループ処理によって非同期メッセージ送信処理の呼び出しを2回行なってしまうのかもしれません。
調査のため該当部分のコードを調べてみました。
結果は問題ありませんでした。
クリーンアーキテクチャに基づいて設計されたMMPのコードはシンプルかつ堅牢で、意図しない二重実行を引き起こすような作りにはなっていません。

調査のためアプリケーションのコードを調べたところあることが分かります。
MMPの並列分散による高速取込処理、特にデータ展開処理呼び出しの部分の構成は非常にシンプルです。
つまり疑うべき場所は非同期メッセージ送信呼び出し以外にありません。容疑者が絞られたということです。
しかしは非同期メッセージ送信呼び出し処理もまた、ロジックがシンプルで意図しない二重実行を引き起こすような複雑なロジックはありませんでした。

では非同期メッセージ送信(Pub/Sub)の再送処理が問題を起こしたという可能性はどうでしょうか？
非同期メッセージ送信は再送処理が組み込まれています。
デフォルトでは600秒の間隔で待機し、受け取りがないと判断すると再度同じ内容を送信します。
600秒待機して何らかの理由で送信に失敗したと判断した非同期メッセージ送信は実際には受信側で処理が成功したにもかかわらずもう一度送信したのかもしれません。
それは検索クエリの二重実行のログが600秒程度の間隔が空いているか調べれば分かるはずです。
しかし二重実行の間隔は2秒でした。
この原因も違います。

ではなぜ2秒間隔でデータ展開処理は二重に呼び出されたのでしょうか？

調査の行き詰まり

「全く分かりません。何が何だか、コードとデータベースで調べるべきことは全部調べたんですが……」
エンジニアのonishiはなぜ原因を突き止められないのでしょう？
ランチに食べた重いレバノン料理が眠気を誘い集中力を乱したのでしょうか？
「しかしいったい何故なんですか！？｣

あるいはコードやデータベース以外に見落としているところがあるのでしょうか？

ここでテックリードのmiyake-sanがヘルプに入ります。
前述の並列分散処理の深い知見を持つmiyake-sanはたちまちのうちにある手がかりを掴みます。
Pub/Subには再送期限を待たずして再送されることがあります。

2秒の間隔で二重実行されたログの説明もこれでつきます。
非同期処理であるPub/Subは基本的にAt least Once, つまり最低1度は非同期でデータを送ることを保証していますが再送期限より前の段階で2回以上送ることもあり得るということです。

ついに原因が判明しました。
原因が分かったあとにするべきことはプロダクトマネージャへの報告と対応策の検討です。

対応策

Pub/Sub ライブラリの中に二重実行を防ぐ仕組みがないかを調べました。
Exactly-once deliveryオプションが存在します。
厳密に1度だけ実行するようになることで今回のような非同期メッセージ送信の二重実行を防ぐオプションです。
しかしExactly-once deliveryオプションはPullでのみ使えます。今回のようなPushでは使えません。

そこで並列分散の実行を管理するバッチを実行するJobレコードモデルに「データ展開処理で実際に展開処理が始まったか」というステータスを付与することで二重実行を防止する方針が決まりました。
このステータスが処理開始済みになっているかのチェックを入れれば今回のような二重起動が起きることはなくなるでしょう。

対応チケットを作った上でプロダクトマネージャの判断により優先度がつけられ、バックログに積まれました。
次スプリント以降優先度に応じて対応される予定です。

今日もMMPは大量のレコードを連携先サービスから取り込んでいます。