73:ログには5W1Hを書く

プログラミング迷子: どんな情報が必要かを知らず「とりあえず」で書かれてしまうログ出力

  • 後輩W:どこまで処理が実行されたかをログに残すように、って言われたんですけど、とりあえず関数の開始と終了をログに出したら良いですか?

  • 先輩T:うーん。関数の呼び出しだけわかっても、知りたいことはわからないよ。5W1Hを書くようにしよう。

「ログに何を書くべきか」は、ロギングにおいて一番難しく、一番大切なことです。 次のエラーログの問題を考えましょう。

具体的な失敗

def main():
    logger.info("取り込み開始")

    sales_data = load_sales_csv()
    logger.info("CSV読み込み済み")

    for code, sales_rows in sales_data:
        logger.info("取り込み中")
        try:
            for row in sales:
                # 1行1行、データを処理する
                ...
        except:
            logger.error("エラー発生")

    logger.info("取り込み処理終了")

このロギングでは、実際にエラーが発生したときに原因の特定は難しいでしょう。 ログが開始と終了しか残っておらず、処理全体でエラー処理がされているからです。

ベストプラクティス

特に長時間実行されるコマンドや、夜間実行される バッチ処理 は細かめにログを残すべきです。 エラーがあった際に原因の特定が格段にやりやすくなります。

def main():
    try:
        logger.info("売上CSV取り込み処理開始")

        sales_data = load_sales_csv()
        logger.info("売上CSV読み込み済み")

        for code, sales_rows in sales_data:
            logger.info("取り込み開始 - 店舗コード: %s, データ件数: %s", code, len(sales_rows))
            try:
                for i, row in enumerate(sales_rows, start=1):
                    logger.debug("取り込み処理中 - 店舗(%s): %s行目", code, i)
                    ...
            except Exception as exc:
                logger.warning("取り込み時エラー - 店舗(%s) %s行目: エラー %s", code, i, exc, exc_info=True)
                continue
            logger.info("取り込み正常終了 - 店舗コード: %s", code)

        logger.info("売上CSV取り込み処理終了")
    except Exception as exc:
        logger.error("売上CSV取り込み処理で予期しないエラー発生: エラー %s", exc, exc_info=True)

細かくログを残すように変更していますが、重要なバッチ処理であればこの程度は必要です。 各店舗の処理毎にインフォログを(店舗コード付きで)残したり、行単位のログをワーニングログとして残すなどの工夫に注目してください。 処理の トレーサビリティ を常に意識しましょう。

ログメッセージに何を書けば良いかわからないときは、次のような5W1Hを意識しましょう。

cover

(中略)詳細は書籍 自走プログラマー をご参照ください