今回はPythonのloggingについての記事です。

私自身は趣味でプログラムを組むことが多く、logging周りの設定はあまり触ったことがないです。

個人で作る小規模なプログラムでは、この辺りを意識しなくてもとりあえず動くものが作れる、というのがあるので。

とはいえ、履歴やエラーを適切にログで残すようにすることで、開発の効率というものは大きく変わってくるでしょう。

ロギングの設定については色々と記事があります。

しかし、実際にどう使えばいいのか、ということがいまいちピンと来ませんでした。

こういうのは実際に開発をしながら使わないと実感がわかないものです。

というわけで、簡単なゲームアプリケーションを例にロギング周りを実装してみました。

今回やること

退屈なことはPythonにやらせように挙げられていた簡単なゲームアプリケーションを例にします。

コインを１回投げて、表か裏かをプレーヤーが答えるゲームです。

１回のトスに対して、２回答えることができるので、普通にやると当てることができるのですが、バグがあるので正解することができません。

import random

guess = ''
while guess not in ('表', '裏'):
    print('コインの表裏を当ててください。表か裏を入力してください:')
    guess = input()

toss = random.randint(0, 1)
if toss == guess:
    print('当たり')
else:
    print('はずれ、もう１回当てて')
    guess = input()
    if toss == guess:
        print('当たり')
    else:
        print('はずれ。このゲームは苦手ですね') 

ゲームを開始するとこのようになります。

コインの表裏を当ててください。表か裏を入力してください:
>>>表
はずれ、もう１回当てて
>>>裏
はずれ。このゲームは苦手ですね

こいつにloggingを設定してバグを処理する、ということを行っていきます。

プログラムの流れ

おおむね、こういう流れでやってみます。

1. rootディレクトリのmain.pyを実行
2. ロギングの設定がされる
3. コイントスゲームがスタートされる
4. 必要に応じてログが出力される

ロギングの設定

まずルートディレクトリにutilsディレクトリを作り、log.pyを作成します。

# utils/log.py
from logging import config
import os

# ルートディレクトリにログ保存用のディレクトリを作成
if not os.path.exists('./log'):
    os.makedirs('./log')

# loggingの設定
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {
            "format": "%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s"
        }
    },
    "handlers": {
        "fileHandler": {
            "class": "logging.FileHandler",
            "level": "DEBUG",
            "formatter": "simple",
            "filename": "./log/game.log",
            "encoding": "utf-8"
        }
    },
    "loggers": {
        "game": {
            "level": "DEBUG",
            "handlers": [
                "fileHandler"
            ],
            "propagate": False
        }
    },
}


def configure_logging():
    """loggingに設定をする"""
    config.dictConfig(LOGGING)

こちらは、プロジェクトのロギングを設定するファイルです。

レベルについて

Pythonではロギングのレベルを以下のように定義しています。

DEBUG 

おもに問題を診断するときにのみ関心があるような、詳細な情報。

INFO 

想定された通りのことが起こったことの確認。

WARNING 

想定外のことが起こった、または問題が近く起こりそうである (例えば、'disk space low') ことの表示。

ERROR 

より重大な問題により、ソフトウェアがある機能を実行できないこと。

CRITICAL 

プログラム自体が実行を続けられないことを表す、重大なエラー。

下に行くほど重くなっていくイメージです。

例えばレベルをERRORにしていたら、DEBUGレベルの出力はされない、というような仕様です。

今回の設定について

こちらを念頭において、行った設定を見ていきましょう。

"formatters": {
        "simple": {
            "format": "%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s"
        }
    },

まずここの部分はログを出力した時の書式の設定です。

以下のように出力されることを定義しています。

2022-06-19 13:30:55,802 game.coin_toss:7 game_start [DEBUG]: 

参考　ロギングの環境設定

https://docs.python.org/ja/3/howto/logging.html#configuring-logging

次にハンドラの部分です。

"handlers": {
        "fileHandler": {
            "class": "logging.FileHandler",
            "level": "DEBUG",
            "formatter": "simple",
            "filename": "./log/game.log",
            "encoding": "utf-8"
        }
    },

ハンドラは簡単に言うと、ログの出力をどう制御するか定義しているというところでしょうか。

今回はデフォルトのlogging.FileHandlerを使用してみました。名前の通りログをファイルに出力するためのハンドラです。

ハンドラにはいろいろ種類があって、単純にコンソールに出力するものから、エラーが起きた際にメールをするためのハンドラ等、色々とあるみたいです。

参考 その他の便利なハンドラ

https://docs.python.org/ja/3/howto/logging.html#useful-handlers

最後にここの部分でロガーを適用するモジュールの設定をしています。

今回はgameディレクトリ内にあるファイルに適用したいので以下のようにしています。

"loggers": {
        "game": {
            "level": "DEBUG",
            "handlers": [
                "fileHandler"
            ],
            "propagate": False
        }
    },

gameファイルの作成

冒頭に書いたゲームを実行するためのファイルを作成していきます。

ルートディレクトリ内にgameディレクトリを作成し、coin_toss.pyを作成します。

# game/coin_toss.py
import random
from logging import getLogger


def game_start():
    # loggerをインスタンス化
    logger = getLogger(__name__)
    # ゲーム開始ログの出力
    logger.debug('game start')

    guess = ''
    while guess not in ('表', '裏'):
        print('コインの表裏を当ててください。表か裏を入力してください:')
        guess = input()

    toss = random.randint(0, 1)
    if toss == guess:
        print('当たり')
    else:
        print('はずれ、もう１回当てて')
        guess = input()
        if toss == guess:
            print('当たり')
        else:
            print('はずれ。このゲームは苦手ですね')

    # ゲーム終了ログの出力
    logger.debug('game end')

とりあえずゲームの開始時と終了時にログを出力する仕様です。

ゲームの開始、ログの出力

後はrootディレクトリにmain.pyを作成し、ゲームを行っていきます。

# main.py
from utils import log
from game import coin_toss


def start():
    # loggingの設定を読み込む
    log.configure_logging()
    # gameを開始する
    coin_toss.game_start()


if __name__ == '__main__':
    start()

main.pyを実行しましょう。

コインの表裏を当ててください。表か裏を入力してください:
>>表
はずれ、もう１回当てて
>>裏
はずれ。このゲームは苦手ですね

そうすると、以下のようにlog/game.logに出力されます。

2022-06-19 14:23:43,551 game.coin_toss:10 game_start [DEBUG]: game start
2022-06-19 14:23:50,217 game.coin_toss:29 game_start [DEBUG]: game end

ゲームのデバッグ

準備が出来たので、loggingを活用してバグを取り除いていきます。

まず、coin_toss.pyを編集し、変数の値を調べてみましょう。

# game/coin_toss.py

def game_start():
    # loggerをインスタンス化
    logger = getLogger(__name__)
    # ゲーム開始ログの出力
    logger.debug('game start')

    guess = ''
    while guess not in ('表', '裏'):
        print('コインの表裏を当ててください。表か裏を入力してください:')
        guess = input()

    toss = random.randint(0, 1)
    # 追加　tossとguessの値を調べてみる
    logger.debug(f'toss="{toss}"')
    logger.debug(f'guess="{guess}"')

    if toss == guess:
        print('当たり')
    else:
        print('はずれ、もう１回当てて')
        guess = input()
        if toss == guess:
            print('当たり')
        else:
            print('はずれ。このゲームは苦手ですね')

    # ゲーム終了ログの出力
    logger.debug('game end')

ログファイルにはこのように書きこまれました。

2022-06-19 18:19:38,459 game.coin_toss:10 game_start [DEBUG]: game start
2022-06-19 18:19:43,171 game.coin_toss:19 game_start [DEBUG]: toss="1"
2022-06-19 18:19:43,171 game.coin_toss:20 game_start [DEBUG]: guess="表"
2022-06-19 18:19:44,930 game.coin_toss:33 game_start [DEBUG]: game end

tossの値とguessの値を見比べて、これでは一緒にならないな、ということが分かります。

というわけで、tossの値に応じて表もしくは裏という文字列に変換する式を一つ追加しましょう。

toss = random.randint(0, 1)
# 追加 tossの値を表か裏に変換
toss = '表' if toss == 0 else '裏'
# tossとguessの値を調べてみる
logger.debug(f'toss="{toss}"')
logger.debug(f'guess="{guess}"')

そうすると意図していた通りにログが出ます。

2022-06-19 18:27:01,134 game.coin_toss:10 game_start [DEBUG]: game start
2022-06-19 18:27:05,724 game.coin_toss:21 game_start [DEBUG]: toss="裏"
2022-06-19 18:27:05,724 game.coin_toss:22 game_start [DEBUG]: guess="表"
2022-06-19 18:27:08,942 game.coin_toss:35 game_start [DEBUG]: game end

自作エラーの放出

次に自作エラーを作成して、ログに放出してみましょう。

題材的には２回目の出力の際も、While文で括って、表か裏の値が入力されることを担保するべきなのでしょう。

とはいえ、今回はloggingの練習なので、２回目のinputで表か裏以外の値が入力されたら強制終了のエラーとしてみます。

# game/coin_toss.py
import random
from logging import getLogger


class InvalidInputError(Exception):
    """無効な値が入力されたことを知らせるエラー"""
    pass


def game_start():
    # loggerをインスタンス化
    logger = getLogger(__name__)
    # ゲーム開始ログの出力
    logger.debug('game start')

    guess = ''
    while guess not in ('表', '裏'):
        print('コインの表裏を当ててください。表か裏を入力してください:')
        guess = input()

    toss = random.randint(0, 1)
    # 追加 tossの値を表か裏に変換
    toss = '表' if toss == 0 else '裏'
    # tossとguessの値を調べてみる
    logger.debug(f'toss="{toss}"')
    logger.debug(f'guess="{guess}"')

    if toss == guess:
        print('当たり')
    else:
        print('はずれ、もう１回当てて')
        guess = input()
        # 追加　ユーザーにエラーを知らせつつ、ログにもエラーとして書きこむ
        if guess not in ('表', '裏'):
            logger.error(f'2回目のguessで無効な値が入力された！guess={guess}')
            raise InvalidInputError('入力は表か裏にしてください')

        if toss == guess:
            print('当たり')
        else:
            print('はずれ。このゲームは苦手ですね')

    # ゲーム終了ログの出力
    logger.debug('game end')

試しにわざと2回目にhogeと入力してみましょう。

コインの表裏を当ててください。表か裏を入力してください:
>>>表
はずれ、もう１回当てて
>>>hoge
>>>
Traceback (most recent call last):
...
    raise InvalidInputError('入力は表か裏にしてください')
game.coin_toss.InvalidInputError: 入力は表か裏にしてください

ログファイルにはこのように書きこまれます。

2022-06-19 18:38:19,541 game.coin_toss:15 game_start [DEBUG]: game start
2022-06-19 18:38:23,679 game.coin_toss:26 game_start [DEBUG]: toss="裏"
2022-06-19 18:38:23,679 game.coin_toss:27 game_start [DEBUG]: guess="表"
2022-06-19 18:38:28,373 game.coin_toss:35 game_start [ERROR]: 2回目のguessで無効な値が入力された！guess=hoge

こうすると、このゲームを遊んでいるユーザーだけでなく、ゲームを作成した人もログファイルを見れば、hogeという値が打たれたんだな、と詳細が分かるわけです。

自作ハンドラでSlackに通知する

今のところ、ゲームを作成した人からすると、ログファイルを見るしかエラーの発生を知る方法がありません。

それでは不便なので、自作ハンドラを作成し、エラーが発生した際にSlackに通知するようにしてみましょう。

以前に書いた「PythonでSlack通知する方法」を参考に適当なチャンネルに通知します。

pip install slackweb

utils/log.pyを以下のようにします。

from logging import config
import os
import logging  # 追加
import slackweb  # 追加


class SlackNotifyHandler(logging.Handler):
    """
    エラーが発生したらSlackに通知する自作ハンドラ
    """

    def __init__(self):
        super().__init__()
        webhook_url = 'https://hooks.slack.com/services/your/slackwebhookurl'
        self.slack = slackweb.Slack(webhook_url)

    def emit(self, record):

        if len(record.msg) > 0:
            msg = self.format(record)
        else:
            msg = ''
        try:
            text = 'エラーが発生！ログを確認!\n' + msg
            self.slack.notify(text=text)
        except Exception:
            self.handleError(record)


# ルートディレクトリにログ保存用のディレクトリを作成
if not os.path.exists('./log'):
    os.makedirs('./log')

# loggingの設定
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {
            "format": "%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s"
        }
    },
    "handlers": {
        "fileHandler": {
            "class": "logging.FileHandler",
            "level": "DEBUG",
            "formatter": "simple",
            "filename": "./log/game.log",
            "encoding": "utf-8"
        },
        # 追加
        'slackHandler': {
            "class": 'utils.log.SlackNotifyHandler',
            "level": "ERROR",
            "formatter": "simple",
        }
    },
    "loggers": {
        "game": {
            "level": "DEBUG",
            # slackHandlerを追記
            "handlers": [
                "fileHandler", "slackHandler"
            ],
            "propagate": False
        }
    },
}


def configure_logging():
    """loggingに設定をする"""
    config.dictConfig(LOGGING)

SlackNotifyHandlerクラスですが、こちらが自作ハンドラのクラスになります。

組み込みのlogging.Handlerクラスを継承するようにします。

そしてemitメソッドで具体的なアクションを放出します。

今回の場合は、メッセージSlackに通知することですね。

次に設定情報にもSlackNotifyHandlerを追記するようにします。

# 追加
'slackHandler': {
    "class": 'utils.log.SlackNotifyHandler',
    "level": "ERROR",
    "formatter": "simple",
}

エラーが起きた時だけ通知したいので、レベルはERRORとします。

あとはgameアプリの中にこのハンドラを追記するだけです。

# slackHandlerを追記
"handlers": [
    "fileHandler", "slackHandler"
],

ゲームをスタートし、エラーを発生させてみます。

このようにエラーレベルの通知がされるようになります。

おわりに

今回はPythonのloggingを使って、簡単なログの出力とエラーが出た際に通知する仕組みを作ってみました。

logの設定プログラムをいじるだけで、振り分けができるのが便利な点かと思いました。

このあたりをその都度書いていたら大変です。

ソースコード

今回使用したコードは全文githubに公開しました。

https://github.com/qlitre/python-logging-test