アフィリエイトやアドセンスの作業を効率化するために
Python を使って色々とツール作成しているのですが、
個人的な利用に留まることや、アプリの規模が小さいこともあって、
これまではアプリログの出力を気にしたことがありませんでした。
Python でログ出力するには、logging というモジュールを使えばいい
ということは知っていたのですが、
ネット検索して表示される Qiita などを見てもなかなか理解できず、
なんとなく logging の勉強から遠ざかっていたんですよね・・・。
ただ最近になって、形上のログ出力は print 文でシコシコと対応していたものの、
出力できる情報が限られるし、コードの可読性も落ちるしで
色々と嫌になってしまったため、ついに先日、重い腰を上げて logging の勉強を真面目に開始しました。
今回の記事では、複数のモジュールからなる Python プログラムにおいて、
どのようにロギングを実装していけばよいのかを図解とサンプルコードを掲載しつつ説明していきます。
参考にしてみてください。
logging 説明の前提
logging について書かれている Quiita などの技術ページは数あれど、
その内容をそのまま自分の開発にすぐ導入できるかというと結構難しかったります。
特に複雑で難しく感じるのが、メイン処理内からほかのモジュールを
呼び出すパターンで、メイン側と呼び出されるモジュール側の
それぞれのログ出力設定の記述をどのようにすればいいのか？を
理解するのに時間がかかりました。
(どの解説ページでも、その著者の独自目線で書かれていることが多くあり、
著者毎に異なるコードの書きっぷりなので、結構混乱するんですよね。。。)
ここでは、複数のモジュールからなる Python プログラムにおいて、
どのように logging の設定を入れればよいのかを
ザックリとしたイメージ図を使って説明していきます。
以下のような main.py / module1.py / module2.py があり、
main.py の中で、module1.py と module2.py 内の関数を呼び出す場合を例に説明していきます。
(下図内の関数はテキトウです)
プログラムの実行ログは画面に出力しつつ、
ログファイルとして保存もする処理を実装していきます。
main.py のログはもちろん出力しますが、
module1.py と module2.py のログも同じく出力するものとします。
|
|
|
logging の主な登場人物
logging を使ったログ出力を実装するにあたり、主な登場人物を紹介しておきます。
最低限なもののみを紹介しますので、深く知りたい方は logging の
公式ドキュメントをご覧ください。
→ logging 公式ドキュメント (Logging HOWTO)
主な登場人物は以下の2つです。
- logger
- handler
logger
python の logging におけるlogger は、その名の通りログ出力を管理する存在です。
log(記録をする) + er(～する人) で logger(記録をする存在)ですね。
プログラムが動作している間に吐き出されるログを、この logger が取りまとめてくれるイメージです。
logging モジュールを使用する際には、まずこの logger を作成するところから始めます。
この logger の基本設定は basicConfig と呼ばれるもので行いますが、
個々の logger の設定を別途詳細に行うことも可能です。
handler
handler は、logger によって生成されたログを、各送信先に送信します。
送信先にはログファイルやコンソール画面、メールなどを選択できます。
一般的に、Handler といえば
「何らかの処理要求が発生したときに起動されるプログラム」のことを指しますが、
logging の handler もそのような存在で、普段はメモリ上で待機しており、
logger から送られてくるログを随時適切な形式に成形して、ログファイルやコンソール画面に出力させる存在です。
1つの logger に対して複数の handler を関連付けることができます。
これにより、logger で取りまとめられたログのうち、
例えば 『ERROR ログだけをコンソール出力し、DEBUG 以上のログすべてをログファイルに出力』する、
なんていうカスタマイズが可能になります。
logger と handler の関係を表したのが下図です。
この図では、1つの logger に対して、ログファイル出力用の handler 1つ、
コンソール画面出力用の handler 1つを関連付けています。
上述した通り、logger には複数の handler を関連付けることができるため、
例えば 2種類のログを別々に出したい場合には、上図の構成にさらにもう1つの
handler(filehandler) を関連付けてやれば OK です。
イメージとしては下図のようになります。
|
|
|
logging によるログ出力方法とログレベルについて
logging のログレベルには以下の5つがあり、デフォルトの設定では、 INFO / DEBUG は出力されません。
出力されるログのレベルを変更するには、BasciConfig でログレベルを明示するか、
各 logger のログレベルを変更してやる必要があります(後述)。
- CRITICAL
- ERROR
- WARNING
- INFO
- DEBUG
ERROR 以上のログを 単純にコンソールへ出力するのみであれば、以下のコードを記載すればよいです。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
import logging # logger の作成 logger = logging.getLogger(__name__) # コンソール画面用ハンドラー設定 consoleHandler = logging.StreamHandler() # logger と コンソール用ハンドラーの関連付け logger.addHandler(consoleHandler) # ログを出力したい箇所へ随時以下のコードを挿入 logger.debug("DEBUGです") logger.info("INFOです") logger.warning("WARNINGです") logger.error("ERRORです") logger.critical("CRITICALです") |
■コンソール出力結果
|
1 2 3 4 5 |
WARNINGです ERRORです CRITICALです |
INFO や DEBUG などの情報もコンソール出力したい場合は、
logger のログレベルを変更したうえで、DEBUG 以上を出力可能なハンドラーと関連付けてやります。
(basicConfig を用いた設定方法は、混乱を避けるためここでは記載しません)
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 |
import logging # logger の作成 logger = logging.getLogger(__name__) # logger のログレベルを変更 (WARNING → DEBUG) logger.setLevel(logging.DEBUG) # コンソール画面用ハンドラー設定 # ハンドラーのログレベルを設定する (DEBUG以上を出力する) consoleHandler = logging.StreamHandler() consoleHandler.setLevel(logging.DEBUG) # logger と コンソール用ハンドラーの関連付け logger.addHandler(consoleHandler) # ログを出力したい箇所へ随時以下のコードを挿入 logger.debug("DEBUGです") logger.info("INFOです") logger.warning("WARNINGです") logger.error("ERRORです") logger.critical("CRITICALです") |
■コンソール出力結果
|
1 2 3 4 5 6 7 |
DEBUGです INFOです WARNINGです ERRORです CRITICALです |
この5段階のログレベルのほかに、スタックトレースを出力する方法もあります。
以下記事をご参考ください。
|
|
|
logging の基本的な設定方法(単一モジュールの場合)
上記までの基礎知識を前提に、まず main.py 1つからなるプログラムで
コンソールとログファイルの両方にログ出力するための logging 設定を紹介していきます。
コード内で記載してやることは以下です。
- logger の作成
- logger のログレベルの設定
- handler(コンソール出力用)の作成
- handler(コンソール出力用)のログレベルの設定
- handler(コンソール出力用)のログフォーマット設定
- logger と handler(コンソール出力用)の関連付け
- handler(ログファイル出力用)の作成
- handler(ログファイル出力用)のログレベルの設定
- handler(ログファイル出力用)のログフォーマット設定
- logger と handler(ログファイル出力用)の関連付け
- ログ出力したい場所に logger のメッセージを配置
イメージとしては下図です。
まず logger を作成します。
その logger に対し、プログラム上で出力されるログのうち、
どのレベルのログを管理・出力するのか？(LogLevel)の設定を行います。
次に、logger から受け取ったログをコンソール画面へ表示するためのハンドラーを作成し、
そのハンドラーによって出力されるログのレベルとログのフォーマットを設定します。
出来たハンドラーは、logger と関連付けます。
同様に、logger から受け取ったログをログファイルへ出力するためのハンドラーを作成し、
そのハンドラーによって出力されるログのレベルとログのフォーマットを設定します。
こちらも、logger と関連付けます。
これらの設定をコードで表すと、以下のようになります。
※このコードをコピペし、メイン処理やログパスなどを書き換えていただければ、そのまま使用可能です。
■ main.py
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 |
import logging import datetime # 1, logger の作成 # 2, logger のLogLevel の設定 logger = logging.getLogger(__name__) logger.setLevel(logging.DEBUG) # 3, コンソール画面用ハンドラー設定 # 4, ログレベルの設定 consoleHandler = logging.StreamHandler() consoleHandler.setLevel(logging.INFO) # 5, コンソールログフォーマット設定 console_formatting = '%(asctime)s [%(levelname)-8s] [%(module)s#%(funcName)s %(lineno)d] %(message)s' console_formatter = logging.Formatter(console_formatting) consoleHandler.setFormatter(console_formatter) # 6, logger と コンソール用ハンドラーの関連付け logger.addHandler(consoleHandler) # ログファイルパス設定 now = datetime.datetime.now() now_log = now.strftime('%Y%m%d%H%M%S') log_filepath = "application_" + now_log + ".log" # 7, ログファイル出力用ハンドラー設定 # 8, ログレベルの設定 fileHandler = logging.FileHandler(filename = log_filepath) fileHandler.setLevel(logging.DEBUG) # 9, ファイルログフォーマット設定 file_formatting = '%(asctime)s [%(levelname)-8s] [%(module)s#%(funcName)s %(lineno)d] %(message)s' file_formatter = logging.Formatter(file_formatting) fileHandler.setFormatter(file_formatter) # 10, logger と ログファイル用ハンドラーの関連付け logger.addHandler(fileHandler) # メイン処理 def main(): logger.debug("DEBUGです") logger.info("INFOです") logger.warning("WARNINGです") logger.error("ERRORです") logger.critical("CRITICALです") if __name__ == "__main__": main() |
logger と 各handler の両方でログレベルをそれぞれ設定しているのは、
例えば 『コンソール出力されるログのレベルを INFO 以上、
ログファイルに出力されるログのレベルを DEBUG 以上』
にしたい場合などをイメージすると、その理由がわかります。
下図のように、logger では DEBUG 以上のすべてのログを出力するようにしておき、
handler 毎にログレベルを調整することで、出力先毎に見たいログ情報を変更することができ、
運用・管理面で非常に便利なためです。
実際に main.py を実行すると、コンソール画面とログファイルには
それぞれ以下のように出力されます。
コンソールとログファイルとで、出力されているログレベルが異なっていることがわかります。
■コンソール画面
|
1 2 3 4 5 6 |
2020-04-14 02:21:21,898 [INFO ] [main#main 56] INFOです 2020-04-14 02:21:21,899 [WARNING ] [main#main 57] WARNINGです 2020-04-14 02:21:21,899 [ERROR ] [main#main 58] ERRORです 2020-04-14 02:21:21,900 [CRITICAL] [main#main 59] CRITICALです |
■ログファイル
|
1 2 3 4 5 6 7 |
2020-04-14 02:21:21,898 [DEBUG ] [main#main 55] DEBUGです 2020-04-14 02:21:21,898 [INFO ] [main#main 56] INFOです 2020-04-14 02:21:21,899 [WARNING ] [main#main 57] WARNINGです 2020-04-14 02:21:21,899 [ERROR ] [main#main 58] ERRORです 2020-04-14 02:21:21,900 [CRITICAL] [main#main 59] CRITICALです |
|
|
|
logging の基本的な設定方法(複数モジュールの場合)
main.py と、複数のモジュールから成り立つプログラムでの logging の実装の場合、
単一モジュールの場合にプラスして、いくつかコードを追記してやる必要があります。
module.py(呼び出されるモジュール側)での実装
まず module.py 側でやることは以下です。
- main用 logger の作成
- ログ出力したい場所に logger のメッセージを配置
module.py 側では、logger を作ることと、
logging のメッセージを随所に配置することのみを行います。
そして、実際にコンソールやログファイルへ出力されるログのレベルなどは、
main.py 側で集約して設定するようにし、module.py 側には記載しないようにします。
module.py 側のコードとしては、以下のようになります。
※このコードをコピペし、メイン処理やログパスなどを書き換えていただければ、そのまま使用可能です。
■module.py
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
import logging # logger の作成 logger = logging.getLogger(__name__) def test1(): logger.debug("DEBUGです") logger.info("INFOです") logger.warning("WARNINGです") logger.error("ERRORです") logger.critical("CRITICALです") |
main.py 側(モジュールを呼び出す側)での実装
main.py 側でやることは以下です。
- main用 logger の作成
- main用 logger のログレベルの設定
- ★モジュール用 logger のログレベルの設定
- main用 handler(コンソール出力用)の作成
- main用 handler(コンソール出力用)のログレベルの設定
- main用 handler(コンソール出力用)のログフォーマット設定
- main用 logger と handler(コンソール出力用)の関連付け
- ★モジュール用 logger と handler(コンソール出力用)の関連付け
- main用 handler(ログファイル出力用)の作成
- main用 handler(ログファイル出力用)のログレベルの設定
- main用 handler(ログファイル出力用)のログフォーマット設定
- main用 logger と handler(ログファイル出力用)の関連付け
- main用 logger と handler(ログファイル出力用)の関連付け
- ★モジュール用 logger と handler(ログファイル出力用)の関連付け
- ログ出力したい場所に logger のメッセージを配置
単一モジュールの場合と比較すると、★マークの個所が増えている部分です。
単一モジュール時に設定した内容に加え、module側で作成した module用の logger を、
ログレベルを設定したうえで main側で作成した各ハンドラーに紐づけてやります。
こうすることで、main.py を1つ編集するだけで、
各モジュールからのログ出力度合いを自在に変更することが可能になります。
イメージとしては下図です。
これらの設定をコードで表すと、以下のようになります。
※このコードをコピペし、呼び出す関数名などを書き換えれば、そのまま使用可能です。
■main.py
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 |
import logging import datetime from module1 import test1 # 1, main 側の logger の作成 # 2, main 側の logger のLogLevel の設定 logger = logging.getLogger(__name__) logger.setLevel(logging.DEBUG) # 3, module 側の logger のLogLevel の設定 logging.getLogger("module1").setLevel(level=logging.DEBUG) #logging.getLogger("module2").setLevel(level=logging.DEBUG) # 4, コンソール画面用ハンドラー設定 # 5, ログレベルの設定 consoleHandler = logging.StreamHandler() consoleHandler.setLevel(logging.INFO) # 6, コンソールログフォーマット設定 console_formatting = '%(asctime)s [%(levelname)-8s] [%(module)s#%(funcName)s %(lineno)d] %(message)s' console_formatter = logging.Formatter(console_formatting) consoleHandler.setFormatter(console_formatter) # 7, logger と コンソール用ハンドラーの関連付け logger.addHandler(consoleHandler) # 8, module 側のロガーを取得しコンソール用ハンドラと関連付ける(外部モジュールの数だけコピペして追加) logging.getLogger("module1").addHandler(consoleHandler) #logging.getLogger("module2").addHandler(consoleHandler) # ログファイルパス設定 now = datetime.datetime.now() now_log = now.strftime('%Y%m%d%H%M%S') log_filepath = "application_" + now_log + ".log" # 9, ログファイル出力用ハンドラー設定 # 10, ログレベルの設定 fileHandler = logging.FileHandler(filename = log_filepath) fileHandler.setLevel(logging.DEBUG) # 11, ファイルログフォーマット設定 file_formatting = '%(asctime)s [%(levelname)-8s] [%(module)s#%(funcName)s %(lineno)d] %(message)s' file_formatter = logging.Formatter(file_formatting) fileHandler.setFormatter(file_formatter) # 12, logger と ログファイル用ハンドラーの関連付け logger.addHandler(fileHandler) # 13, module 側のロガーを取得しファイル出力用ハンドラと関連付ける(外部モジュールの数だけコピペして追加) logging.getLogger("module1").addHandler(fileHandler) #logging.getLogger("module2").addHandler(fileHandler) # メイン処理 def main(): logger.debug("DEBUGです") logger.info("INFOです") logger.warning("WARNINGです") logger.error("ERRORです") logger.critical("CRITICALです") if __name__ == "__main__": main() test1() |
実際に main.py を実行すると、コンソール画面とログファイルには
それぞれ以下のように出力されます。
しっかり module.py 側のログも出力されているのがわかります。
■コンソール画面
|
1 2 3 4 5 6 7 8 9 10 |
2020-04-15 00:44:57,282 [INFO ] [main#main 58] INFOです 2020-04-15 00:44:57,282 [WARNING ] [main#main 59] WARNINGです 2020-04-15 00:44:57,283 [ERROR ] [main#main 60] ERRORです 2020-04-15 00:44:57,283 [CRITICAL] [main#main 61] CRITICALです 2020-04-15 00:44:57,299 [INFO ] [module1#test1 9] INFOです 2020-04-15 00:44:57,300 [WARNING ] [module1#test1 10] WARNINGです 2020-04-15 00:44:57,300 [ERROR ] [module1#test1 11] ERRORです 2020-04-15 00:44:57,301 [CRITICAL] [module1#test1 12] CRITICALです |
■ログファイル
|
1 2 3 4 5 6 7 8 9 10 11 12 |
2020-04-15 00:44:57,281 [DEBUG ] [main#main 57] DEBUGです 2020-04-15 00:44:57,282 [INFO ] [main#main 58] INFOです 2020-04-15 00:44:57,282 [WARNING ] [main#main 59] WARNINGです 2020-04-15 00:44:57,283 [ERROR ] [main#main 60] ERRORです 2020-04-15 00:44:57,283 [CRITICAL] [main#main 61] CRITICALです 2020-04-15 00:44:57,299 [DEBUG ] [module1#test1 8] DEBUGです 2020-04-15 00:44:57,299 [INFO ] [module1#test1 9] INFOです 2020-04-15 00:44:57,300 [WARNING ] [module1#test1 10] WARNINGです 2020-04-15 00:44:57,300 [ERROR ] [module1#test1 11] ERRORです 2020-04-15 00:44:57,301 [CRITICAL] [module1#test1 12] CRITICALです |
もし外部モジュールを増やしたい場合は、コード内でコメントアウトされている個所を外して
追加する外部モジュール分だけ logger を追加して handler に関連付けてやればよいです。
最後に
logging については多々記事があり、それぞれの記事で異なる書き方が紹介されており、
個人的にかなり混乱してしまったため、今回自分なりにまとめて記事にしてみました。
自作のツールを作成する際には、この記事内のコードをコピペして使用するだけで事足りています。
logging よく分からないけど使ってみたいという方は、参考にしてみてください。
【注意】
この書き方が必ずしも正解というわけでは決してありませんので、予めご認識をお願いします。
logging についての理解と整理を目的としているため、結構くどい書き方になっていると思います。
(例えば、basicConfig の設定をしっかり書くことで、全体的なコードは減らせると思います。)
コメント