夕方のオフィスで、改修中のコードの画面を見ながら、処理の要所に目印を置くように落ち着いてログを書き足している保守運用の担当者
保守・改修約14分

改修時にログを仕込む｜あとから原因を追えるログの残し方

「注文が、ときどき消えるみたいなんです」

問い合わせを受けて、サーバーのログを開きます。該当しそうな時刻を探しても、出ているのは error の1行だけ。どの注文で、どの処理の、どこで失敗したのかが分かりません。結局「次に起きたら教えてください」と返すしかなくて、なんだか申し訳ない気持ちになる。

でも、ログが足りないのは、あなたの手落ちではありません。そのコードが書かれたとき、まだ誰も困っていなかった。だから「あとで追うための目印」を置く理由がなかっただけです。

そして、目印はいまからでも置けます。いちばん置きやすいのは、改修でそのコードを触るときです。この記事では、改修のついでに、未来の自分が原因を追えるログを仕込むやり方を一緒に整理していきます。

結論：やることは4つです。①「入口」「外部呼び出し」「例外」の3か所に絞って仕込む（全部に書かない）、②1行に「何の処理が・誰の何に対して・どうなったか」を、IDつきで書く、③レベルを使い分ける（ERROR＝人が対応すべき失敗／WARN＝おかしいが続行できた／INFO＝業務の節目）、④パスワード・トークン・個人情報は書かない。完璧なログ設計は要りません。今日触るコードに、目印を2〜3個置くだけで十分です。

なお、ここではPHPを例にしていますが、考え方は言語やフレームワークに関係なく使えます。ログの出力先や書き方は現場ごとに違うので、自分の環境に置き換えながら読んでみてください。

何が起きているのか：ログは「ある」のに、答えてくれない

原因を追えないとき、ログがまったくないことは意外と少ないものです。困るのは、たいていこんな状態です。

どれも、書いた人が悪いわけではありません。書いた時点では「動いている」ことを確かめられれば十分でした。ログに求められる役割が、あとから変わったのです。

だから、足りない分を一度に全部埋めようとしなくて大丈夫です。改修で触るところから、少しずつ目印を足していけば、ログは確実に育っていきます。

ログを仕込む場所：「入口」「外部呼び出し」「例外」の3か所

処理の流れの中でログを仕込む3か所として、処理が始まる入口、外部のサーバーやデータベースを呼び出す境目、エラーを受け止める例外の場所を示した図
全部に書かなくていい。処理の「入口」「外部呼び出し」「例外」の3か所に目印があれば、原因の場所はかなり絞れる

ログは、多ければいいわけではありません。1行ごとに書くと、今度は量が多すぎて探せなくなります。改修で仕込むなら、まずはこの3か所に絞るのがおすすめです。

1. 入口：処理が「始まった」ことと、何を受け取ったか

画面からのリクエスト、バッチの開始、APIの受付など、処理の入口です。「この処理が、この注文IDで始まった」と1行あれば、問い合わせの1件と結びつけられます。

バッチなら、開始と終了、そして処理件数を残しておくと、「昨日だけ件数が少ない」といった変化にも気づけます。

2. 外部呼び出し：自分の外に出ていく境目

データベース、外部のAPI、メール送信、ファイルの読み書き。自分のコードの外に出ていくところは、失敗がいちばん起きやすい場所です。呼び出した相手、結果（成功・失敗・ステータスコード）、かかった時間を残しておくと、「こちらの問題か、相手の問題か」の切り分けが早くなります。外部APIの切り分けは外部API連携の不具合の切り分けでも整理しています。

3. 例外：失敗を受け止めた場所

catch で例外を受け止めているのに、何も書かずに先へ進んでいるコードは、原因調査のいちばんの落とし穴です。受け止めた例外は、少なくともメッセージと発生場所をログに残す。これだけで「何も出ていない」状態がなくなります。スタックトレースが残っていれば、読み方はスタックトレースの読み方を参考にしてください。

1行に書く中身：「何の処理が・誰の何に対して・どうなったか」

場所が決まったら、中身です。あとから検索して読むことを考えると、1行にこの要素があると助かります。

書き方を比べてみると、違いがよく分かります。

# 追えないログ
error
failed to save

# 追えるログ
[ERROR] order.save failed order_id=10482 user_id=331 reason="payment api timeout" elapsed_ms=30012 req=7f3a9c
[INFO]  mail.send ok order_id=10482 to_domain=example.com elapsed_ms=420 req=7f3a9c

下の2行なら、order_id=10482 で検索すれば、この注文に何が起きたかがまとまって出てきます。req=7f3a9c で検索すれば、同じリクエストの流れが追えます。

ポイントは、キー=値 の形で書くことです。文章で「注文10482の保存に失敗しました」と書くより、grep で探しやすく、あとで集計もしやすくなります。ログの絞り込み方はエラーログをgrepとtailで絞り込むで紹介しています。

PHPで書くならこんな形

フレームワークを使っていない古いPHPのコードでも、error_log で書けます。

<?php
// 例外を受け止めた場所で、何の処理・誰の何・どうなったかを残す
try {
    $result = $paymentClient->charge($orderId, $amount);
} catch (Throwable $e) {
    error_log(sprintf(
        '[ERROR] order.charge failed order_id=%d user_id=%d reason="%s" at=%s:%d',
        $orderId,
        $userId,
        $e->getMessage(),
        $e->getFile(),
        $e->getLine()
    ));
    throw $e; // 握りつぶさず、これまでどおり上に伝える
}

大事なのは最後の throw $e; です。ログを足すだけで、処理の流れは変えない。改修のついでに挙動まで変えてしまうと、それ自体が新しい不具合の種になります。もともと例外を握りつぶして処理を続けていたコードなら、その挙動もいったんそのままにして、ログだけ足すのが安全です。

LaravelやMonologなど、PSR-3に沿ったロガーを使っている現場なら、$logger->error('order.charge failed', ['order_id' => $orderId, 'user_id' => $userId]); のように、IDを配列（コンテキスト）で渡す形がそのまま使えます。いまの現場にある書き方に合わせるのがいちばんです。

レベルを使い分ける：ERROR・WARN・INFO・DEBUG

ログのレベルは、あとで「どれを見ればいいか」を決める目印です。細かく悩まなくて大丈夫なので、まずはこの基準で分けてみてください。

レベル使う場面例
ERROR処理が失敗し、人が対応すべきもの決済APIがタイムアウトして注文が保存できなかった
WARNおかしいが、処理は続けられたもの在庫APIが遅く、リトライで成功した
INFO業務の節目。正常に進んだ記録注文を受け付けた／バッチが1,240件処理して終了した
DEBUG調査のときだけ見たい細かい情報計算途中の値、SQLの組み立て結果

目安は、ERRORが出たら誰かが見に行く、と考えることです。何でもERRORにすると、本当に大事な1行が埋もれてしまいます。監視でERRORを拾っているなら、なおさらです（アラートの考え方は監視アラートの閾値の決め方）。

DEBUGは、本番では出力しない設定になっていることが多いレベルです。調査のために一時的にDEBUGを本番で出すときは、いつ戻すかを決めてからにしておきましょう。

書かないもの：パスワード・トークン・個人情報

ログは、思っている以上にいろいろな人と場所に渡ります。サーバーにログインできる人、ログを集めるサービス、調査のために外部の会社に渡すファイル。だから、ログに書かないものも決めておきます。

うっかりしやすいのが、リクエストの中身をまるごと出力する書き方です。print_r($_POST, true) をそのままログに書くと、パスワード欄も一緒に残ってしまいます。まるごと出したくなったら、必要な項目だけを選んで書くようにしましょう。

このあたりは、OWASPの「Logging Cheat Sheet」がログに残すもの・残さないものを整理していて参考になります。秘密の情報の扱い全般はパスワードとAPIキーの平文放置をなくすでもまとめています。

量と置き場所：ループの中には書かない

ログを足したら、最後に量を確かめます。

具体例：ログがあった改修と、なかった改修

同じ「ときどき注文が保存されない」という問い合わせでも、ログの有無でこう変わります。

違いは、調査の腕前ではありません。改修のときに、目印を置いておいたかどうかだけです。再現しない不具合の追い方は「再現しない」バグの調べ方でも整理しています。

影響：ログを仕込むようになると、何が変わるか

明日やること

  1. 次に触る改修で、ログを仕込む場所を2〜3個決める。「入口」「外部呼び出し」「例外」のどこに当たるかを見てみましょう。
  2. 何も書かずに進んでいる catch を1つ探す。見つけたら、処理はそのままに、ログを1行だけ足します。
  3. 1行の書き方を決める。[レベル] 処理名 結果 キー=値 の形を、チームや自分用のメモに書いておきます。
  4. 書かないものを確かめる。パスワード・トークン・個人情報が出力されていないか、足したログを見直します。
  5. 検証環境で出力先を確かめる。どのファイルに出るか、ローテーションの対象かを見てから本番に出します。

今日やるのは、2の「何も書かずに進んでいる catch を1つ探す」だけでも十分です。その1行が、いつか誰かの調査を何時間も短くしてくれます。

改修時のログ仕込みチェックリスト

全部できなくても大丈夫です。「例外を書いた」の1つだけでも、次の問い合わせのときにはっきり違いが出ます。

よければ、こちらも

明るい昼のオフィスで、画面に表示された整ったログの記録を見て原因にすぐたどり着き、ほっとした笑顔を浮かべている保守運用の担当者

ログは、いまの自分のためではなく、少し先の誰かのために置く道しるべです。その誰かは、たいてい数か月後の自分です。

ログが足りなくて困った経験があるなら、それはもう「どこに目印があれば助かったか」を知っているということです。その感覚は、いちばん確かな設計図になります。

まずは次の改修で、何も書かずに進んでいる catch を1つだけ探してみてください。

ほかの実務ヒントは記事一覧からどうぞ。保守運用の小さな備えを、メールでも少しずつお届けしています。

関連用語