0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

@k-izumi

pythonライブラリ・アプリケーション作成時のロギングのコーディング方法 (前編)

0
Last updated at Posted at 2025-06-22

ソフトウェアが出力するログはプログラミング中や運用中に想定外のことが起きた際、解決への第一歩である原因解析を進めるうえで重要な情報です。Python のプログラムでは、標準モジュールの logging を使用することでログ記録を簡単に実現できるようになっています。

本来、このモジュールは柔軟にログ出力を変更できる機能を兼ね備えていますが、その特性を失わせがちです。というのも、Pythonは初心者向けの解説がWEB上に山ほどあるので、ロギングについても仕組みから丁寧に説明している記事がたくさんあります。このこと自体は悪いことではありませんが、仕組みの説明に使われるコードは往々にして、実用する上で大事な柔軟性を損なうコードになっています。仕組みの説明のために使うコードの実用性が低いのは当たり前のことなのですが、実用性の判断を疎かにしてそのコードをそのまま使ってしまうと、「ちょっとログ出力を変えたいだけなのにプログラムに修正が入る」という柔軟性の低いロギングになってしまいます。

この記事では、ロギングの柔軟性を高めること、つまりあなたが作成するライブラリの利用者やアプリケーションの運用者・保守担当者が思い通りのログをプログラムの改修無しで出せることを目指して、logging モジュールの使い方を考えます。

なお、長くなったので前後編に分かれています。後編はこちら。

logging の仕組みと柔軟性確保のための基本方針

まずは logging モジュールを使用したロギングの仕組みを確認し、その仕組みに沿って、柔軟性確保のための方針を考えましょう。

logging の仕組み

Python の logging を用いたロギングは Java の logback, log4j 等と似ていて、ログ出力のための工程は大きく次の2段階に分かれています。

  1. プログラム中で、ロガーに対してログメッセージを送る
  2. ロギング環境 (ハンドラ、フォーマッタ等) を設定する

これらが実施されることで、ロギング環境設定どおりにログメッセージがファイル等に出力されます。

なお、それぞれの段階を実施する主体は開発している物によって次のように異なります。

開発する物 ロガーへのメッセージ送信 ロギング環境設定1 (デフォルト設定) ロギング環境設定1 (カスタム設定)
アプリケーション アプリ開発者 アプリ開発者 アプリ運用者
ライブラリ ライブラリ開発者 アプリ2開発者 アプリ2運用者
ライブラリのモジュール実行3 ライブラリ開発者 ライブラリ開発者 ライブラリ利用者

この記事では先述の通り、ライブラリの利用者が思い通りのログを出せるようにすることを目指すので、『ロギング環境設定 (カスタム設定)』列の人々のあらゆる潜在的要件に応えるために『ロガーへのメッセージ送信』列と『ロギング環境設定 (デフォルト設定)』の人が事前に何ができるかを考えることになります。

柔軟性確保のための基本方針

上述したロギングのそれぞれ段階について方針を立てます。利用者が柔軟にログ出力を変更できるようにするために次のように考えましょう。

  • プログラム中で、随所で適切なロガーに対して適切なレベルのログメッセージを送る
  • ロギング環境として設定可能なあらゆる設定を、利用者の指定通りに設定できるようにする 4

ここでいうレベルとは、CRITICAL, ERROR, WARNING, INFO, DEBUG 等のことであり、メッセージの重要度を意味します。たとえば、あなたのライブラリを使うアプリの開発者は動作確認中、異常の発生に気付くために CRITICAL, ERROR, WARNING レベルのログだけを標準出力か標準エラー出力へ出力したいと考えるでしょう。そして、不具合の原因調査時にあなたのライブラリが何をしているのかを知るために DEBUG レベル以上のログを別途ファイル出力しておきたいと考えるかもしれません。logging モジュールではこのようなロギング環境設定をできる仕組みになっているので、利用者（今回の例ではアプリ開発者やそのアプリの運用者5）が設定できるようにします。

また、ロガーは複数作ってそれぞれに異なる名前を付けることができます（詳細は後述）。そして、ロギング環境設定では、ロガーごとに出力するログのレベルや出力先を変えることができるようになっています。そのため、例えば機能AのログをロガーAに、機能BのログをロガーBに……としていれば、利用者は機能Aの動作について調べたいときにロガーAのDEBUGレベル以上のすべてのログメッセージを特別に用意したログファイルへ出力する一方、全てのロガー 6 のERRORレベルメッセージを普段通りのログ出力先へ普段通りに出すということもできます。

このような方針で柔軟性を維持するための具体的な設計とコーディングを見ていきましょう。

ロガーの作成と使用

まずはログ出力の一段階目、メッセージをロガーへ送る個所です。単純な例は次の通りです。

単純な例
import logging

# mymodule という名前のロガーを作成
logger = logging.getLogger("mymodule")

# メッセージの送信
logger.error("○○（エラーの内容）が発生しました")
logger.warning("○○（警告の内容）が発生しました")
logger.info("○○を実行しました")
logger.debug("○○を実行しました")

ロガーを作成し、いくつかのレベルでメッセージを送信してみています。この例はあくまでロガーの作成にかかわる最低限の関数・メソッドを示しただけなので、柔軟性を持たせるための条件を満たせていません。ここからは、どのようにメッセージ送信をするべきかを列挙します。

ロガーの名称の最上位部分をライブラリ名（アプリ名）で統一する

ロガーの名称には任意の文字列を指定できますが、ロガー名称はピリオドで区切られた階層的な値として解釈されます。たとえば、ロガー mymodule.feature1 はロガー mymodule の子です。そのため、後述するロギング環境設定で「ロガー mymodule の DEBUG ログを特別なファイル○○に出力する」と設定した場合、ロガー mymodule.feature1 へのメッセージもロガー mymodule.feature2 へのメッセージもそのファイルへ出力されるようになります。

そのため、ロガーの名称の最上位部分をライブラリ名（アプリ名）で統一しておけば、利用者・運用者はあなたのライブラリ（アプリ）と他のライブラリを区別してログ設定をできるようになります。

ロガー名として __name__ を使う方法があります。__name__ にはパッケージ名＋モジュール名が . 区切りで入っているため、あなたのライブラリの全コードがライブラリ名のパッケージ内に実装されていれば、__name__ で条件を満たせます。パッケージやモジュールの分割方針によっては、__name__ はロガー命名としても使いやすいものになっていると思います。

logging 初心者向けには logging.error() のようにデフォルトのロガー (ルートロガー) を使うコード例も多いですが、実用上はデメリットが多くお勧めできません。とくに、「ロガーごとに出力を変える」という柔軟な設定をできなくなってしまうため、この記事においては禁忌です。

ログレベルの使い分け方を統一する

先述の通り、ロギング環境設定ではログレベルごとに出力の有無や方法を変えることができます。しかし、もし ERROR レベルも DEBUG レベルもエラーメッセージと正常動作の報告の両方に使われていたら、「エラーメッセージだけ見たい」という要望を満たすロギング環境設定ができなくなってしまいます。

これを回避するためには、ログレベルの使い分けを統一する必要があります。理想はログを出す全モジュールで統一されていることですが、サードパーティライブラリも使用する場合はあまり現実的ではないので、ライブラリ・アプリ内で統一するようにしましょう。

ちなみに、公式のドキュメント（の和訳）では次のように使い分けが書かれているので、これをベースに考えるとよいでしょう。

ログレベル どういう意味か / いつ使用するべきか
DEBUG 詳細情報。典型的には、問題が発生した際に原因を突き止めようとする開発者向けの情報。
INFO 想定された通りのことが起こったことの確認。
WARNING 想定外の事象、または近い将来に問題が起きる可能性 (たとえば 'disk space low' すなわちディスク空き容量の低下) の表示。ソフトウエアは引き続き期待通りに動作している状態。
ERROR より重大な問題により、ソフトウェアがある機能を実行できないこと。
CRITICAL プログラム自体が実行を続けられないことを表す、重大なエラー。

ただし、必ずしもこれだけに準ずればよいとは限りません。たとえば、もしあなたが作っているものがアプリであれば次のようなことが考えられます。

  • ユーザの入力誤りは ERROR ログを出すようにしない。なぜなら、悪いユーザの行動次第で ERROR ログが大量に出てしまい、本当に気付かなければいけないログが埋もれてしまうから7。同じ理由で CRITICAL, WARNING も不適
  • ログの一部（重要なもの）はメールで通知したいという要件があるのであれば、「CRITICALのものはいちいちメール送信されるようにしよう（メール送信が不要な情報はCRITICALレベルで出さないようなルールにしよう）」と考える

随所で情報に富んだログを出す

いくらロギング設定を自由に変えられても、ロガーにメッセージが送信されていなければ何もできません。また、たいした情報が無ければログが出ていないのと変わりません。そこで、ログ送信は適宜実施し必要な情報を渡すために次の点に気を付けます。

プログラムの外部との入出力値を出す

何か問題が起きたときに、外部からの値を正しく受け取れているか、外部へ正しく出力できるかを調べたいことはよくあります。そのため、これらの値を出しておくと役立ちます。

def load_my_config(fp):
    config = json.load(fp)
    logger.info("設定ファイルをロードしました")
    logger.debug("TYPE: %s", config["TYPE"])
    logger.debug("INTERVAL: %d", config["INTERVAL"])

    return config

パスワードやトークンなどの認証情報は出力しないでください。

個人情報など取り扱いに注意が必要な情報も、出力するかどうかはよく検討してください。出力する場合、ログファイルも情報セキュリティ保護のために管理すべき対象になるかもしれません。

例外情報を出す

例外発生時の例外情報は問題解決に必要です。そのため、例外発生時は（例外発生をただの正常系 if 分岐替わりに使っている場合を除いて）その情報を出しておきましょう。キーワード引数 exc_info に例外インスタンスを指定します。

try:
    with open(filepath) as fp:
        load_config(fp)
except Exception as e:
    logger.error("設定ファイル読み込みに失敗しました", exc_info=e)
    # exc_info=True などでもよい。その場合 sys.exc_info() で得られる例外情報を使ってくれる。
    # .error() の代わりに .exception() を使うと exc_info を省略できる。

ここでの注意点は、例外は必ずしも ERROR レベルで出すべきとは限らないということで、特にアプリケーションを作っている場合に注意が必要です。たとえば、ログレベルの件でも述べたとおり、ユーザの入力ミスで ValueError が発生したときのログレベルは INFO や DEBUG とするべきです。

ライブラリを作っている場合、ログを見る人として『ライブラリを使用している開発者』を想定するので、ユーザのいたずらはひとまず考えなくてよいです。開発者に伝えるべき情報を、先述した「統一された基準」に従ったレベルでロガーへ送信しましょう。

なお、例外情報は、後述するカスタムフォーマッタを作っておけば、ロギング環境設定で出力しないように設定することも可能です。なので、出す・出さないを柔軟に決められるようにするためにも、ロガーには例外情報を渡すようにしておきましょう。

専門的でもいいので情報を出す

ログを読む人としては以下の対象を想定します。

  • ライブラリを作る場合：ライブラリを使用する開発者・そのライブラリを使って作られたアプリケーションの運用者・保守担当者
  • アプリケーションを作る場合：アプリケーションの運用者・保守担当者

いずれも専門家ですので、専門的な言い回しや表現を用いてでも正確で不足なく情報が載るようなメッセージにしましょう。

※for等のループではログ出力を制限する

具体的な制限ルールはログレベルと同様に検討すべき事項ですが、ループ内でのログ出力には注意が必要です。なぜなら、ロジック次第ではありますが同じようなログが何度も出ることになるため、あっというまにログファイルを埋め尽くしてしまう恐れもあるためです。

そのため、ログレベルの使い分けルールに応じて以下のようなルールの採用を検討しましょう。

  • for等のループでは、ループが中断する場合を除いて、DEBUGレベルのみを使用する
  • for等のループでは、ループが中断する場合やループが20回以下であることが保証されている場合を除いて、ログ出力しない
    • ループ回数保証は、関数呼び出しをまたいだ多重ループで過小評価しがちのため注意
  • for等のループでは、ループが中断する場合を除いて、ロガー名の末尾に .loop を付けた専用のロガーを使用する（ログ出力しないようにするロギング設定が面倒なのでライブラリ開発時は非推奨）

ログ送信を制限しない、設計書に「ログ出力する」と書いていなくても出してよいとする

この項目の是非は「設計書」の粒度によります。できあがるプログラムの各行と1対1対応するレベルで細かく設計書に書くスタンスをとる場合には当てはまりません。

一方で、設計書にすべてを書くことは不可能だと割り切るスタンスであれば、「○○の旨をログに出す」といちいち書かない（あるいは書いたつもりでも必要な情報が漏れる）ため、このルールは重要になります。

ログに出すべき情報は、プログラムの実装方式によって変わります。そのため、往々にして実装中に「この情報はログに出した方がいい」と気づくことになります。もし必要と気づいたログを出すために「設計書を修正し、出力する文言を書いておかなければならない」というルールがあると、そのことが足かせとなりログ送信をやめてしまいかねません。

そのため、先述したログレベルの使い分けとロガーの命名ルールを順守することが前提ですが、ログ送信の制限については上で述べた「for等のループではログ出力を制限する」のような最小限のルールに留めましょう。

今回はログメッセージの話ですが、一般利用者のUIに表示するメッセージであれば話が変わります。こちらはユーザの操作フロー・ユースケースを考慮して設計する必要があるため、基本的にはメッセージ出力のタイミングも場所も内容も設計書に記載されるべきであり、そのとおりに実装するべきです。

ユーザ向けメッセージの考え方に引きずられてログメッセージを不足させることが無いようにしましょう。

※メッセージそのものを設定で変えられるようには頑張らない

柔軟性を追求しようとすると、「メッセージの文面そのものも運用者が後から指定できると柔軟だ」と考えるかもしれませんが、これは考えない方がよいと思います。

まずメリットがそこまでありません。ログメッセージはアプリケーションのUIに表示されるメッセージと違い、開発者・運用者・保守担当者などの専門家しか読みません。そのため運用中に言い回しを変えたいということは基本的にありません（情報が足りないから増やしたいということは多々ありますが、この要望にはメッセージを可変にしていても対応できません）。

一方で手間は多くなります。そもそもメッセージそのものを差し替え可能にする機能は logging モジュールにないので、自分で用意することになります。差し替えに失敗しても情報は出るようにするなど考えることも多いため、差し替え機能自体を熟慮して設計しなければ、ちょっと不都合があっただけでログに情報が出なくなるような改悪にもなりかねません。

以上のことから、手間をかけてでも多言語対応したいなど特別な事情が無い限り、メッセージはソースコード内に直接記載し、% 指定子等を使用した情報の埋め込み以外は固定値で十分です。

今回はログメッセージの話ですが、一般利用者のUIに表示するメッセージであれば話が変わります。こちらは次に示すように、ソースコードの外でメッセージを定義するメリットがあり、また、ログメッセージほどのデメリットが生じません。

  • 複数個所で同じ文言を出したいことが多い
  • 出力のタイミングが設計で決まっていて、想定以上にメッセージの種類が多くなることが無い
  • メッセージ定義ファイルを文書レンダリングシステム (sphinx等) からも参照できるようにすると、説明書・マニュアルへも同一のメッセージを埋め込める（定義の修正だけで、プログラム本体にもマニュアルにも変更を反映できる）
  • ユーザビリティ向上のために言い回しを変えたい場合に、プログラム本体に手を付けずに修正できる（保守担当者の負担軽減）

カスタム属性情報 (extra) を活用する

この節は主にアプリケーション開発向けです。ライブラリ開発の場合、後述する条件に当てはまる属性があまりなく、カスタム属性をライブラリ利用者に周知する手間も考えるとメリットが少ないと思われます。

ロガーにログを送信する際、LogRecord 属性 として現在日時やログ出力箇所の行番号やPythonファイル名などの情報も自動で付加され、これらの情報はロギング環境設定次第ではログメッセージと一緒に出力することができます。

この情報は大変便利ですが、開発しているアプリケーションの性質次第では、より多くの情報を常に付加してログ出力を可能にしたいことがあります。いくつか具体例を挙げてみます。

  • （認証しての利用が前提であるアプリケーションで）ユーザ名
  • （WEBアプリケーションで）現在処理中のリクエストURL
  • （WEBアプリケーションで）リクエストごとにユニークなID
    • スレッドやプロセス毎にユニークなIDは LogRecord 属性 にすでにある
  • （バッチ処理で）バッチ処理実行毎にユニークなID（処理結果問い合わせに使用するID等）

これらの情報をログの全行に含められると、問題発生時に、発生時の事象を無関係の事象（同時刻に別プロセスで出力されたログ）と区別して効率よくログを読み進めることができるようになります。

そのために下記のようにキーワード引数 extra を使用できます。

# 関数 get_user_id_or_none() でユーザ名（非認証状態ならNone）を得られるようにしたとする
# 辞書 ctx から ["req_id"] でリクエスト固有のIDを得られるようにしたとする

def build_extra():
    # この関数でどんな例外が起きても、"user_id", "request_id" をキーに持つ辞書を返すようにする
    return {
        "user_id": get_user_id_or_none(),
        "request_id": ctx.get("req_id", None),
    }

def some_process():
    result = get_authorization()
    
    # ログ送信
    if result.failed:
        logger.error("認可情報取得エラー", extra=build_extra())

この例では、ロギング環境設定次第では現在時刻などと同様に user_id と request_id の二つのカスタム属性もログ出力の各行に埋め込むことができるようになっています。たとえば、ロギング環境設定次第では次のように出力できます。

2006-02-08 22:20:02,165 [REQ-00001234][user: foo] 認可情報取得エラー

extra で与える属性名は既存の LogRecord 属性 と重複してはいけません。

上記のとおり（カスタム属性を使用するよう設定した出力先に限りますが）ログ出力の全行に属性値が埋め込まれるため、大多数のログ出力で値が存在するような属性のみをカスタム属性としましょう。

この例では extra へ受け渡す辞書を生成する関数を作成していますが、これは、すべてのログ出力で同じ構成の辞書を extra へ渡すためです。ロギング環境設定では「特定の出力先へのログ出力でのみ特定のカスタム属性を埋め込む」ということができますが、埋め込もうとしているカスタム属性が付与されていないログを出力しようとするとエラーになってしまい、そのログが出力されません。このような事態を防ぐため、すべてのログ送信で共通の構成の extra をする必要があり、そのための手段として関数 build_extra を定義し使用しています。

上記の例でカスタム属性とした情報を extra を使用せず直接メッセージに埋め込んでもログ出力はできますが、「リクエストIDを出力したくなくなった」という要望に柔軟に応えられません。extra を使用しましょう。

アプリケーション開発（もしくはライブラリ開発のうちライブラリ自身のモジュール実行の箇所の開発）の場合はログ送信とその利用が内輪で完結するため、毎回 extra を使用する代わりに logging.setLogRecordFactory を使用して、LogRecord (ロガーへのログ送信時に作成される、現在時刻などログ出力に埋め込める属性を持つオブジェクト) にカスタム属性を持たせることもできます。

参考: https://qiita.com/podhmo/items/efb65ed90871ba2ac544#%E5%85%A8%E3%81%A6%E3%81%AE%E3%83%AD%E3%82%B0%E5%87%BA%E5%8A%9B%E3%81%AB%E7%89%B9%E5%AE%9A%E3%81%AE%E6%83%85%E5%A0%B1%E3%82%92%E4%BB%98%E5%8A%A0%E3%81%97%E3%81%A6%E3%83%AD%E3%82%B0%E5%87%BA%E5%8A%9B

後編へ続く

次は、ロギング環境設定です。作成する物に応じて環境設定をし、利用者のカスタム設定も読み込めるようにします。

  1. アプリやモジュール実行の最初の方で設定をロードする。デフォルト設定の実装者は、カスタム設定をロードできるように作る。 ↩ ↩2

  2. ここでいう「アプリ」とは、当該ライブラリを利用するアプリケーションのこと。つまり、ロガーへのメッセージ送信はライブラリ側、ロギング環境設定はアプリ側となり、内輪で完結しないということ。 ↩ ↩2

  3. python -m <モジュール名> で実行できる <モジュール名>/__main__.py のこと。 ↩

  4. 先述した「仕組みを説明するコード」ではこの点を満たせないことが多いです。 ↩

  5. 運用者なら運用担当者へメール送信したいと考えるかもしれません。これもロギング環境設定で可能です。 ↩

  6. あなたが作成したライブラリ以外のライブラリが使うロガーや、あなたのライブラリの利用者が使うロガーも含みます ↩

  7. フロントエンドでバリデーションしているから ValueError が起きるはずないので ERROR レベルにするという論理も成立はしますが、WEB開発において悪いユーザへの対策は「フロントエンドのあらゆる機能を迂回してサーバアクセスできる・してくる」という前提で考えるべきなので、よく検討しましょう。 ↩

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?