この記事は Akatsuki Advent Calendar 2017 の 8 日目の記事です。
7日目: バイナリのビルド作業はそろそろボタンをポチるだけにしようぜ
背景
システムを運用していると、日々アプリケーション・ミドルウェア・インフラのログが蓄積されていきます。これらのログはシステムの障害対応・解析のための貴重な情報源となりますし、そうであることが期待されます。
しかし、これらのログの取り扱いを誤ると誤った障害解析結果を導き出してしまったり、解析にいたずらに時間がかかったり、障害を特定することができなかったりといったことが起こります。
今回はこれらのログを扱う上で注意すべき点とその改善案を紹介をしたいと思います。
前提
私はソーシャルゲームのインフラとサーバサイドアプリケーションを担当しており、下記のサービス・ソフトウェアを利用しています。
- AWS
- ELB (Classic)
- EC2 (AmazonLinux)
- RDS (MySQL)
- CloudWatch
- 他
- nginx
- Ruby on Rails (unicorn)
- 他 BigQuery, ElasticSearch, Re:dash, Kibana, Mackerel 等
そのタイムスタンプ、いつのもの？
通常、ログデータにはタイムスタンプが付けられていますが、このタイムスタンプは一体「いつ」の時刻を記録したものなのでしょうか。
ほとんどの場合、対象ソフトウェアが処理を開始した時間が記録されるのですが、実は例外もあります。
私の所属しているプロジェクトで使っているソフトウェアの中では nginx がこれに該当します。
nginx では「処理が完了した時刻 (= レスポンスを返した時刻)」が記録されます。
システムが正常に稼働している限りこれらの違いを気にすることは少ないと思いますが、障害解析時はその限りではありません。
各アプリケーション・ミドルウェア・インフラのログを少なくとも秒単位であわせ解析する必要があるため、各タイムスタンプが「いつ」の時刻を記録したものなのか把握していないと、誤った障害解析結果を導きかねません。
特にタイムアウト処理が絡んだ場合、レスポンスを返した時刻はリクエストを受けた時刻と大きな差が発生します。
何気なく記録されているログのタイムスタンプにも罠があります。ご注意ください。
必要な情報出してる？
前項で「nginx のタイムスタンプはレスポンスを返した時刻」と説明しましたが、ではいったいどうやって「処理を開始した時刻(= リクエストを受けた時刻)」を出力するのでしょうか。
実は nginx のデフォルトの設定ではこれができません。
nginx で「リクエストを受けた時刻」を記録する方法はいくつかあるようなのですが、最も簡単なのは「レスポンスを返すまでにかかった時間」を一緒に記録することです。ログの解析時にそれらの値を使って「リクエストを受けた時刻」を求めることができます。ログ解析時に前処理は必要になりますが、それを低コストで行える環境もあわせて用意しておくとよいです（後述)
(※ 最も良いのはもちろん予めログにリクエストを受けた時刻を記録することですが、ログ収集時に計算させる方法も可能です）
死ぬ前の情報は残した？
エラー時の情報は貴重です。この情報の有無で障害解析のスピードと精度は数倍変わってくるでしょう。しかし、中にはエラー時の情報を残さずに死んでしまうソフトウェアもあります。私のプロジェクトで利用しているもの中では unicorn がこれに該当します。
unicorn はリクエストを処理する worker プロセスと、workerプロセスを管理する masater プロセスから構成されます。
unicorn はタイムアウトの設定を持ち、worker プロセスの処理がこのタイムアウト内に完了しない場合、master プロセスは workerプロセスに対して即座に SIGKILL を送りつけます。その結果、「タイムアウト内に完了しなかった処理」がログに記録されないという事態が発生します。
これに対する改善策はいくつかあります。
- より上位にあるソフトウェアで記録を残す
- 具体的には ELB や nginx でログを残す。当該リクエストを処理したホストの情報、エラーコード、エンドポイント等を記録する。
- SIGKILL の代わりにトラップ可能な SIGINT 等を利用し、そこで
Rails.logger.flushさせる - Rails の ActionController の
around_actionで "ソフトな" タイムアウトを設定する
around_action :global_timeout
def global_timeout
Timeout.timeout(TIMEOUT_SEC) do
yield
end
end
私の所属するプロジェクトで実際に適用されているのはまだ1のみですが、2,3の手法も評価していく予定です。
ログデータ膨大すぎるんだけど...
正確な障害解析には普段から多くの情報を取得しておく必要がありますが、その結果、解析に時間がかかったり、そもそも普通のマシンでは処理ができなかったりといったことが発生します。
私の所属するプロジェクトでは、ログをBigQueryとElasticSearchに格納し、Re:dashやKibanaで可視化できる仕組みを構築しています。
普段はマクロなインフラメトリクス（や、売上情報等）を表示するために使っていますが、障害解析時はクエリを書くことで簡単に情報を絞り込んだり、可視化することができ、便利です。nginxのタイムスタンプ問題もクエリを書くことで簡単に解決できます。
(※ すべてBigQuery+Re:dash に統一化したいなぁ)
さいごに
障害解析は「より少ない情報、より少ない時間で原因を特定する」エクストリームスポーツではありませんし、そうあってはなりません。
エンジニアにエスパーの力を求めるのは間違っています。
また、「システムの癖を知った、長年の経験のあるエンジニアにしかできない作業」であってもなりません。
障害解析のために十分な情報を集めることや、スピーディに解析できる環境を用意することは言うほど簡単ではありませんし、コストもかかりますが、安定したサービスを提供するには必要不可欠なものです。
堅牢なシステムの構築は１日にして成らず、頑張っていきましょう。