ログとリクエストの追跡｜コードで実践

このレッスンでは、障害が起きたときに原因へたどり着くためのログの書き方と、1 本のリクエストを最初から最後まで追いかけるためのトレース識別子を扱います。

System.out.println ではなく Logger を使います

学習中は System.out.println で足りますが、本番のアプリでは使いません。出力先を切り替えられず、重要度による絞り込みもできず、いつどのスレッドで起きたのかも残らないからです。Spring Boot は既定で SLF4J というログの窓口と Logback という実装を持っているので、次のように書きます。

Java

@Service
public class UserService {
    private static final Logger log = LoggerFactory.getLogger(UserService.class);

    public User find(long id) {
        log.debug("finding user. id={}", id);
        return repository.findById(id)
                .orElseThrow(() -> new UserNotFoundException(id));
    }
}

中括弧のプレースホルダを使う点が要点です。文字列を足し算でつないでしまうと、そのレベルが無効で出力されない場合でも連結の処理だけは走ります。プレースホルダなら、出力すると決まってから初めて組み立てられます。

レベルは絞り込みのための道具です

ログレベルは、重要度の目盛りであると同時に、出す量を切り替えるつまみです。よく使う 5 段階の目安は次の通りです。

レベル	使いどころ
ERROR	処理が失敗し、人の対応が要る
WARN	続行はできたが、放置すると問題になりそう
INFO	業務上の節目。注文の確定、利用者の登録など
DEBUG	開発時に流れを追うための詳細
TRACE	変数の中身まで含む最も細かい記録

設定した水準以上のものだけが出力されます。本番は INFO、調査中だけ一時的に DEBUG、という運用が一般的です。ここで大事なのは、あとから DEBUG に上げれば見られる状態にしておくことです。そもそも書いていないログは、どんな設定にしても出てきません。

構造化ログにすると機械が読めます

ユーザー 7 が見つかりませんでした という 1 行は、人には読めても機械には読めません。あとから「利用者 7 に関するログだけ集めたい」と思っても、正規表現で本文を切り出すはめになります。そこで、ログを JSON など決まった構造で出す構造化ログが使われます。

JSON

{"level":"INFO","traceId":"trace-000042","method":"GET","path":"/users/7","message":"user not found"}

こうしておくと、ログ基盤側で traceId や path を条件に検索できます。人が読む見た目より、あとで絞り込めることを優先する考え方です。

トレース識別子で 1 本のリクエストをつなぎます

本番のサーバーは同時に何十本ものリクエストを処理しているので、ログは複数のリクエストの行が入り混じって並びます。この中から「あの 1 回の呼び出し」に属する行だけを抜き出すために、リクエストごとに固有の識別子を振り、すべての行に載せます。これがトレース識別子です。

問題は、その識別子をどうやって Controller から Service、Repository まで持ち回るかです。すべてのメソッドの引数に足すのは現実的ではありません。ここで使われるのが MDC という仕組みです。MDC はスレッドごとに紐づく小さな入れ物で、入口のフィルタで値を入れておくと、同じスレッドで走るあらゆるログ出力からその値を参照できます。

Java

public class TraceIdFilter implements Filter {
    @Override
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
            throws IOException, ServletException {
        MDC.put("traceId", newTraceId());
        try {
            chain.doFilter(req, res);
        } finally {
            MDC.remove("traceId");   // 後始末を忘れない
        }
    }
}

最後の finally が要点です。サーバーのスレッドは使い回されるので、消し忘れると次のリクエストが前の識別子を引き継いでしまい、まったく無関係な行が同じ 1 本のリクエストに見えてしまいます。

演習で書くもの

Spring では前のレッスンで学んだフィルタが識別子を作り、MDC を通じて各行に埋め込みます。ここではその 1 行を組み立てる部分を書きます。テストを安定させるため、現在時刻や乱数は使わず、渡された連番だけから識別子を作ってください。

System.out.println ではなく Logger を使います

Java

@Service
public class UserService {
    private static final Logger log = LoggerFactory.getLogger(UserService.class);

    public User find(long id) {
        log.debug("finding user. id={}", id);
        return repository.findById(id)
                .orElseThrow(() -> new UserNotFoundException(id));
    }
}

レベルは絞り込みのための道具です

ログレベルは、重要度の目盛りであると同時に、出す量を切り替えるつまみです。よく使う 5 段階の目安は次の通りです。

レベル	使いどころ
ERROR	処理が失敗し、人の対応が要る
WARN	続行はできたが、放置すると問題になりそう
INFO	業務上の節目。注文の確定、利用者の登録など
DEBUG	開発時に流れを追うための詳細
TRACE	変数の中身まで含む最も細かい記録

構造化ログにすると機械が読めます

JSON

{"level":"INFO","traceId":"trace-000042","method":"GET","path":"/users/7","message":"user not found"}

こうしておくと、ログ基盤側で traceId や path を条件に検索できます。人が読む見た目より、あとで絞り込めることを優先する考え方です。

トレース識別子で 1 本のリクエストをつなぎます

Java

public class TraceIdFilter implements Filter {
    @Override
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
            throws IOException, ServletException {
        MDC.put("traceId", newTraceId());
        try {
            chain.doFilter(req, res);
        } finally {
            MDC.remove("traceId");   // 後始末を忘れない
        }
    }
}

ログとリクエストの追跡

System.out.println ではなく Logger を使います

レベルは絞り込みのための道具です

構造化ログにすると機械が読めます

トレース識別子で 1 本のリクエストをつなぎます

演習で書くもの

要件

入出力例

ヒント

メモ

ログとリクエストの追跡

System.out.println ではなく Logger を使います

レベルは絞り込みのための道具です

構造化ログにすると機械が読めます

トレース識別子で 1 本のリクエストをつなぎます

演習で書くもの

要件

入出力例

ヒント

メモ