この記事は「ネオシステム Advent Calendar 2023」の1日目の記事です。
はじめに
皆さん、今日も楽しくログと向き合っていますでしょうか。
システム開発において、ログの重要性を説明する必要も無いかと思いますが、
動くものを早くリリースしてほしいという顧客からの圧力に負けるなどで、ログ設計は蔑ろにされることが多いと思います。
しかし、システムには障害が付き物。
迅速さが求められる障害対応の中で、見辛いログと向き合うのは中々に苦痛です。
冒頭の画像でも、プログラマーが実に苦しがっている様が見て取れます。
今流行りの生成AIで作ってみたのですが、うまく作ってくれるものですね。
でも、2枚目の画像の右の人の肘のところにある物体は一体何なんでしょうか…
それはさておき、本記事では自分がログ設計を行う上で気を付けてきた点をまとめてみました。
あまり大したことは書いていませんが、少しでも皆さんの役に立てば嬉しいです
ログ設計時に気を付けている点
上げたら上げたで枚挙に暇がないのですが、特に以下の点を気を付けるようにしています。
- ログ出力の重要性を理解する
- 必要な情報をきちんと出力する
- 使用するログレベルを必要最低限にする
- トランザクションIDを設ける
- ログ設計にかける工数を確保する
1. ログ出力の重要性を理解する
個人的に障害が発生しないシステムは絶対にあり得ないと考えています。
JSTQB（日本ソフトウェアテスト資格認定委員会）が提唱している「ソフトウェアテストの7原則」というものがありますが、端的に言うと完全無欠なテストを行うことは難しいということが書かれています。
それにシステムは人が作るものですし、人はコンディションを常に一定に保つことは困難です。
ちょっと体調が悪いけど、期限が迫っているので無理を押して出社して開発を行い、ケアレスミスによってバグを混入してしまうなんてことはよくある話です。
そしてそのバグが含まれたままのプログラムがリリースされ、障害に繋がるなんてこともよくある話です。
重要なのは、障害が起きることを前提に、早期解決できる仕組みを設けることです。
アプローチは様々あると思いますが、分かりやすいログをきちんと出力することがその最善手であると考えています。
障害は必ず起きるもの。それを踏まえて早期解決に繋がるログをきちんと出力する
2. 必要な情報をきちんと出力する
誰かに何かを伝えたい時、よく5W1Hを意識するように言われます。
- when（いつ）
- where（どこで）
- who（誰が）
- what（何を）
- why（なぜ）
- How（どのように）
5W1Hに沿うことで、伝えたい内容を相手に正確かつ速やかに伝えることができます。
ログの内容も5W1Hを意識することで分かりやすくなると考えています。
それを踏まえて私は必ず以下の情報を出力するようにしています。
| 5W1h | 出力項目 | 備考 |
|---|---|---|
| when | 時刻（年月日時分秒） | 処理開始、終了時刻。アクセス時刻等 |
| where | 機能名 | 「ユーザー登録」「参照」等の機能名（関数名） |
| who | 機能の実行者 | ログインユーザー名等 |
| what | 入出力パラメータ | |
| how | 処理 | 入力チェック、DB処理等 |
5W1Hと言いながら、whyを使っていないのは内緒です；
ログに出力する情報は、5W1Hを意識して必要な情報のみ出力する
3. 使用するログレベルを必要最低限にする
私は経験上Javaでの開発が多く、ロギングユーティリティには「Log4j」かその後継である「logback」をよく利用していました。
log4jには6つのログレベルがあります。
| レベル | 内容 |
|---|---|
| FATAL | 致命的なエラー |
| ERROR | エラー。予期せぬエラー |
| WARN | 警告 |
| INFO | 情報 |
| DEBUG | デバッグ情報 |
| TRACE | トレース情報。デバッグ情報より更に詳細な情報 |
経験上、FATALとERRORを明確に使い分けないといけない状況に直面したことがありません。
いずれにしても直ちに対応しないといけないという点では殆ど相違ないため「ERROR」に集約するようにしています。
出力されたログは、コスト面での問題等がない限り監視を行うことが多いです。
監視設定の煩雑化を避けるためにもログレベルは必要最低限に留めるべきと考えています。
TRACEについても、DEBUGとの使い分けに悩むことが多いと思います。
TRACEにはデバッグ情報より更に詳細な情報を書くべきと言われますが、更に詳細な情報をDEBUGで書いたとしても、大きなデメリットを感じることが正直ありませんでした。
そのため「DEBUG」のみ使用するようにしています。
なお、ERRORとWARNの使い分けは以下のようにしています。
| レベル | 出力時 | 監視アラート |
|---|---|---|
| ERROR | サーバー起因のエラーが発生した時 （HTTPの500番台エラーに相当） |
行う |
| WARN | クライアント起因のエラーが発生した時 （HTTPの400番台エラーに相当） |
行わない （ただし短時間で殺到した場合にはアラートが発報されるようにしておく） |
ログレベルは「ERROR」「WARN」「INFO」「DEBUG」に絞る
4. トランザクションIDを設ける
よほど小規模なシステムでない限り、昨今のシステムは必ず冗長構成が施されています。
その場合、各サーバーのログがFluentd等のツールによってログサーバーに集約・統合されることになるかと思います。
統合されたログは、各サーバーのログが入り乱れ、どれがどのトランザクションのログなのかが分かりづらいことがままあります。
そのため「トランザクションID」を必ずログに出力し、grepコマンド等を利用してトランザクション毎に確認しやすくなるようにしています。
トランザクションIDには、一意な値であれば何でも良いかと思いますが、
私は「UUID」、もしくは特定の時間や日でgrepをかけやすくするために「タイムスタンプ（ミリ秒含む）＋乱数」を設定することが多かったです。
トランザクションIDを出力して、トランザクション毎のデータを参照しやすくする
5. ログ設計にかける工数を確保する
極論を言えば、ログを正しく出力しなくてもシステムは動作します。
そのため、顧客にログ設計や実装を必要工数として計上してもらうことは困難を極めます。
そんな時、私は先述した「ログ出力の重要性」を顧客にきちんと説明するようにしています。
障害が発生する度に保守運用工数が嵩んでしまうと、システムが長期稼働した際に損をしてしまうのは顧客ですし、その点を引き合いに出して説得することが多いです。
それで応じてくれれば良し。
応じてくれなければ、自分が保守運用に携わることがない未来を祈りましょう；
ログ出力の重要性を引き合いにして、頑張って工数を確保しよう
最後に
ログは軽視されがちですが、きちんと設計すれば必ず保守運用工数の削減に繋がります。
システムがリリースされて保守運用フェーズに入ると、少しずつ人員も削減され、少ない人員で速やかに障害対応を求められる日がすぐに訪れます。
そこで顧客と障害の板挟みになってログの重要性に気付くことも良い経験になるとは思いますが、そんな苦しい経験を経なくても本記事が気付きのきっかけになってくれれば幸いです。
最後まで読んで頂き、ありがとうございました。
明日の記事担当は @kzkamiya さんになります。
よろしくお願いします！
参考文献
- JSTQB Foundation Levelシラバス（Version 2018V3.1.J03）
https://jstqb.jp/dl/JSTQB-SyllabusFoundation_Version2018V31.J03.pdf