変な日本語表現のご指摘はいつでも大歓迎です！！

ココネアドベントカレンダー2023年の18日目の記事となります。

プログラムにとってログは絶対欠かせないものじゃないかと思います。

「あれ？」って退勤５分前にslackに大量のalertが来たら.........

実際slackのalertもログから異常を検知して取ってくるものなので、即イシュー対応ができます。（ありがたい）
ということで今回はエンジニアにとって大事なログについて少し共有したいと思います。

ログがない生活？（極端です）

間違いから学ぶとは言え、何が間違っているかが分かりにくくなる
問題に対処して学んだことが再起動以外の何物でもなければ、その瞬間はマインドフルネスが必要
明日、サーバーが落ちないように夜中に祈りを捧げる間、良質な睡眠をとれなくなる
自分自身を信じられなくなり、if (true) { return; }のようなConstantコードすらも壊れる可能性があると思うようになり、FBIが自分を監視していると信じる人々のように変わるかもしれない

ロギング

ロギングレベル

会社のルールによって異なるかもしれませんが、一般的にTRACE、DEBUG、INFO、WARN、ERROR、FATALなどがよく使われます。
各レベルはログに残されるイベントのレベルを示します。設定レベルを決めて、特定のレベル以上のログのみを表示できます。

TRACE → DEBUG → INFO → WARN → ERROR → FATAL
レベルが高いほどログメッセージの重要度も高いです。

例）ロギングレベルをINFOに設定した場合、INFO,WARN,ERROR,FETALレベルのログは出力されますが、DEBUG,TRACEレベルのログは出力されません。

で、どんなロギングレベルを使う？

自分は主にDEBUG、INFO、WARN、ERRORをよく見ましたが、いったいいつ？どういうレベルを使うか常に悩んだりします。
例）サーバーは異常なしの状態ですが、リクエストが間違って4XX HTTP状態コードをレスポンスしたら、APIに異常はないので、記録としてINFOレベルのログに残すべきかそれとも一応エラーだからERRORとして残すべきか？その間のWARNで残すべきか？

世の中大体そういうもので、これもケースバイケースです。
単純にあの状況情報だけで決めるのは難しいです。

論理的理由と一貫性

上の状況でどんなログレベルを使うか工夫するために情報を把握していきましょう。
フロントエンドでリクエストする前に値の検証があったら、ある程度は検証されたリクエストが来るはずです。
もし間違ったリクエストが来たら次の状況の中の可能性があります。

フロントエンドで検証されなかった値がある
一般的なフロントエンドからではなく、別のルートからリクエストが来た

1はミスまたはフロントエンドとバックエンドのコミュニケーション問題で十分ありうる状況です。また、APIは正常に動いたので、エラーやバグを表示するためのERRORレベルは高いかもしれません。
2の場合も十分発生しかねません。これは悪意を持った誰かによるリクエストかもしれません。
ですが、いくらフロントエンドで値の検証をするとしても当然バックエンドもリクエストの検証が必要です。
それで間違ったリクエストが結構来る様子でしたら、これは十分見守る必要があると思い、情報を表現するためのINFOレベルも高いかもしれません。
上の状況だと自分はWARNレベルでロギングすると思います。

個々の個人やプロジェクトによって、どのレベルがどのような状況に適しているかは異なることがあります。重要なのは、レベルを選択する際に論理的な理由を持ち、一貫性を持った選択をすることだと思います。
個人のプロジェクトではない場合、複数の人がログに残すことになるため、メンバーが共通の視点を持てるように、コンベンションを定めることも重要かもしれません。
結局のところ、ログは問題が発生した際に原因を迅速に特定し解決するためのものですので、一貫性のあるログは非常に重要だと思います。

ロギメッセージの重要性

ログメッセージの書き方も様々ですが、
どれだけ論理的で一貫性のあるログレベルを設定し、ログを残したとしても最終的に残るメッセージがあまり役に立たなければ意味がありません。
デバッグを容易にするために十分な情報を残し、ログを見つける際の利便性を考慮して、1つの問題につき1行でログを残しましょう。

log.java

// 掲示板に投稿時のリクエストで間違ったタイトルによって例外が発生した場合
// 特に役に立たないログ
log.warn(e.getMessage());
// ↑よりは少し調査しやすいログ
// デバッギングに役立つ情報と一緒にstack traceも一緒に残した方が良いと思います
log.warn("POST:CREATE:INVALID_TITLE. userId={}, invalidTitle={}, message={}", e.getUserId(), e.getInvalidTitle(), e.getMessage(), e);

ログファイル管理Tip (logback)

日付でログを探しやすくした方が管理しやすい（logback.xml）
- 日付別管理：fileNamePattern（ex: log/%d{yyyy-MM}/debug.%d{yyyy-MM-dd}.%i.log.gz）
- 一定のサイズになったら削除：maxFileSize（ex: 1KB）,maxHistory（ex: 15）

logback.xml

<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>log/debug.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRolliingPolicy">
    <fileNamePattern>log/%d{yyyy-MM}/debug.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
    <maxFileSize>1KB</maxFileSize>
    <maxHistory>15</maxHistory>
  </rollingPolicy>
  <encoder>
    <Pattern>${CONSOLE_LOG_PATTERN}</Pattern>
  </encoder>
</appender>

最後に

ログを通じて様々なことができると思います。

性能把握ができるかも
- 特定イベントのタイムデルタが特定時間以上の場合を検索
- ノード間レスポンスが遅い場合を検索
- パーシング失敗が多発するところを検索
役立つログから自分のミスを繰り返して伸びることもできるかも
- 自分が正しいと思ったことがログを通じて間違ったことに気づいたことがある
- ログを通じてエラーケースのバリエーションも把握できる
ELK Stackのようなツールを導入してリアルタイムで効率的にログを収集、分析してユーザーの動向も把握しやすくなるかも

ただ、何もかもログとして残してしまうとサーバーに負荷がかかるので、ログに残すデータは絶えず工夫する必要があります
（プログラムが遅くなる原因の一つはI/O）

行くにしてもログ1行くらいはいいだろ？（Logging）