いろいろ備忘録日記

主に .NET とか Go とか Flutter とか Python絡みのメモを公開しています。

Pythonメモ-75 (ライブラリメモ - logging) (getLogger, basicConfig, dictConfig, raven, SentryHandler)

概要

標準ライブラリの logging についてのメモです。

Pythonには、初めから標準ライブラリで loggingが付いています。

他の言語の場合だと、別途ライブラリを使ったりする(log4jとかlog4netとか)ところ、そのまま使えます。

とても便利。。。なのですが、このloggingモジュールさん、ちょこっととっつきにくいです。

たまに使うと、結構忘れるので以下に個人メモしています。参考になれば。

まだ途中なので、サンプル作ったらまた更新する予定。

最後についでに個人的に大好きなサービス Sentrylogging の連携を記載しています。

基本パターン (ログレベルの変更)

デフォルトのまま使うと、ログレベルはWARNINGとなっています。なので、INFOとかは出力されません。

一番ラクなのは、logging.basicConfig()でログレベルを指定しまうこと。

"""
logging モジュールのサンプルです。
最も基本的な使い方について (ログレベルの変更)
"""
import logging

from trypython.common.commoncls import SampleBase


class Sample(SampleBase):
    def exec(self):
        """サンプル処理を実行します。"""
        # --------------------------------------------------------
        # logging モジュールは、python 標準ライブラリで他の言語でいう log4jやlog4netなど
        # と同様にロギング処理を提供するもの。公式ドキュメントでは以下のURLで説明が記載されている。
        #
        #     https://docs.python.jp/3/library/logging.html
        #
        # このモジュールは、非常に多機能であるため以下のチュートリアルが用意されている。
        #
        #     基本: https://docs.python.jp/3/howto/logging.html#logging-basic-tutorial
        #     上級: https://docs.python.jp/3/howto/logging.html#logging-advanced-tutorial
        #
        # ---------------------------------------------------------
        # logging モジュールで定義されている ログレベル は、以下の5つ。
        #
        #   DEBUG
        #   INFO
        #   WARNING
        #   ERROR
        #   CRITICAL
        #
        # 下にいくほど、ログレベルが高い。
        # デフォルトのログレベルは、 WARNING となっている。 
        # なので、何の設定もしないまま logging モジュールを使うと
        # WARNING 以上のログレベルのみ出力が行われる。 
        # 出力先は、デフォルトでは 標準エラー に出力される。
        # --------------------------------------------------------
        # logging モジュールを利用する際に最も簡単に設定が行えるやり方は
        #
        #     logging.basicConfig()
        #
        # を利用することである。この関数は、多くのキーワード引数を備えており
        # 指定することで logging モジュールの全体設定が行えるようになっている。
        #
        #     https://docs.python.jp/3/library/logging.html#logging.basicConfig
        #
        # --------------------------------------------------------
        # 今回は最も簡単なところの、ログレベルの調整から。
        # WARNING がデフォルトレベルなので、変更する
        logging.basicConfig(level=logging.INFO)
        logger = logging.getLogger(__name__)

        # それぞれのログレベルで出力
        logger.debug('debug')
        logger.info('info')
        logger.warning('warn')
        logger.error('error')
        logger.critical('critical')

        # ロギングを終了。強制的に flush を実施。
        # 基本必要ないが、大量にログを入れた後にすぐに終了や
        # 対象ログファイルを開こうとすると、PermissionErrorが発生
        # する場合があるため。
        logging.shutdown()

        # [結果]
        # --------------------------------------
        # INFO: __main__:info
        # WARNING: __main__:warn
        # ERROR: __main__:error
        # CRITICAL: __main__:critical


def go():
    """処理を実行します。"""
    obj = Sample()
    obj.exec()


if __name__ == '__main__':
    go()

try-python/logging01.py at master · devlights/try-python · GitHub

結果は

INFO:__main__:info
WARNING:__main__:warn
ERROR:__main__:error
CRITICAL:__main__:critical

となります。

基本パターン (ファイルへの出力)

ログレベルと同様に logging.basicConfig()filenameを指定するとそのファイルに出力されます。

"""
logging モジュールのサンプルです。
最も基本的な使い方について (ファイルへの出力)
"""
import logging
import pathlib
import tempfile

from trypython.common.commoncls import SampleBase


class Sample(SampleBase):
    def exec(self):
        """サンプル処理を実行します。"""
        # --------------------------------------------------------
        # logging モジュールは、python 標準ライブラリで他の言語でいう log4jやlog4netなど
        # と同様にロギング処理を提供するもの。公式ドキュメントでは以下のURLで説明が記載されている。
        #
        #     https://docs.python.jp/3/library/logging.html
        #
        # このモジュールは、非常に多機能であるため以下のチュートリアルが用意されている。
        #
        #     基本: https://docs.python.jp/3/howto/logging.html#logging-basic-tutorial
        #     上級: https://docs.python.jp/3/howto/logging.html#logging-advanced-tutorial
        #
        # --------------------------------------------------------
        # 今回も、 logging.basicConfig() について
        # filename キーワードを指定して、出力するファイル名を指定する。
        # --------------------------------------------------------
        logdir = pathlib.Path(tempfile.gettempdir())
        logfile = logdir / 'logging02.log'
        logging.basicConfig(level=logging.INFO, filename=str(logfile))
        logger = logging.getLogger(__name__)

        # それぞれのログレベルで出力
        logger.debug('debug')
        logger.info('info')
        logger.warning('warn')
        logger.error('error')
        logger.critical('critical')

        # ロギングを終了。強制的に flush を実施。
        # 基本必要ないが、大量にログを入れた後にすぐに終了や
        # 対象ログファイルを開こうとすると、PermissionErrorが発生
        # する場合があるため。
        #
        # 今回のサンプルのように、ログ・ファイルに出力して、すぐにそのファイルを
        # 開こうとすると PermissionError が発生する場合がある。
        # (丁度 logging が、そのファイルに出力している最中に開くと例外となる)
        logging.shutdown()

        with logfile.open(mode='r', encoding='utf-8') as f:
            for l in f:
                print(l, end='')

        logfile.unlink()


def go():
    """処理を実行します。"""
    obj = Sample()
    obj.exec()


if __name__ == '__main__':
    go()

try-python/logging02.py at master · devlights/try-python · GitHub

結果は

INFO:__main__:info
WARNING:__main__:warn
ERROR:__main__:error
CRITICAL:__main__:critical

となります。

基本パターン (フォーマッタの指定)

出力する書式を変更したい場合、最も簡単なのが logging.basicConfig()でフォーマットを指定することです。

"""
logging モジュールのサンプルです。
最も基本的な使い方について (フォーマッタの指定)
"""
import logging

from trypython.common.commoncls import SampleBase


class Sample(SampleBase):
    def exec(self):
        """サンプル処理を実行します。"""
        # --------------------------------------------------------
        # logging モジュールは、python 標準ライブラリで他の言語でいう log4jやlog4netなど
        # と同様にロギング処理を提供するもの。公式ドキュメントでは以下のURLで説明が記載されている。
        #
        #     https://docs.python.jp/3/library/logging.html
        #
        # このモジュールは、非常に多機能であるため以下のチュートリアルが用意されている。
        #
        #     基本: https://docs.python.jp/3/howto/logging.html#logging-basic-tutorial
        #     上級: https://docs.python.jp/3/howto/logging.html#logging-advanced-tutorial
        #
        # --------------------------------------------------------
        # 今回も、 logging.basicConfig() について
        # format キーワードを指定して、出力文字列のフォーマットを変更する。
        # format 文字列内にて指定できるキーワードについては、以下を参照。
        #
        #     https://docs.python.jp/3/library/logging.html#logrecord-attributes
        #
        # 追加で指定できる属性値については、以下を参照。
        #
        #     https://docs.python.jp/3/library/string.html#formatstrings
        #
        # つまり、左寄せで8文字表示にするには以下のように指定する。
        #
        #     %(levelname)-8s
        #
        # 逆に、右寄せで8文字表示にするには以下のように指定する。
        #
        #     %(levelname)8s
        #
        # --------------------------------------------------------
        fmt = '[%(asctime)s][%(levelname)-8s] %(name)s %(filename)s:%(funcName)s:%(lineno)d | %(message)s'
        logging.basicConfig(level=logging.WARNING, format=fmt)
        logger = logging.getLogger(__name__)

        # それぞれのログレベルで出力
        logger.debug('debug')
        logger.info('info')
        logger.warning('warn')
        logger.error('error')
        logger.critical('critical')

        # logging を終了
        logging.shutdown()


def go():
    """処理を実行します。"""
    obj = Sample()
    obj.exec()


if __name__ == '__main__':
    go()

try-python/logging03.py at master · devlights/try-python · GitHub

結果は

[2018-04-19 23:02:42,858][WARNING ] __main__ logging03.py:exec:51 | warn
[2018-04-19 23:02:42,858][ERROR   ] __main__ logging03.py:exec:52 | error
[2018-04-19 23:02:42,859][CRITICAL] __main__ logging03.py:exec:53 | critical

となります。

基本パターン (日付書式の設定)

loggingモジュールでは、logging.basicConfig()datafmtパラメータを指定することで、日付書式を設定することが出来ます。ですが、pythonの日付書式は他の言語とちょっと変わっていてミリ秒の指定の仕方がちょっとクセがあります。(ちょっとハマりました)他の言語と同じような感じでやるとマイクロ秒となりますので注意。

"""
logging モジュールのサンプルです。
最も基本的な使い方について (日付書式の指定)
"""
import logging

from trypython.common.commoncls import SampleBase


class Sample(SampleBase):
    def exec(self):
        """サンプルの処理を実行します。"""
        # --------------------------------------------------------
        # logging モジュールは、python 標準ライブラリで他の言語でいう log4jやlog4netなど
        # と同様にロギング処理を提供するもの。公式ドキュメントでは以下のURLで説明が記載されている。
        #
        #     https://docs.python.jp/3/library/logging.html
        #
        # このモジュールは、非常に多機能であるため以下のチュートリアルが用意されている。
        #
        #     基本: https://docs.python.jp/3/howto/logging.html#logging-basic-tutorial
        #     上級: https://docs.python.jp/3/howto/logging.html#logging-advanced-tutorial
        #
        # --------------------------------------------------------
        # 今回も、 logging.basicConfig() について
        # datefmt キーワードを指定して、日付文字列のフォーマットを変更する。
        # datefmt 文字列内にて指定できるキーワードについては、以下を参照。
        # (time.strftime() と同じ書式が指定できる)
        #
        #     https://docs.python.jp/3/library/time.html#time.strftime
        #
        # デフォルトは now.strftime('%Y-%m-%d %H:%M:%S.%f')[:-3] と同じ形。
        # --------------------------------------------------------
        # ミリ秒をログに出力するやり方
        # --------------------
        # Pythonの日付書式は、他の言語と比べると少し変わっていて、ミリ秒のための書式が存在しない。
        # strftime() の書式では、 %f と指定すると「マイクロ秒」が出力される。
        # そのため、通常の sftftime() の場合は、%fを指定して、前3桁を有効とするようする。
        #
        # が、loggingで指定する datefmt で %f を指定すると
        # 実行時に例外が発生する。 (ValueError)
        #
        # (datetime.datetime.now().sftftime('%H:%M:%S.%f') はエラーとならない・・・)
        #
        # では、どのようにしてミリ秒を表示するのかという話題になるが
        # 以下のスレッドの情報がとても有用だった。
        #
        #     https://stackoverflow.com/a/7517430/190597
        #
        # %(msecs)d と指定するとミリ秒が出力できる。
        #
        # この場合、format と datefmt の両方を指定する必要がある。
        # %(msecs)d は、 %(asctime)s とペアで使用する必要があるので
        # 結局以下のように指定する。
        #
        #     %(asctime)s.%(msecs)03d
        #     (--> 03d は、3桁表示でゼロ埋めせよという指示 (3 --> 003))
        #
        # 間の「.」は、出力時の秒とミリ秒の間に入る文字を表す。
        # ここをカンマにすると 15:14:23,333 となる。
        #
        # Pythonドキュメントでは、以下のところに記載がある。
        #     https://docs.python.jp/3/library/logging.html#logrecord-attributes
        # --------------------------------------------------------
        fmt = '[%(asctime)s.%(msecs)03d] | %(message)s'
        datefmt = '%Y/%m/%d %H:%M:%S'  # ここで %f を指定すると実行時にフォーマットエラーになるので注意.
        logging.basicConfig(format=fmt, datefmt=datefmt, level=logging.INFO)

        logger = logging.getLogger(__name__)
        logger.warning('warning')

        # logging を終了
        logging.shutdown()


def go():
    """処理を実行します。"""
    obj = Sample()
    obj.exec()


if __name__ == '__main__':
    go()

try-python/logging04.py at master · devlights/try-python · GitHub

結果は

[2018/04/19 23:06:23.043] | warning

となります。

応用編 (ハンドラの指定)

まだ途中・・・。

try-python/logging05.py at master · devlights/try-python · GitHub

応用編 (フィルタの指定)

まだ途中・・・。

try-python/logging06.py at master · devlights/try-python · GitHub

応用編 (フォーマッタの指定)

まだ途中・・・。

try-python/logging07.py at master · devlights/try-python · GitHub

応用編 (isEnabledFor()の使い方)

まだ途中・・・。

try-python/logging08.py at master · devlights/try-python · GitHub

応用編 (logging.config.dictConfig() の使用)

loggingでは、設定情報を外部に出して実行時に読み込む機能があります。

logging.config.dictConfig() も、その一つで 辞書形式になっているデータを読み込み設定を行います。

json 形式をそのまま読み込めるので便利です。

{
    "version": 1,
    "disable_existing_loggers": "true",
    "formatters": {
        "console": {
            "format": "[%(asctime)s][%(levelname)-8s] %(name)s %(filename)s:%(funcName)s:%(lineno)d | %(message)s",
            "datefmt": "%Y/%m/%d %H:%M:%S"
        }
    },
    "handlers": {
        "console": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "console",
            "stream": "ext://sys.stderr"
        }
    },
    "loggers": {
        "": {
            "handlers": ["console"],
            "level": "WARNING",
            "propagate": "false"
        }
    }
}

try-python/logging_config.json at master · devlights/try-python · GitHub

"""
logging モジュールのサンプルです。
応用編 (logging.config.dictConfig() の使用)

REFERENCES::
https://docs.python.jp/3/library/logging.config.html#logging-config-dictschema
https://docs.sentry.io/clients/python/integrations/logging/
https://stackoverflow.com/questions/38323810/does-pythons-logging-config-dictconfig-apply-the-loggers-configuration-setti
"""
import logging
import logging.config
import json
import pathlib

from trypython.common.commoncls import SampleBase


class Sample(SampleBase):
    def exec(self):
        """サンプルの処理を実行します。"""
        # --------------------------------------------------------
        # logging.config.dictConfig() の使用
        # loggingでは、設定情報を外部に出して実行時に読み込む機能があります。
        #
        # logging.config.dictConfig() も、その一つで 辞書形式になっているデータを読み込み設定を行います。
        #
        # json形式をそのまま読み込めるので便利です。
        # 本サンプルでの設定内容に関しては、 logging_config.json ファイルを参照ください。
        # --------------------------------------------------------
        config_file = pathlib.Path('logging_config.json')
        with config_file.open(mode='r', encoding='utf-8') as fd_conf:
            logging.config.dictConfig(json.load(fd_conf))

        logger = logging.getLogger(__name__)

        logger.debug('debug message')
        logger.info('info message')
        logger.warning('warning message')
        try:
            1 / 0
        except ZeroDivisionError:
            logger.error('error message', exc_info=True)


def go():
    """処理を実行します。"""
    obj = Sample()
    obj.exec()


if __name__ == '__main__':
    go()

try-python/logging09.py at master · devlights/try-python · GitHub

結果は

[2018/04/19 23:13:05][WARNING ] __main__ logging09.py:exec:38 | warning message
[2018/04/19 23:13:05][ERROR   ] __main__ logging09.py:exec:42 | error message
Traceback (most recent call last):
  File "/Users/xxxx/PycharmProjects/try-python/trypython/stdlib/logging09.py", line 40, in exec
    1 / 0
ZeroDivisionError: division by zero

となります。

応用編 (Sentry と logging の連携)

Sentry というサービスがあります。結構有名かもしれません。

sentry.io

エラー情報をトラッキングしてくれるサービスです。

コードにてSentryのライブラリを仕込んでおくと、後は勝手に Sentry 側に送られて情報をまとめてくれるという感じです。同一ログをまとめてくれたり、エラー情報を解決済みとかマーク出来たりするので、個人的にはとても気に入ってます。

Sentry 自身はオープンソースなソフトウェアなので、オンプレミスでインストールすることも出来るみたい。(やったことはないですが)

使い方などは以下に記載されています。

Sentry Documentation

で、Sentry は、いろいろな言語から利用できるのですが

もちろん pythonからも利用できます。(Sentry 自体も Python で作られています。)

Pythonから利用する場合、クライアントライブラリを入れる必要があります。

Sentry の Python ライブラリは raven という名前のモジュールです。

インストールは、conda からでも pip からでも行なえます。以下は conda の例。

$ conda install raven -y

ravenlogging モジュールは連携することが出来ます。

raven の中に SentryHandler というlogging 側に設定できるハンドラが用意されているので

それを設定すれば完了です。めちゃ簡単。

SENTRY を使う場合、別途IDとなる SENTRY_DSNというのが必要になるのですが(APIキーみたいなものです)

これは通常環境変数とかに設定しておきます。raven 側のクラスは環境変数に SENTRY_DSNというキーがあるのかを見てくれていますので、この方法で設定しておけば、何もしなくても設定完了となります。

"""
logging モジュールのサンプルです。
応用編 (Sentry と logging の連携)

Sentry の Python ライブラリは raven という名前のモジュールです。
インストールは、conda からでも pip からでも行なえます。以下は conda の例。

$ conda install raven -y

参考情報::
https://docs.sentry.io/
https://docs.sentry.io/clients/python/
"""
import logging

from raven import Client
from raven.conf import setup_logging
from raven.handlers.logging import SentryHandler

from trypython.common.commoncls import SampleBase


class Sample(SampleBase):
    def exec(self):
        """サンプルの処理を実行します。"""
        # --------------------------------------------------------
        # Sentry と logging の組み合わせのサンプル
        # Sentry DSN は 環境変数 SENTRY_DSN に設定してから起動します。
        #
        # ログレベルがDEBUGやINFOのものもSentryに送信するには
        # 以下のように logging 側の level と SentryHandler 側の level を調整します。
        #
        # (*) Windowsの場合、一時設定するには以下のようにします。
        #
        #     $ set SENTRY_DSN=xxxxx
        #
        # (*) bashの場合、一時設定するには以下のようにします。
        #
        #     $ export SENTRY_DSN=xxxxx
        #
        # (*) PyCharmの場合、実行時構成の画面にて環境変数の設定ができるので、そこで設定しておく。
        #
        #     https://www.jetbrains.com/help/pycharm/run-debug-configuration-python.html
        #
        # 参考情報::
        #     https://docs.python.jp/3/library/logging.config.html#logging-config-dictschema
        #     https://docs.sentry.io/clients/python/integrations/logging/
        #
        # 以下で、Sentryとの連携を行っています。
        # loggingモジュールとSentryのライブラリ (raven) の連携自体は 
        #     setup_logging() 
        # を呼び出すだけで完了します。
        #
        # その際、 SentryHanler() の設定時に どのログレベルで Sentry に送るかを決めておきます。
        # (以下の例では、ログレベルがERROR以上の場合のみSentryに連携しています。
        #    それよりも低いログレベルの場合は通常のログ出力が行われます。)
        #
        # --------------------------------------------------------
        fmt = '[%(asctime)s][%(levelname)-8s] %(name)s %(filename)s:%(funcName)s:%(lineno)d | %(message)s'
        logging.basicConfig(level=logging.INFO, format=fmt)

        client = Client()  # 引数に何も指定しない場合、環境変数[SENTRY_DSN]から読み取られる
        handler = SentryHandler(client, level=logging.ERROR)
        setup_logging(handler)

        logger = logging.getLogger(__name__)

        logger.debug('debug message')
        logger.info('info message')
        logger.warning('warning message')
        try:
            1 / 0
        except ZeroDivisionError:
            logger.error('error message', exc_info=True)


def go():
    """処理を実行します。"""
    obj = Sample()
    obj.exec()


if __name__ == '__main__':
    go()

try-python/logging10.py at master · devlights/try-python · GitHub

結果は

[2018-04-19 23:26:48,583][INFO    ] __main__ logging10.py:exec:65 | info message
[2018-04-19 23:26:48,583][WARNING ] __main__ logging10.py:exec:66 | warning message
[2018-04-19 23:26:48,583][ERROR   ] __main__ logging10.py:exec:70 | error message
Traceback (most recent call last):
  File "/Users/xxxx/PycharmProjects/try-python/trypython/stdlib/logging10.py", line 68, in exec
    1 / 0
ZeroDivisionError: division by zero
Sentry is attempting to send 1 pending error messages
Waiting up to 10 seconds
Press Ctrl-C to quit

となります。最後の3行のところを見ると、Sentry側に送られているのが分かります。

この後、Sentryにログインして確認すると、ちゃんとログが飛んでいます。


過去の記事については、以下のページからご参照下さい。

サンプルコードは、以下の場所で公開しています。