ログとリクエストの追跡

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

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

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

@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 段階の目安は次の通りです。

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

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

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

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

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

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

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

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

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 行を組み立てる部分を書きます。テストを安定させるため、現在時刻や乱数は使わず、渡された連番だけから識別子を作る補助メソッドを用意しています。レベルの選択とログ行の連結を書いてください。

演習で使うひな形

normalizeMethod(" get ") は "GET"、normalizePath(" users ") は "/users"、traceId(42) は "trace-000042" です。これらは用意済みなので、入力が有効かを確認し、sequence % 10 == 0 でレベルを選んでログ行を組み立てます。

1. 整形済みの値が空、または連番が負なら INVALID を返すこと
2. sequence % 10 で WARN と INFO を選ぶこと
3. traceId を使って識別子付きの行を組み立てること