こちらの記事はDIVXアドベントカレンダー2023の11日目の記事です。

はじめに

こんにちは株式会社divxの西辺です。
今回のテーマは「ログの重要性について解像度をあげて理解してみる」です。
開発や保守運用のタスクを行う際に必要に応じてログを確認したり、デバッグをしてデータの流れを追ったり行ってるかと思います。
当初自分自身ログはなんとなくエラー等を確認して理解できるレベル感でした。
しかし現在ログやシステム調査をする機会に恵まれ,よりログに触れ合う機会が多くなり、”ログって意外と奥深い”と感じたため皆さんへ共有させていただければと思います。
また最後にログと結びつきが深いデバッグの効率的な実行方法もまとめてみましたのでご参考になればと思います。

ログにはどんな情報が書かれているのか

自分自身調査タスクを経験する前は”エラーが起きたり意図しない挙動をした際に確認する場所”と言う認識でした。
実際ログは自分が思っている以上に情報が詰まっており、エラーを見にいくだけではなく、処理のパフォーマンス情報やリクエスト情報等が載っています。これは、いわば情報の宝庫です。
まずは、そもそもログとはどのような情報が出力されるのか？から説明させてください。

Started GET "/api/v1/posts/7" for 172.24.0.1 at 2023-11-27 08:47:14 +0900
Processing by Api::V1::PostsController#show as HTML
Parameters: {"id"=>"7"}
[1m[36mPost Load (1.3ms)[0m [1m[34mSELECT posts.* FROM posts WHERE posts.id = 7 LIMIT 1[0m
↳ app/controllers/api/v1/posts_controller.rb:51:in set_post' [1m[36mUser Load (1.2ms)[0m [1m[34mSELECTusers.* FROMusersWHEREusers.uid= 'test2@gmail.com' LIMIT 1[0m ↳ app/controllers/api/v1/posts_controller.rb:20:inshow'
[1m[36mUser Load (0.9ms)[0m [1m[34mSELECT users.* FROM users WHERE users.id = 7 LIMIT 1[0m
Completed 200 OK in 9ms (Views: 0.1ms | ActiveRecord: 3.4ms | Allocations: 2687)

上記は特にログの出力設定をいじっていないRuby on Railsのデフォルトのログ出力結果です。
ログの見方を簡易的ですがカテゴリー・該当箇所・概要・調査時の利用方法にまとめてみました。

HTTPメソッド及びパスやパラメーター・ステータスコードは馴染みがありましたがその他の項目についてはあまり注意深くみていませんでした。
馴染みがないSQLクエリと処理にかかった時間の箇所をより具体的にみていきます。
・SQLクエリ
RailsではActiveRecordの機能によりモデルへのアクセスをよしなに行ってくれる特徴があり、実際にどのようなクエリが発行されているのかが見えにくい部分があるかと思います。
そのためログに吐き出されるクエリを見ることで想定通りの挙動をしているのか？ということを確認することができます。
例えば記事の個別情報を取得するために下記のように実装をしていたとします。

#コントローラー
#api/app/controllers/api/v1/posts_controller.rb
def show
is_current_user_post_owner = current_user&.id == @post.user_id
render json: @post.as_json(methods: [:formatted_created_at, :formatted_updated_at]).merge(is_current_user_post_owner: is_current_user_post_owner)
end
def set_post
@post = Post.find(params[:id])
end

問題がなければ下記のようなクエリが発行されますが、必要な条件が抜けているケースもあるのでその場合は条件を追加している実装箇所を見直すと原因追求が早くなります。

"SELECT posts.* FROM posts WHERE posts.id = 7 LIMIT 1" 

・処理にかかった時間
ここではActiveRecord: 3.4msについて注目して説明をさせていただきます。
データベースへのクエリ実行にかかった時間をミリ秒単位で示しているのですが、この部分を確認することでクエリのパフォーマンスを確認することができます。
例えば記事検索機能で一部の検索条件にてなかなか表示されないという事象があったとします。
その際に実際に実行をしてみてここの箇所確認することでクエリのパフォーマンスが問題ないかどうかという視点で見ると調査が早くなります。(該当検索条件の使用しているカラムにINDEXが貼られていないので検索が遅いなど。。)

調査タスクにおけるログ確認の問題提起

ログは処理のパフォーマンス情報やリクエスト情報等記載されている非常に便利なものです。
ただし調査時にログに頼りすぎるとかえってリスクを抱えてしまう場合があるため、ここではどのようなリスクを含んでいるのかをみていきたいと思います。

・工数的なリスク
　⚪︎前提や背景を解釈せずにログを見る可能性が高まり出戻りが起きてしまうリスクがある
　⚪︎原因はフロント側にあるなどログを見ても意味がないのに見に行って無駄に時間を費やしてしまうリスクがある
・コスト的なリスク

　⚪︎ログの監視ツールによっては余分にお金がかかってしまう
　　▪️例）AWS Athenaはスキャンされたデータ量に応じてコストがかかる(つまり条件を絞らないとお金がその分かかってしまう)

上記に2点のリスクを抱えていることを念頭に置いてログの利用方法に関して考えねばなりません。

調査タスクにおけるログの活用方法

先述したリスクを極力回避するにはログを見る箇所を絞ることが大切です。
つまり調査タスクにおいていきなり本番ログを見るのではなく仮説を立てた上であくまで証拠集めのフェーズで確認しに行くことが大切となります。
実際に自身が調査タスクを経験した上で最適だと思った手順を共有させていただければと思います。

1. 聞かれている事の前提を理解する
2. 手元の環境(開発環境)で再現をしてみる
　a. 再現性があればデバッグをしつつ調査がしやすくなります
3. 事象に対する仮説を立てる
　a. 仮説はMECEに考えて常に仮説を過信しない
4. ログやデバッグを利用して証拠を集めていく

4の時点でおおよその原因箇所が狭まるので、ログの確認が必要な場合必要な情報だけを見にいくと言う流れになります。
では実際に具体的な事象の例を基にもう少し解像度を上げてみてみましょう。

具体例で見てみる

チケット販売システムにて下記の調査依頼があった際のことを例に挙げてみてみます。

11/27にチケットAが購入できないとお客様より問い合わせがあったので原因を追求していただきたい。

前提を理解する

この時点ではまだ事象の発生ケースが読めないためログを見るとしても絞り込みが難しいです。
そのため下記の内容のヒアリングを行い事象の切り分けを行います。
[事象の切り分け]
・特定のメンバーが購入できないor全員購入できない
・チケットAのみ購入できないor他のチケットも購入ができない
・チケットの購入できなかった時の状況詳細が知りたい
　⚪︎購入対象にチケットAが表示されない
　⚪︎購入ボタンを押下するとエラーが表示される

事象の切り分けを通して下記の発生ケースであることが確認が取れました。
・全員購入できない
・チケットAのみ
・購入ボタンを押下するとT001 チケットが購入できませんとエラーが表示される

手元の環境(開発環境)で再現をしてみる

・同様のチケット設定やメンバーを用意して事象の再現を試みる
　⚪︎再現できた

事象に対する仮説を立てる

・チケットA周りの設定に問題がある

　⚪︎T001 チケットが購入できませんが表示されるロジックを見れば手がかりになりそう
　　▪️処理を追った結果チケットを登録した翌日の0時にバッチ処理にてチケット購入が有効になることが分かった(チケットAはチケット購入が無効のままだった)
つまりバッチ処理が走っていないことが原因かもしれない。

ログを確認する

上記の事象の切り分けや仮説検証を通して”該当時間にバッチが走っていない可能性がある”ことまで確認の幅を狭めることが出来ました。
狭めることでバッチが走る時間帯0時前後にバッチの実行結果があるかどうか見るだけで済みます。

【コラム】効率の良いデバッグ方法

ここでは調査タスクを行う中でよく使うデバッグ方法を2つ紹介させていただければと思います。
※前提としてここでのデバッグとはpry-railsのgemを利用した手法を指しています。

デバッグを強制的に終了させる方法

[1] pry(Hoge)> !!!

こちらのコマンドでデバッグを強制終了することができます。
ループ処理中にquitを打っても永遠にループを抜け出せない時に有効打かなと思います。

ループ処理の中身を効率的に見る方法

array = ["hoge1", "hoge2", "hoge3"]

array.each do |fuga|
puts "sample"
end

このようなループ処理の中でhoge2の処理だけをデバッグしたいという時があった際にquitで該当のループが回ってくるのを待つと非効率になってしまいます。
その際は下記の様に不必要な処理以外はスキップさせると効率よくデバッグできます。

array = ["hoge1", "hoge2", "hoge3"]

array.each do |fuga|
return unless fuga == "hoge2"
puts "sample"
end

ここではhoge2以外の処理はスキップさせています。

最後に

ログの確認は、システムの挙動を理解し、問題を診断するための強力なツールです。
しかし、そのような情報を適切に利用するためには、まず何を探し、どこを探すかを理解することが不可欠です。
また、仮説を立ててログを確認することで、時間とコストを節約できるだけでなく、的確な解決策に辿り着く確率も高まります。
この記事が皆様のログやデバッグの認識に少しでも貢献できれば幸いです。
自分自身も今後はログの出力の設定の部分に目を向けてログの設計についても解像度を上げて理解に努めていこうと思っております。
最後までご覧いただきありがとうございました。

divxでは一緒に働ける仲間を募集しています。
興味があるかたはぜひ採用ページを御覧ください。