サイバーウェーブは Ruby on Railsの開発に強みがあります。開発中に不明な現象が発生したときこそ、エンジニアの腕の見せどころです。ていねいにログやスタックトレースをたどり、推論と検証を繰り返して、的確に原因の所在を突きとめます。
ログやスタックトレース、エラーメッセージは英語の羅列のため、プログラミングをはじめて日が浅い方はつい「うっ」となって、よく読まずにやみくもに原因を探そうとしがちです。ベテランのエンジニアほど、まずは目の前の「システムが問題だと言っていること」をしっかりと読み込みます。
じっさいに私が取り組んだ事例を例にして、エンジニアの基本スキルとしてログやスタックトレース、エラーメッセージからすばやく原因を突き止める手順を紹介します。
ログを調査するときのファイルとコマンド
不明な現象に遭遇したのは、サイバーウェーブの自社プロダクトである「VALUE KIT」と外部の他社サービスを連携させようと新機能を開発していたときでした。「ユーザーがトランザクションをキャンセルすると、キャンセルリクエストが多重送信されてしまうことがある」という現象でした。
今回の調査では「VALUE KIT」が出力するふたつのログを頼りにしました。
- 「VALUE KIT」と外部の他社サービスの通信ログ
- Ruby on Railsのログ
コマンドは下記の3つを使いました。
| scp | ログファイルを別のサーバーから手元のフォルダへコピーする。 |
| grep | テキストファイルの文字列を検索する。 |
| zgrep | 圧縮されたファイルを解凍せずに文字列を検索する。ローテートされて圧縮されたログを調査するときはgrepではなくzgrepを使う。 |
手順1：発生している現象を整理し、原因はどのログを調査すればわかりそうかを特定する
他社の外部サービスへのつなぎこみでぶつかったのは「トランザクションをキャンセルできなかった」というアラートでした。まずはその現象が発生したときに、詳細はどのログに記録されるのかを特定します。開発環境を操作して現象を再現し、ログがどのように残るかを確認します。
検証したところ、以下のふたつのログに情報が残っていそうだと当たりをつけました。
- 「VALUE KIT」と外部の他社サービスの通信ログ
- Ruby on Railsのログ
ポイントは、手元で現象をくりかえし再現できるように、再現手順を特定すること。そしてその結果どのようなログが出力されるのかを特定することです。今回の現象は、ユーザーがトランザクションのキャンセルボタンをクリックしたときに再現されることを特定しました。そこで、他社サービスへの接続を試行するコマンドの文字列を検索することで該当箇所を調べられるーと推測しました。
また、この現象がほかにも影響を及ぼしていないかの調査も大切です。今回はトランザクションが意図せず多重でキャンセルされた結果、他社サービスが記憶しているデータの個数と、VALUE KITが記憶しているデータの個数が不一致になってしまう、という現象を把握しました。
手順2：問題を含むログを抽出し、調査しやすいように整形する
ログファイルを手元の作業フォルダにコピーし、grepまたはzgrepでキャンセルリクエストのログを抽出します。
zgrep -e '"transaction failed"' ./**/{{ Path to log file }}.log*.gz > cancel_logs.txt※`transaction failed
`は、トランザクションがキャンセルされたときに外部サービスが返してくるキーワード
`transaction failed`キーワードは外部サービスでの処理が失敗したことを示すのみです。原因を特定するためのポイントは、該当のログの前後も見ることです。今回は、外部サービスへのPOSTリクエストの成否を示すログだけでなく、続く行にあるPOSTメソッドの引数のログにヒントがありました。
エラーが発生するとき、ログには引数のプロパティ`authenticity_token`が同じ値をもつリクエストが複数存在していました。`authenticity_token`とは、Ruby on RailsがCSRF対策として自動生成するトークンを指します。
`authenticity_token`は画面を表示し直すたびに変わります。ところが同じ`authenticity_token`の値をもつログが、立て続けに記録されていました。つまり画面を更新していないのにいくつものリクエストが発行されています。`authenticity_token`が同じ値であるということは、ユーザーがリクエストの結果を待たずに同じリクエストを再送している。原因として有力候補なのは、ユーザーがリクエスト送信後に、さらに送信ボタンを連打できてしまっている可能性です。
仮説の正誤を確認するためには、`transaction failed`に続く数行を合わせて取得することで、多重リクエストしているかどうかを調べることができます。
ログを取り出しても、多くの場合は1行の長いテキストデータです。そのままだと読みづらく、原因を見つけづらい。そこで取り出したログを、テキストエディタで正規表現を用いて整形します。
———–
整形する正規表現（Regex）
.*"status":"([^"]*)".+"merrMsg":"([^"]*)".+"transactionId":"([^"]*)".*整形する正規表現（置換後のテンプレート）
$3t$1t$2手順3：スプレッドシートで開いてデータを分析する
ログの抽出と整形が終わったら、より詳しく調べやすいよう、Google スプレッドシートやMicrosoft Excelで開きます。整形したデータをさらにカンマ区切りまたはタブ区切りに加工して開きます。
カンマ区切りにするかタブ区切りにするかの判断は、私はタブ区切りにすることが多いです。Webブラウザの入力フォームにおいて、カンマはユーザーが入力しやすい文字であるのに対して、タブは入力される可能性が低いためです。カンマが入力された行が混入した場合、ログの一部だけスプレッドシートのカラムが合わなくなってしまい、調査に戸惑うことがあるためです。
今回はGoogle スプレッドシートで開き、VLOOKUPやピボットテーブルを用いてより詳しい現象を把握します。トランザクションが多重キャンセルされたとき、他社サービスの記憶するデータ個数とVALUE KITの記憶するデータ個数を突き合わせ、差分がどのタイミングでどのように発生するかを調べました。
手順4：プログラムを修正する
原因が正しく特定できたら、問題を解決するようにプログラムを修正します。そして正しく修正できた試験をします。
調査方法の引き出しを広くもっておこう
ログやスタックトレース、エラーメッセージから原因をスマートに突き止める手法は、エンジニアが基本として身につけておくべきスキルです。もちろん、この記事で紹介した調査方法はあくまでも一例です。調査手順や方法は、プロジェクトやシステム構成、技術スタックの状況によりさまざまです。自分と会社にノウハウを蓄積し、いくつも引き出しをもって、柔軟に課題を解決できるようにしていきましょう。
