皆さん、こんにちは。
技術開発部のOです。
普段はWebエンジニアとしてフロントエンドやサーバーサイドの開発に携わっています。
この記事では、過去に対応したあるバグの調査・解決を通してアプリケーション開発においてログを確認すること・ログを保存しておくことの重要さをお伝えできればと思います。
稀に起きている静かな不具合
早速本題です。
某日、SPIDERPLUSのある機能が時折期待した動作をしなくなりました。
不具合を引き起こすデータでも100%再現できる訳ではなく、その時々によって問題なく動いたり想定外の動きをしたりと、ランダムに結果が変化するバグです。
ログを確認してもエラーが起きているわけではなく、また手元でもなかなか再現せず、手がかりがつかみにくい状況でした。
どう対応したか
検証環境で再現するデータが発見される
様々な状況で試しているうちに同様の事象が発生しやすいケースが運良く発見されました。
問題を引き起こしている箇所を絞り込む
該当のバグはある判定処理の結果が期待していない値になっていた事で引き起こされていました。
ただ、バグ発生後にデータベースの値を確認しても判定処理が対象としている値は問題ないように見え、最終的にデータベースに保存されている値ではなくそこまでの状態遷移の間で何か想定していない動作をしている可能性が考えられました。
ログを整理し、仮説を立てる
そこで、まずその判定処理にデバッグコードを埋め込み、検証環境上でバグが再現した際に該当機能に関連するイベントを複数コンテナのアプリケーションログ、データベースから全て取得し、時系列順に並べて起こった事実を整理しました。
そして発生した事実を確認したところ「A→B→Cと処理が動くはずがA→C→Bと動いた」
仮説が浮かび上がったため裏付けを取るデバッグコードを更に追加。
結果的には複数の非同期処理の終了タイミング次第になっていたものの、ほとんど起きないために(また起きてもエラーが起きないために)これまで気づかずにいた部分が原因でした。
無事仮説通りに原因が特定でき、修正リリースをして解決いたしました。
最後に
ログは情報の宝庫
ログは見慣れてない人からすると「ウッ」と拒否反応が出てしまうかもしれませんが、情報の宝庫です。
1つ1つ地道に確認していくと答えが見えてくることもあるので、根気よく確認していくのが大事かなと思います。
その際、ログを見る前に「この辺りが原因なのでは」と考えが浮かぶかもしれませんが、誤った先入観となってしまう恐れもあります。
そのため、一旦推測は脇に置いておいて事実だけを確認するのがおすすめです。
（「勘が働いて」調査を素早く進められることもあるのでこの辺りの塩梅は難しい所がありますが、あくまで事実が先にあってそれを読み解く時に該当アプリケーションに対する知識などが役に立つ、位の感覚でしょうか）
転ばぬ先のログ
また、いざ調査しようとしたときに困らないよう、普段からログ出力のコードを埋め込んでおきましょう。
HTTPリクエストやエラーの情報はもちろんのこと、何がどこまで進んだかの「正常ログ」も残しておくと調査の時に役立ちます。
ログが多すぎてノイズになったりリソースを圧迫したりすることはありますが、後から間引くことは出来てもログ出力していなかった時間の情報を後から得るのは困難です。
特に今回のように手元での再現が難しい場合は本番環境での試行錯誤を避けるためにもあらかじめいれておくことが重要でした。
なので、個人的には判断に迷う箇所や気になる箇所があったらログを入れる、位にしてしまって良いかなと思っています。
この記事が皆さんの参考になれば幸いです。
ところで、スパイダープラスでは仲間を募集中です。
スパイダープラスにちょっと興味が出てきたなという方がいらっしゃったらお気軽にご連絡ください。
お読みいただき、ありがとうございました。
