小幡 知弘 
みなさんこんにちは。VSCodeのデバッグモードを使用してGUI的なデバッグばかりしていて、環境依存しないテストやデバッグについて真剣に考えないといけないと考えている小幡です。
今日はログ出力について触れてみます。「Pythonで作るRPG」の作成をしている時に、「テストやログについても触れないとなぁ」と思っていたのですが、ログ出力などは主題でもないと思いましたので別枠で記事にしようと思っていました。print()で全て出力していましたが、今回はlogging.logger()を使って見ます。
前提条件
- Python3.9
- Windows10
ロギング(logging)とは？
例によってPythonのHOW TOが充実していますので、正確な情報は以下リンクを参照してください。
まずは公式ドキュメント通りに進めてみます。本題の「logging.getLogger(__name__)を使い、モジュール事にログを出力して」はその後で記述します。
と言っても、公式ドキュメントにあることを複合的に使うだけなのですが。
最も簡単なログ出力
まずは最も簡単なログ出力を行ってみます。
test.pyを新規作成し、以下コードを記述します。
import logging
logging.error('Error!')そしてコマンドラインで以下のコマンドを実行します。（test.pyのpathについては割愛）
python test.pyすると以下の結果がコンソールに出力されます。
ERROR:root:Error!このエラーメッセージは、「:」コロン区切りで読み解く事ができます。
最初の「ERROR」は「logging.error()」で指定したエラーログレベルのERRORを意味しています。
2つ目の「root」はloggingがどこで行われたかを意味しています。今回の場合は、実行したファイルでエラーが発生したので「root」と表示されていますpathのようなイメージです。
3つ目の「Error!」は「logging.error()」に渡した文字列「Error!」が出力されています。
まとめると下の様に見る事ができます。
レベル:場所:メッセージログをファイルに出力する
上記のログが出力できて、その内容が理解できれば、後は出力です。
追加するのは「basicConfig()」を設定する1行だけです。追加したコードは以下です。
import logging
logging.basicConfig(filename='test.log', encoding='utf-8')
logging.error('Error!')先ほどと同じように実行すると「test.log」というファイルが作成され、先ほどと同じエラー文が記述されていると思います。
encoding引数は、python3.9からとのことなので、それ以前のバージョンを使用している場合は注意してください。
バージョン 3.9 で変更: encoding 引数が追加されました。 以前のバージョンあるいは無指定の Python では、エンコーディングには
https://docs.python.org/ja/3/howto/logging.htmlopen()が使うデフォルト値が使われます。
本題：モジュール毎にログを出力
ファイルにログを出力できたら、後はモジュール事にログが出力できれば、本題の「モジュール事にログを出力する」ことが出来ます。
ここで言う「モジュール毎」というのは、「pythonで書かれたファイル毎」に近いイメージです。先ほどのpythonファイルでは、「test.py」というルートのファイル１つでログを出力させていましたが、実際にコードを書くときは、ほかにもディレクトリやファイルを作成しコードを分割するかと思います。
ログを出力する際に、どこで発生したログなのかを明記しておくことで、デバッグがスムーズになるということです。pythonが最初から機能しているトレース機能も、コンソール画面にエラーが発生した場所を明記してくれていると思いますが、これを自作するイメージに近いかもしれません。
ログ出力はログレベルを決めることで、どういうログなのかも示す事ができるので多様な場面で使えるものだと思います。
それではモジュール毎という仮定で「test.py」と「sub.py」を用意し、以下のようにコードを記述してみました。「test.py」はメインモジュールで、「sub.py」はサブモジュールというイメージでしょうか。
import logging
import sub
def main():
logging.basicConfig(filename='test.log', encoding='utf-8')
logger = logging.getLogger(__name__)
sub.do_sumthing()
logger.error('After do something.')
if __name__ == '__main__':
main()一番最初に呼び出されるモジュールとしての簡単なコードです。他から呼び出されることがないように、例によっていつものif文がコード末に2行記述してあります。
2行目で「sub.py」をインポートしています。
7行目・8行目は先ほどのログ出力のための準備です。
10行目にて「sub.do_somthing()」としてsubモジュールのdo_something関数を呼び出しています。
11行目にてルートの「test.py」にてログを出力しています。
では、sub.do_something()を見ていきましょう。
import logging
logger = logging.getLogger(__name__)
def do_something():
logger.critical('Error!')こちらも4行目まではログ出力の準備です。
6行目でdo_something()を定義しています。
8行目でログレベルをクリティカルとして「Error!」というメッセージを出力させています。
logging.getLogger(__name__)
ここでのポイントは「logging.getLogger(__name__)」という1行です。
まず、「logging.getLogger()」というのは公式ドキュメントにもあるように、モジュール毎のロガーを作成し、名前を使ているというイメージです。以下公式ドキュメントの引用文です。
ロガーに名前をつけるときの良い習慣は、ロギングを使う各モジュールに、以下のように名付けられた、モジュールレベルロガーを使うことです:
https://docs.python.org/ja/3/howto/logging.html
こうすることで、ロガーがどこで発生したエラーなのかを表示してくれるようになります。
そして「__name__」というのが、モジュール毎の名前をさせてくれるものです。
これは「test.py」のメイン関数呼び出しの際にも使用していますが、そのモジュールの名前を入れてある変数のイメージです。「sub.py」の場合であれば、「sub」が格納されています。
一番最初に呼び出されるモジュールは、そのモジュールの名前ではなく「__main__」が格納されます。
それでは以上の事を踏まえて「test.py」を実行します。
python test.pyすると結果は、先ほどと同様に「test.log」が作成され、以下のようにログが出力されます。
CRITICAL:sub:Error!
ERROR:__main__:After do something.
1行目は「sub.do_something()」が呼び出されたことで出力されたログです。
ログレベルがクリティカルで、発生した場所は「sub」であることがわかります。行末にはログメッセージも出力されています。
2行目は「test.py」で出力されたログです。
ログレベルはエラー。呼び出された場所は「__main__」となっています。
これは先ほど説明した通り、一番最初に呼び出された「test.py」であることを表しています。そして行末には同じくエラーメッセージが出力されています。
まとめ
以上でモジュール毎にログを出力する方法の説明は終わりです。
やったことをまとめると、
- loggingをインポートする
- logging.getLogger()を使ってモジュール毎のロガーに名前をつける
- __name__を使って、モジュールの名前を呼び出す
- logging.basicConfigを使い出力ファイルを指定する
という内容でした。
今回はログレベルの詳細は割愛しましたが、レベルの低いinfoなどを使用してコードの流れを監視したい場合などは公式ドキュメントを参照ください。
以上、長文を最後までお読みいただきありがとうございました。
また次回もお会いできることを楽しみにしております。
次回はtryとexceptionでエラーをキャッチする事を、今回のロギングに絡めた記事を書けたら良いなと考えて居ます。ありがとうございました。