Pythonロギング：詳細なチュートリアル

公開: 2022-03-11

アプリケーションがより複雑になるにつれて、優れたログを持つことは、デバッグ時だけでなく、アプリケーションの問題/パフォーマンスに関する洞察を提供する場合にも非常に役立ちます。

Python標準ライブラリには、基本的なロギング機能のほとんどを提供するロギングモジュールが付属しています。 正しく設定することにより、ログメッセージは、ログがいつどこで発生するか、および実行中のプロセス/スレッドなどのログコンテキストに関する多くの有用な情報をもたらすことができます。

利点にもかかわらず、ロギングモジュールは、適切にセットアップするのに時間がかかるため、見過ごされがちです。完全ではありますが、私の意見では、https：//docs.python.org/3/library/logging.htmlの公式ロギングドキュメントです。ロギングのベストプラクティスを実際に提供したり、ロギングの驚きを強調したりすることはありません。

このPythonロギングチュートリアルは、ロギングモジュールに関する完全なドキュメントではなく、ロギングの概念と注意すべき「落とし穴」を紹介する「はじめに」ガイドを目的としています。 投稿はベストプラクティスで終わり、より高度なロギングトピックへのポインタが含まれています。

投稿内のすべてのコードスニペットは、ロギングモジュールをすでにインポートしていることを前提としていることに注意してください。

 import logging

Pythonロギングの概念

このセクションでは、ロギングモジュールでよく見られるいくつかの概念の概要を説明します。

Pythonのログレベル

ログレベルは、ログに与えられる「重要性」に対応します。「エラー」ログは「警告」ログよりも緊急である必要がありますが、「デバッグ」ログはアプリケーションをデバッグする場合にのみ役立ちます。

Pythonには6つのログレベルがあります。 各レベルは、ログの重大度を示す整数に関連付けられています：NOTSET = 0、DEBUG = 10、INFO = 20、WARN = 30、ERROR = 40、およびCRITICAL=50。

PythonLoggingのログレベル

NOTSETを除いて、すべてのレベルはかなり単純です（DEBUG <INFO <WARN）。その特殊性については次に説明します。

Pythonロギングフォーマット

ログフォーマッタは基本的に、コンテキスト情報を追加することでログメッセージを充実させます。 ログがいつ送信されるか、どこに送信されるか（Pythonファイル、行番号、メソッドなど）、およびスレッドやプロセスなどの追加のコンテキスト（マルチスレッドアプリケーションをデバッグするときに非常に役立ちます）を知ることが役立つ場合があります。

たとえば、ログ「helloworld」がログフォーマッターを介して送信される場合：

 "%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

になります

2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world

Pythonロギングメッセージのフォーマット

Pythonロギングハンドラー

ログハンドラーは、ログを効果的に書き込み/表示するコンポーネントです。コンソール（StreamHandlerを介して）、ファイル（FileHandlerを介して）、またはSMTPHandlerなどを介して電子メールを送信することによってログを表示します。

各ログハンドラーには、2つの重要なフィールドがあります。

  • ログにコンテキスト情報を追加するフォーマッター。
  • レベルが劣るログを除外するログレベル。 したがって、INFOレベルのログハンドラーはDEBUGログを処理しません。

Pythonロギングハンドラー

標準ライブラリは、一般的なユースケースに十分な数のハンドラーを提供します：https：//docs.python.org/3/library/logging.handlers.html#module-logging.handlers。 最も一般的なものはStreamHandlerとFileHandlerです。

 console_handler = logging.StreamHandler() file_handler = logging.FileHandler("filename")

Pythonロガー

ロガーは、おそらくコードで最も頻繁に直接使用されるものであり、最も複雑でもあります。 新しいロガーは次の方法で入手できます。

 toto_logger = logging.getLogger("toto")

ロガーには3つの主要なフィールドがあります。

  • 伝播：ログをロガーの親に伝播するかどうかを決定します。 デフォルトでは、その値はTrueです。
  • レベル：ログハンドラーレベルと同様に、ロガーレベルは「重要度の低い」ログを除外するために使用されます。 ただし、ログハンドラーとは異なり、レベルは「子」ロガーでのみチェックされます。 ログがその親に伝播されると、レベルはチェックされません。 これはかなり直感的でない動作です。
  • ハンドラー：ログがロガーに到着したときに送信されるハンドラーのリスト。 これにより、柔軟なログ処理が可能になります。たとえば、すべてのDEBUGログをログに記録するファイルログハンドラーと、CRITICALログにのみ使用される電子メールログハンドラーを設定できます。 この点で、ロガーとハンドラーの関係は、パブリッシャーとコンシューマーの関係に似ています。ログは、ロガーレベルのチェックに合格すると、すべてのハンドラーにブロードキャストされます。

Pythonロギングのプロセス

ロガーは名前で一意です。つまり、「toto」という名前のロガーが作成されている場合、 logging.getLogger("toto")を呼び出すと同じオブジェクトが返されます。

 assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

ご想像のとおり、ロガーには階層があります。 階層の最上位にはルートロガーがあり、logging.rootからアクセスできます。 このロガーは、 logging.debug()などのメソッドが使用されるときに呼び出されます。 デフォルトでは、ルートログレベルはWARNであるため、より低いレベルのすべてのログ（たとえば、 logging.info("info")を介して）は無視されます。 ルートロガーのもう1つの特徴は、WARNより大きいレベルのログが最初にログに記録されたときにデフォルトのハンドラーが作成されることです。 通常、 logging.debug()などのメソッドを介してルートロガーを直接または間接的に使用することはお勧めしません。

デフォルトでは、新しいロガーが作成されると、その親はルートロガーに設定されます。

 lab = logging.getLogger("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

ただし、ロガーは「ドット表記」を使用します。つまり、「ab」という名前のロガーは、ロガー「a」の子になります。 ただし、これはロガー「a」が作成されている場合にのみ当てはまります。それ以外の場合は、「ab」の親がルートのままです。

 la = logging.getLogger("a") assert lab.parent == la # lab's parent is now la instead of root

ロガーがレベルチェックに従ってログに合格するかどうかを決定する場合（たとえば、ログレベルがロガーレベルよりも低い場合、ログは無視されます）、実際のレベルではなく「有効レベル」を使用します。 レベルがNOTSETでない場合、つまりDEBUGからCRITICALまでのすべての値の場合、有効なレベルはロガーレベルと同じです。 ただし、ロガーレベルがNOTSETの場合、有効なレベルは、NOTSET以外のレベルを持つ最初の祖先レベルになります。

デフォルトでは、新しいロガーにはNOTSETレベルがあり、ルートロガーにはWARNレベルがあるため、ロガーの有効レベルはWARNになります。 したがって、新しいロガーにいくつかのハンドラーが接続されている場合でも、ログレベルがWARNを超えない限り、これらのハンドラーは呼び出されません。

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

デフォルトでは、ログが通過するかどうかを決定するためにロガーレベルが使用されます。ログレベルがロガーレベルよりも低い場合、ログは無視されます。

Pythonロギングのベストプラクティス

ロギングモジュールは確かに非常に便利ですが、最高のPython開発者でさえ長時間の頭痛の種となる可能性のあるいくつかの癖が含まれています。 私の意見では、このモジュールを使用するためのベストプラクティスは次のとおりです。

  • ルートロガーを構成しますが、コードで使用しないでください。たとえば、実際にルートロガーをバックグラウンドで呼び出すlogging.info()のような関数を呼び出さないでください。 使用しているライブラリからのエラーメッセージをキャッチしたい場合は、たとえば、デバッグを容易にするために、ファイルに書き込むようにルートロガーを構成してください。 デフォルトでは、ルートロガーはstderrにのみ出力するため、ログは簡単に失われる可能性があります。
  • ロギングを使用するには、 logging.getLogger(logger name)を使用して新しいロガーを作成してください。 私は通常、ロガー名として__name__を使用しますが、一貫している限り、何でも使用できます。 さらにハンドラーを追加するために、私は通常、ロガーを返すメソッドを持っています（要点はhttps://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0にあります）。
 import logging import sys from logging.handlers import TimedRotatingFileHandler FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") LOG_FILE = "my_app.log" def get_console_handler(): console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(FORMATTER) return console_handler def get_file_handler(): file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight') file_handler.setFormatter(FORMATTER) return file_handler def get_logger(logger_name): logger = logging.getLogger(logger_name) logger.setLevel(logging.DEBUG) # better to have too much log than not enough logger.addHandler(get_console_handler()) logger.addHandler(get_file_handler()) # with this pattern, it's rarely necessary to propagate the error up to parent logger.propagate = False return logger

新しいロガーを作成して使用できるようになったら、次のようにします。

 my_logger = get_logger("my module name") my_logger.debug("a debug message")
  • FileHandlerの代わりに、例で使用されているTimedRotatingFileHandlerなどのRotatingFileHandlerクラスを使用します。これは、ファイルがサイズ制限に達したとき、または毎日実行するときに、ファイルを自動的に回転させるためです。
  • Sentry、Airbrake、Raygunなどのツールを使用して、エラーログを自動的にキャッチします。 これは、ログが非常に冗長になり、エラーログが簡単に失われる可能性があるWebアプリのコンテキストで特に役立ちます。 これらのツールを使用するもう1つの利点は、エラーの変数値に関する詳細を取得できるため、どのURLがエラーをトリガーしたか、どのユーザーが関係しているかなどを知ることができることです。

より多くのベストプラクティスに興味がある場合は、Python開発者が仲間のToptalerMartinChikilianによって犯す10の最も一般的な間違いを読んでください。