経緯
ある日、上長から、先輩がやっているシステム移行のバグをこたうち君が直して欲しい。という依頼を受けました。そして、3年目に入ったぐらいの若造だった私は、はぇーそうですかーと思って、とりあえず言われた内容だし、やるかー。と言って、やり始めた結果、ひどい目にあいました。
移行バグの状況
あまり詳しくはかけないのですが、移行対象者が1,000万人おり、そのうちデータの移行に関してバグが発生した人数が1万人いました。
バグの発生率が0.1%で、その数が1万人いるわけです。これは、よくよく考えると厳しくて、99.9%の移行が完了した、残り0.1%がバグっているわけです。なので、移行プログラムを確認しても。明らかなミスを発見することは、ほぼほぼできません。したがって、どういうバグにより移行が阻害されているかというと、例えば、移行前のシステムが、極一定期間、コード上のバグでトランザクションを貼り忘れていたためにデータベースの一貫性が壊れていた。のような、異常なまでのエッジケースです。そのようなバグが1万件ある。というような状況です。これが、どんだけキツイ状況か？ということは、想像に難くないと思います。
バグの系統分類
データの移行は、ユーザー毎に行っており、1ユーザーにつき、1つのログが出力されるような仕組みになっていました。最初、私は手あたり次第バグを直す。ということをしていました。移行がエラーになったログをとりあえず1つ取り出し、それを解析して、バグの解析を行い、修正して、もう一度移行する。ということを繰り返しました。しかし、これは進捗が芳しくありませんでした。
そこで、私は、手あたり次第直すのはやめ、ログを広域的に解析することを始めました。とりあえずErrorという文字列をログ上で調べ、そErrorという文字列の付近にある"原因と思われる文言"を見つける。という作業を行い、それによりエラーの系統分類を行いました。
やっていること自体は簡単で、"UserNotFound"というエラーの原因であれば、それを"grep -l"で該当するエラーログのファイルを見つけてきました。
grep -l "UserNotFound" *.log > UserNotFound.csv
grep -l "FileNotFound" *.log > FileNotFound.csv
grep -l "Invalid Username" *.log > InvalidUsername.csv
多いバグは直すべきバグか？
前節で書いたような、簡易的なバグの系統分類を行いました。(以下の表は実データではなく例です)
| バグの種類 | 該当ファイル数 |
|---|---|
| UserNotFound | 2,420 |
| FileNotFound | 2,520 |
| InvalidUsername | 1,620 |
| その他 | 5,700 |
こう見たとき、"FileNotFound"のバグが一番多い。と分かりました。そうすると、"FileNotFound"のバグを修正すると、多くの移行エラーが解消され、効率よく移行が進むと考えられます。しかし、現実問題として、それほど直りませんでした。
"簡単なバグ"とは何か？
前節では、バグの発生頻度が高いものから修正していくとアプローチをしていきましたが、実際問題それほどうまくいきませんでした。端的に、なぜ失敗したか。というと、"バグが直らなかった"からです。仮に"FileNotFound"のバグを直そうとしたとき、2,520個あるログファイルから、ランダムに1つとりだし、どの部分でエラーになっているのかを細かく見ていきます。それで、バグの原因を特定し、直す。という極シンプルなアプローチをするわけですが、「このバグの原因を特定する」ということが、そもそも難しかった。ということです。先にも書いたように、99.9%は移行に成功しているプログラムなので、ほぼバグらしきバグは見つからないことが多いです。そのため、データベースの不整合があり、複数の問題が同時に発生するような、移行プログラムを見るだけでは分からないケースが多かったです。そのため、バグの修正は困難を極めました。
そこで、"バグの原因が簡単で、発生頻度が高いものから直す"ということを考えました。では、 "バグの原因が簡単である"とは、現実的には、どのように判定するのか？というと、"バグの原因が重複していない"と捉えました。
今、UserNotFound,FileNotFound,InvalidUsernameのバグに注目しています。この時、UserNotFoundのバグに該当しつつも、FileNotFoundにも該当しているログというものが存在します。そういった、複数のバグに該当しているログは、原因の解析が難しくなる。と考えました。そのため、そういった、 バグが重複している部分は除外し、単一の原因でバグが発生していると思われるログのうち、一番量の多いものログを抽出し、解析し、直す。 というアプローチをとりました。
そのようなバグの原因とエラーの件数をベン図に表してみました。(ベン図内の数字は該当するログの数です)
この場合、UserNotFoundとFileNotFound両方に該当するログは、520(220+300)件です。同様に、UserNotFoundとInvalidUsername両方に該当するログは420(120+300)件です。"簡単なバグ"と言える領域、単一の原因で引き起こされていると思われる移行エラーは、数字に下線の引いてある領域になります(UserNotFoundであれば1,800件の領域、FileNotFoundであれば1,300件の領域)。この簡単なバグのうち、一番多いものから直す。としているので、UserNotFoundの1,800件のログ(★印)から解析します。この方法が一番うまくいきました。
なぜ効率的にバグを直せるのか？
この方法が私の中では一番良いアプローチでした。その原因を一言で話すと、
バグの解析に一番時間がかかるため、その時間を最小にした
ということでした。
最初におこなった、「該当するものが多いものから直す」というアプローチだと、FileNotFoundに該当したエラーを調べるとします。当たり前の話をしますが、2,520件のログを全て確認することはできないため、ランダムに1つのログを確認することになります。そうすると、FileNotFoundにおいて、FileNotFoundのみが原因の単純なログは1,300個、全体が2,520個なので、約51%の確率で調査しやすいログを引き当てることが出来ます。これは運が良いパターンですが、これは確率的な挙動でしかなくて、分類していれば、FileNotFoundの中で、原因が出来るだけ単純な1,300個を簡単に選ぶことが出来ます。そのため、分類して、重複を調査しておくと、調査難易度の低いバグだけを選ぶことが出来ます。同様に分類したメリットとして、原因が単純なログの中で、一番量の多いものがリストアップ出来たため、効率的にバグの修正が可能になりました。
また、副次的なメリットとして、バグの調査が簡単になる。というメリットがあります。例えば、UserNotFoundというエラーは、InvalidUserStatusという内容が原因で出たログだとします。これをパターン1とします。しかし、同じUserNotFoundでも、パターン2では、DatabaseConnectionTimeOutが発生したために、InvalidUserStatusが起こり、そのためにUserNotFoundが起こったとします。この時、InvalidUserStatusのバグを直した場合、パターン1のUserNotFoundは直りますが、パターン2のUserNotFoundは直りません。しかし、移行を再実行すると、パターン2のエラーメッセージは、DatabaseConnetionTimeoutの様に変化し、バグの原因が追いやすくなる場合があります。
これは、この手段に特有の事象ではありません。しかし、このような厄介なバグを追う際には意識しておいた方がよいことなので書いておきます。厄介なバグは、厄介な原因が多重で絡んでいることが多いです。そのため、簡単で分かりやすいバグを先んじて直し、問題の原因の重複を戦略的に減らしていくことで、厄介なバグの調査の難易度を減らしておくと、あとが楽になってきます。この簡単に直せるバグを先んじて特定できる。というのは、この手法のメリットといえます。
大規模な移行バグを修正するための戦術
以上の内容を端的にまとめると以下の様になります。
- 移行を行い、ログを収集する
- ログからエラーの文言を調べる
- エラーに特有の文言を発見する(UserNotFound,FileNotFound,InvalidUsername...)
- ログをエラーに特有の文言で分類する
- それぞれのエラーの分類が、どれだけ重複をしているかを調べる
- 分類した中で、分類が重複していないバグの量が最大のものを選ぶ(UserNotFound)
- 重複していないバグの量が最大のものから、ログを選び、バグの調査を行う(UserNotFoundの1800件に該当するログ)
- バグを修正する。
- 1.へ戻る。
戦術のポイント
多分一番難しいのが、
"エラーに特有の文言を発見する"
の工程です。何を選べばいいのか？どれくらいの量が該当すればいいのか？という疑問があると思います。個人的には全体のログの40%未満のログが該当する特有の文言を見つけることが出来ればよいと思います。
悪い例で言うと、例えば、"Error"という文言だと、あまりにも該当するログが広すぎるため、あまり意味がないでしょう。一方で、"kotauchisunsun is Invalid User"のような固有名詞を含めた文言であると、これは該当行が少なすぎるため、バグ解消の効率が悪くなります。そのため、「ちょうどいい調査サイズの特有の文言を見つける」ことがキーポイントとなってきます。
もう1つは、
"移行のコストが低いこと"
です。これは、移行したログからいかに効率的にバグを修正するか？という技術です。そのため、移行のコストが軽くないと効果を発揮しません。例えば、1週間に1度しか移行できず、試行回数が稼げないのであれば、おそらく効果を発揮しにくい手法となります。
終わりに
この移行バグを直したのは、もう5年ほど前の話ですが、当時は大変だった記憶があります。厄介なバグを直してくれ。というオーダーは私には結構ある話でした。だから、自分に対する自信から、自分だったら直せるだろう。と高をくくっていたきらいがあります。しかし、「とりあえずこの方法でいこう」と思った方法がことごとくダメだったため、それに対して、色々と趣向を凝らした記憶があります。
この話の難しいポイントは２つあって、その1つは、そもそもバグの発生率が0.1%しかないことです。これは非常に辛く、表面的にコードを読んでいるだけでは全然原因究明が上手くいきませんでした。しかも、その数が1万件というあたりも大変で、これは全部をローラーするには多すぎるため、効率が非常に悪かったです。もう1つのポイントは、そのような移行ノウハウがないこと。当たり前ですが、システム移行というのは、その会社に特有の事象が絡まりあい、抽象的に取り扱える手段が少ない話だと思います。そのため、システム移行のノウハウは社内に閉じたものが多く、あまり外の知見を活かせるものも少ないため、インターネット上に知識が共有されていません。そのような、移行に関する知見、バグの管理に関する知見がない。ということに気づいた後、何とかひねり出した方法がこれでした。
当時の上長からは、いつ終わるんだ。はやく終わらせろ。としか言われず、特に有用な協力をもらわなかったので、なんだこいつ。じゃあお前が直せよ。と思いながら作業をした記憶がよみがえってきました。そんな中で、今から考えると良くこんな方法を思いついたな。と思いました。
移行のような、同時多発的に多くのバグが出るようなケースは、バグを修正するのがとても難しいように思います。それは、同時多発的に起こるバグの中で、どのバグを選ぶことで、全体の効率よくバグが修正できるか。ということです。この手法がそういったときの一助になれば幸いです。