スレッドが競合した時のこと

今日は備忘録。

先日の業務中、「複数のプロセスが同時に一つのメソッドを通ったことが原因でデータがおかしなことになる」というバグを発見しました。
単純な例を出すとこんな感じでしょうか。

2018年1月25日0時30分時点で太郎さんのM銀行の口座の残高はちょうど100万円です。
太郎さんはA社とB社の2社から給料をもらっており、給料日はいずれも25日です。
1月25日1時00分ちょうどにA社から50万円の給与が振り込まれました。
と、全く同じタイミングでB社から70万円の給与が振り込まれました。
太郎さんの口座の残高は100万+50万+70万=220万円となるはずです。
ところが、実際の残高は150万円となっています。
おかしいですね…

無論、銀行のシステムがこんなポンコツ実装なはずはないですが、「スレッドセーフではない」というのはこういうことです。
次に実際に目撃したバグの状況を抽象的に書いてみます。

サイトの会員がログインし、トップ画面に入ってきました。
トップ画面では、会員に紐づく情報を取得するために2つのリクエストが飛びます。仮に/getと/gainの2つとします。
/getにアクセスするとGetクラスのAメソッドを通り、その中でCalledクラスのMメソッドを呼びます。
/gainにアクセスするとGainクラスのBメソッドを通り、その中でCalledクラスのMメソッドを呼びます。
このMメソッドは、会員に紐づく1つのレコードをDBから取得して返します。ただし、まだ会員に紐づくレコードが存在しない場合、新しくレコードを生成してからそのレコードを返します。
今回、会員に紐づくレコードが存在しない状態で2つのリクエストがほぼ同時に飛び、Mメソッドが1つしか存在してはいけないはずのレコードを2つ作ってしまっていました。
2つのプロセスがMメソッドを数十ミリ秒以内の絶妙なタイミングで通過した場合のみ発生する稀なバグでした。
幸い実害はなかったのですが、本来1件のレコードを返すはずのメソッドが2件のレコードを返してくるせいでフレームワークが大量にwarnを出していました。

過去の履歴を見ると、GetクラスとCalledクラスが同時に誕生し、その後数年を経てからGainクラスが実装された結果、こんなことが起こったようです。
1人の会員につき1つのレコードしか持たないのだから、DBで会員番号のカラムにunique制約を付けておけばいいのですが、そもそも同時にリクエストが飛ぶことは想定していなかったようです。まあ流石に仕方ない気もします。

最初はMメソッドにsynchronizedを付与して排他制御にすれば同時にレコードを更新することは防げるのでは?と思いましたが、リクエストが分かれているせいで別々にインスタンスを作ってクエリを実行してしまうので意味がありません。

そこで、DBに残ってしまった重複データを削除してから会員番号のカラムにunique制約を付けて、Mメソッドの中で例外をcatchし、そこでもう一度Mメソッドを通るようにしようと考えました。
が、そもそも同じ画面で1つの情報を取るために2つのリクエストを投げる実装そのものがよろしくないのです。投げるリクエストを1つに絞るために実装を改めるということで決着しました。

改めてここまでの文章を読み返してみるとあっさり対策できたような感じに見えますが、原因箇所を具体的に書いてくれないフレームワークのwarnログと大量のアクセスログを突合し、原因箇所を見つけるまでにはかなりの時間がかかりました。
おまけに「複数スレッドが1つのメソッドを同時に通った場合」と言っても実際テストしてみると20回に1回くらいしか起こらないもので、再現するのになかなか苦労しました。
そういうわけで、いつか同じようなことに出くわしたときに思い出せるよう、備忘録を書いたのでした。