どう print と使い分ける？ 私のログの使い方

この記事は ユニークビジョン株式会社 Advent Calendar 2021 7日目の記事です。

デバックには手を焼いている。なんでみんなログを使わないのか
（個人的には print でデバックするのをやめてほしい。
　会社でRSpecを使っていると、テストの成否とは関係ない出力が邪魔で仕方がない... 😵）

ここでは、私が良く使っているログの基本的なアプローチを述べる。

ログは副作用

最近は副作用を嫌う人が増えてきたように感じる。
とはいえ、我々は好んで副作用を利用することがある。

そう、ログだ。

例えば、あるデータを処理して JSON を返すプログラムの場合を考えみよう。

下記はJSONデータは標準出力。

$ python output_json.py --data 1
> { "data" : 1 }

下記は標準エラー。

# 標準エラーを利用する場合
$ python output_json.py --unknown-key 1
> ERROR: 'unknown-key' などというキーは存在しません。

# 標準出力でエラーを出しても良い
$ python output_json.py --unknown-key 1
> {"errors": ["'unknown-key' などというキーは存在しません。"] }

これはプログラムとしてみたときの作用だ。しかし、ログは副作用だ。
しかも、ログをONにしようが OFF にしようが、プログラムは機能しなければならない。

これが私の使い分けの基準になっている。

私がデバックのために print を使うのを嫌い、ログを推奨しているのは、
デバック出力の目的がプログラムの作用とは関係のない副作用だと考えているからだ。

ログの種類

有名所は下記の4つ。

• error
• warning/warn
• info
• debug

他にも、 exception, trace, critical などツール毎に細かいレベルが存在する。
でも使い分けきれた試しがない

個人的なログの使い分け

種類	ログレベル	目的	正常/異常	目線
error	4	エラー内容を知りたい。	異常	使用者
warning	3	処理の続行はできるが、警告したい。	正常	使用者/開発者
info	2	何が起こっているのかを知りたい。	正常	使用者
debug	1	途中の動きを詳しく知りたい。	正常/異常	開発者

普段はログレベルを 2 に設定し、開発者がデバックするときはログレベルを 1 に設定する。

実際の使い方

サーバ などの常駐型を想定しない場合の話。
単純な例として挙げたため、このプログラムには標準出力に対する作用がない
（最初の例であげた JSON データの出力のような）。

もし標準出力に作用がある場合、利用するログレベルを標準エラーへ出力するものに限定するか、
ログの出力先をファイルに設定する。

基本形： エラーが起こったら出力

from logging import getLogger

logger = getLogger(__name__)


def main():
    try:
        logger.info("仕事を始めるよ！！")
        do_something()
    except Exceition as e:
        logger.error(e)
        exit(1)

基本形では、ユーザ目線のエラーしか出ない。

$ python test_program.py input_file.json
> INFO: 仕事を始めるよ！！
> ERROR: あなたのJSONファイルは間違っている。

エラーの原因を詳細に見たい

このままでは原因の調査が難しい。
ログレベルを操作することで、エラー内容を詳細にする機能を追加する。

from logging import getLogger

logger = getLogger(__name__)


def main():
    try:
        logger.info("仕事を始めるよ！！")
        do_something()
    except Exceition as e:
        if loglevel > DEBUG:
            # エラーメッセージのみ出力される。
            logger.error(e)
        else:
            # 詳細なエラー発生原因も出力される。
            logger.exception(e)

        exit(1)

こうすることで開発者は詳細なエラーを見ることができる。

$ python test_program.py input_file.json --log-level debug
> INFO: 仕事を始めるよ！！
> ERROR: あなたのJSONファイルは間違っている。
>     traceback:
          ...
          test_program.py:58 詳細なエラーも出力される。

ログレベルの変更方法

1. 引数で指定する

基本的なアプローチ。どのレベルが指定されたか明確。

$ python test_program.py input_file.json --log-level debug

2. 設定ファイルで指定する

設定ファイルを使うと、表面的にはログレベルがわからない。
利点とも欠点とも解釈できる。

$ echo 'log_level = debug' >> ~/.your_app/config.toml
$ python test_program.py input_file.json

3. 環境変数で指定する

CI/CD 等を使っており、コードを変えずにログレベルを変えたい場合おすすめ。

$ LOG_LEVEL=debug python test_program.py input_file.json

サーバなどの常駐型の場合

どこかで適切なエラー処理が行われ、プロセスが死なない

基本的には利用しているフレームワークがエラー処理をしてくれる。

import web_framework


def main():
    web_framework.run()

より豊かなログ処理

ファイルログ

ログローテーションなどのより豊かな選択が取れる。

基本的には出力先をファイルに変えただけ。

ログスコープの選択

ログツールによっては、ライブラリ毎にログレベルを選択できたりする。
利用したライブラリをデバックしたいわけではないときに重宝する。

すごすぎ 🤯

参考文献

いろいろなロガーを触ってきたけど、Pythonの標準ライブラリ が好き 😍