5
5

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 3 years have passed since last update.

Pythonのloggingに[ファイル名:行番号 メソッド名]を出力できるようにしたい

Last updated at Posted at 2021-04-01

本タイトルの内容を調べてみて自前で実装したのですが、公式に同じ機能があり、役に立たなそうだから供養という体裁をとっていました。
実際に使ってみるとちょっと想定と違う挙動になったので書き直しています。

#【追記】0.問題意識
awsのlambdaを使って開発をしています。
設計上のひとつの秩序として、処理系はClassでまとめて、メソッドはlambdaのエントリーポイントのみということにしてみました。
ログの出力処理もClassでまとめようと考えています。
その際に、loggingにある機能をつかって本タイトルの実装としようとしたところ、ログ出力用Class内で実行したログ出力処理を行番号・メソッド名として出力するという結果になりました。
これだと意味がないので、やっぱり使い物になるかも説

##1.結論から言うloggingに機能はあるけどちょっと違った。
loggingにそういう機能がありました。
https://docs.python.org/ja/3/library/logging.html#logging.LogRecord

【追記】
似たような機能はありましたが、こちらはlog.debugなどのログ出力の実行場所が記録されるだけということがわかりました。

検証1

logger.py
import logging

def test_method():

    log = logging.getLogger()
    formatter = "[%(asctime)s] [%(process)d] [%(levelname)s] [%(filename)s:%(lineno)d %(funcName)s] %(message)s "
    logging.basicConfig(level=logging.DEBUG, format=formatter)
    log.debug('test')

test_method()

実行結果

[2021-04-01 11:49:39,995] [57865] [DEBUG] [logger.py:8 test_method] test 

便利〜

【追記】
便利じゃなかった。

検証2

logger.py
class Logger():
    """
    ログ出力用クラス
    """
    def __init__(self):
        self.logger = logging.getLogger()
        self.logger.setLevel(logging.DEBUG)
        formatter = logging.Formatter(
          '[%(levelname)s]\t%(asctime)s.%(msecs)dZ\t%(aws_request_id)s\t%(filename)s\t%(funcName)s\t%(lineno)d\t%(message)s\n',
          '%Y-%m-%dT%H:%M:%S'
        )
        for handler in self.logger.handlers:
            handler.setFormatter(formatter)

    def debug(self, log_message):
        self.logger.debug(log_message)

    def info(self, log_message):
        self.logger.info(log_message)

    def warning(self, log_message):
        self.logger.warning(log_message)

    def error(self, log_message):
        self.logger.error(log_message)


def test_method(event, context):
    log = Logger()
    log.debug('test debug')
    log.info('test info')
    log.warning('test warning')
    log.error('test error')

[DEBUG]	2021-04-01T04:20:35.437Z	87afa56f-bb0a-435e-8652-8dbc61c3be91 logger.py	debug	20	test debug
[INFO]	2021-04-01T04:20:35.437Z	87afa56f-bb0a-435e-8652-8dbc61c3be91	logger.py	info	23	test info
[WARNING]	2021-04-01T04:20:35.437Z	87afa56f-bb0a-435e-8652-8dbc61c3be91 logger.py	warning	26	test warning
[ERROR]	2021-04-01T04:20:35.437Z	87afa56f-bb0a-435e-8652-8dbc61c3be91	logger.py	error	29	test error

最初の検証と違う環境で実行しているので、「ファイル名 メソッド名 行番号」になっています。
メソッドがtest_methodになっておらず、また行番号もclass内の行番号になっています。
これではいかん。

##2.【供養】最初無いもんだと思ってやったこと実はこれでよかった

logger.py
import logging
import inspect
import os

class Logger():
    """
    ログ出力用クラス
    """
    def __init__(self):
        self.logger = logging.basicConfig(level=logging.DEBUG, format="[%(asctime)s] [%(process)d] [%(name)s] [%(levelname)s] %(message)s")

    def debug(self, execution_location, log_message):
        self.logger = logging.getLogger(execution_location)
        self.logger.debug(log_message)

    def info(self, execution_location, log_message):
        self.logger = logging.getLogger(execution_location)
        self.logger.info(log_message)

    def warning(self, execution_location, log_message):
        self.logger = logging.getLogger(execution_location)
        self.logger.warning(log_message)

    def error(self, execution_location, log_message):
        self.logger = logging.getLogger(execution_location)
        self.logger.error(log_message)

class Trace():
    """
    ログ出力とセットで使う処理をまとめたクラス
    """
    @classmethod
    def execution_location(self):
        """
        処理の実行場所を出力する。[ファイル名: 行番号  メソッド名]
        """
        frame = inspect.currentframe().f_back
        return "{}:{} {}".format(os.path.basename(frame.f_code.co_filename), frame.f_lineno, frame.f_code.co_name)

def test_method():
    log = Logger()
    log.debug(Trace.execution_location(), 'debug test')

test_method()

実行結果

[2021-04-01 12:11:05,181] [62612] [logger.py:42 test_method] [DEBUG] debug test

inspectについて
https://docs.python.org/ja/3/library/inspect.html
ログ生成場所でTrace.execution_locationを実行しないとファイル名、行番号、メソッドがLoggerクラス内になってしまってうまくいかないなーなどと2時間くらい考えた結果、上記のような実装になりました。
あまりキレイじゃないなーと思っていたので、より良い解決方法が見つかったのは良かったです。
自前の実装でうまくいってました。できれば組み込みで処理したいんですけどね。ドキュメント残さなくていいし。

##3.敗因勝因
知らない誰かが作ったLoggerクラスが先にあり、その挙動を調べるところからスタートして、ドキュメントを後回しにしたことです。
ある程度頭の中で見通しができるまではドキュメントを読んでも進まなかったとも思うので、まぁいいっちゃいいんですけど。
実は勝ってました。

##4.本来の目的はaws lambdaのloggingだったりする
aws側でさらに便利な出力がされるようになっているようです。
Lambda (Python) からのログ出力Tips
https://qiita.com/ohtsuka1317/items/6d4f527e6a0ccf0903f7

##5.感想
loggingの場所を知りたいという意味では組み込みのものをそのまま使えば良いと思います。
本件の私の解決法よりスマートな方法があればその方がなお良しですね。

【更に追記】
さらにもうちょっと調べてみたらスマートな解決策があったのでこっちを使うことになると思います。
aws-lambda-powertools
https://pypi.org/project/aws-lambda-powertools/

##A.参考
Pythonでロギングを学ぼう
https://qiita.com/__init__/items/91e5841ed53d55a7895e
pythonで実行中のファイル、関数、行番号を取得する
https://qiita.com/ymko/items/b46d32b98f013f06d805

5
5
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
5
5

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?