ロギングの手法あれこれ

はじめに

こんにちは。しがないデータサイエンティストです。
突然ですが皆さんはデバッグは好きですか？僕は嫌いです。コードを書いている時は自分は天才だと思いながら進めていますが、あとから見返すと誰だこのウンコードを書いた奴は？😡を繰り返しています。業務では機械学習スクリプトを実装することが多いのですが、規模が大きくなってくるとどこで何のエラーが出ているのか追うのも大変になり修正に手を付けるまでが億劫になります。

これまでデバッグ作業はprintを用いてなんとなくやっていたのですが、実行ログの出力としてpythonのloggingを使ってみると非常に便利で、デバッグ作業が大好きになりました。嘘です。大好きにはなってはいませんがデバッグがやり易くなったのは本当です。個人的に結構詰まるポイントが多かったので振り返り用にまとめていこうと思います。

参考

公式リファレンスと以下記事を参考にさせていただきました。
Logging HOWTO
Good logging practice in Python
ログ出力のための print と import logging はやめてほしい
Pythonでprintを卒業してログ出力をいい感じにする
Pythonのlogging.exceptionを使うときのよくある勘違い

目次

1. ロギングとは
2. 準備
3. 単体ファイルでのログ出力
4. ファイルをまたぐログ出力
5. try-exceptでのエラーログ出力
6. 実装
7. まとめ

1. ロギングとは

Logging HOWTOによれば、

logging は、あるソフトウェアが実行されているときに起こったイベントを追跡するための手段です。

と記載があります。printじゃダメなの？と思う方もいるかもしれません。
しかし、システムが複雑になったり大規模化する場合にはロギングを活用した方が圧倒的にコードもすっきりしますし、どのモジュールでの処理なのかが分かりやすく利点が多いです。

2. 準備

フォルダ構成としては以下のようにします。

もう少し単純にconfigを設定しないやり方もあるのですが、ロギングを使いたい状況がある程度システムが大規模であることを考えると、configを設定した方が後々把握しやすいなどメリットがあるため今回はこのような構成を採用しました。

今回は例として、以前作成したGoogle Calendar API から年月、片道の交通費を入力してその月の交通費を自動計算するスクリプトに対してロギングを実装します。(Google Calendar APIを使って月末申請の交通費を自動計算してみた)

log_config.jsonの中身は以下の通り。

log_config.json

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

    "handlers": {
        "consoleHandler": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout"
        },
        "fileHandler": {
            "class": "logging.FileHandler",
            "level": "INFO",
            "formatter": "simple",
            "filename": "tmp.log"
        }
    },

    "loggers": {
        "__main__": {
            "level": "DEBUG",
            "handlers": ["consoleHandler", "fileHandler"],
            "propagate": false
        }
    },

    "root": {
        "level": "INFO"
    }
}

レベルはDEBUG/INFO/WARNING/ERROR/CRITICALから選べ、デフォルトはWARNINGとなっています。YAMLファイルでも記述することができます。
configについての詳細はこちらの記事を参考にさせていただきました。

3. 単体ファイルでのログ出力

まずはファイル単体でのロギング設定についてみていきましょう。
メソッドの任意の箇所に下記コードでロガーを作成します。

# ロガークラスのインポート
1 from logging import getLogger
2 from logging import config as logConfig 
3 
4 with open('./config/log_config.json', 'r') as f:
5     log_conf = json.load(f)
6 log_conf["handlers"]["fileHandler"]["filename"] = Path(log_path, f" {this_year}_{this_month}.log")
7 logConfig.dictConfig(log_conf)
8 logger = getLogger("__main__")

4, 5行目ではconfigファイルを読み込んでいます
6, 7行目ではコンフィグの上書きをしています。今回はスクリプトの実行の度に出力するログファイル名を変更しています。
8行目でlog_config.jsonの"loggers"内の"__main__"の設定でロガーを作成します。"__main__"は任意の名前に変えて設定を変更することもできます。

ロガーを作成したら任意の箇所に出力する内容を記述します。

# ログ出力
logger.info(f"{this_year}年{this_month}月の交通費：{month_transportation_expenses}円")
logger.info(f"出社日数：{go_company_days}日")

logger.debug/logger.info/logger.warning/logger.errorのように出力レベルを変更することが可能です。

全体のコードは後ほど掲載しますが、ファイルを実行すると以下のような出力がlogフォルダ下に作成されます。

log_config.jsonのformattersで設定した

"format": "%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s"

という設定に即した出力がされていることが確認できます。
個人的には関数名と行番号が確認できるのが嬉しいですね。（printで出力しようとすると結構めんどくさいので）

4. ファイルをまたぐログ出力

さて、上記では単体ファイルによるログ出力を行いました。システムの規模が大きくなると別ファイルでクラスを作成したりとファイル数が増えてきますよね。安心してください。複数ファイルになってもロギングを使えば同じようにログを出力することができます。

例えば以下のように別ファイルで計算用のクラスを作成したとします。

calculate.py

1 from logging import getLogger
2 from logging import config
3 
4 calc_loger = getLogger('__main__.calc')
5 
6 class Calc():
7     def __init__(self, events, expense):
8         self.events = events
9         self.expense = expense
10 
11         # ログ作成用
12         self.logger = getLogger('__main__.calc.Calc')

4行目でこのファイル用のロガーを作成します。
12行目でクラスのメソッド内で使えるようにロガーを作成します。
この２行を追加するだけでメインの実行ファイルのロガーと同じログファイルにログを出力することができます。

このファイルのメソッド内でログを出力したいときにはこのように記載すれば良いです。

# ログ出力
self.logger.info('calclate_transportation_expenses')

例えばCalcクラスのcalculate_transportation_expensesメソッド内に上記ログ出力を記載したとすると、下記のように呼び出したクラス、メソッド、メッセージ等を出力することができます。

5. try-exceptでのエラーログ出力

エラー時のログも出力することができます。大量のデータを使って処理を回しているときなど、どのデータでどんなエラーが出たのか追いづらいことがありますが、ログを使えば簡単に確認することができます。

try:
    logger.info('get date succeed')
except:
    logger.exception('get date failed')

例えば今回の例では日付を入力する際に存在しない14月と入力した場合、下記のようなエラーがログファイルに出力されます。

6. 実装

今回の例で作成したコードの全体は以下の通りです。フォルダ構成及びファイル名は2. 準備の通りです。

calc_transport_expences.py

from __future__ import print_function
import datetime
from datetime import date, timedelta
import os.path
from googleapiclient.discovery import build
from google_auth_oauthlib.flow import InstalledAppFlow
from google.auth.transport.requests import Request
from google.oauth2.credentials import Credentials
from pyasn1.type.univ import Null
import json
import sys
from pathlib import Path

# 計算クラスのインポート
from calculate import Calc

# ロガークラスのインポート
from logging import getLogger
from logging import config as logConfig

# If modifying these scopes, delete the file token.json.
SCOPES = ['https://www.googleapis.com/auth/calendar.readonly']

#引数を指定しなければ今月情報を取得する
#引数に月・年を指定すればその月の情報を取得する
def get_events(this_month=date.today().month, this_year=date.today().year):
    """Shows basic usage of the Google Calendar API.
    Prints the start and name of the next 10 events on the user's calendar.
    """
    try:
        creds = None
        # The file token.json stores the user's access and refresh tokens, and is
        # created automatically when the authorization flow completes for the first
        # time.
        if os.path.exists('token.json'):
            creds = Credentials.from_authorized_user_file('token.json', SCOPES)
        # If there are no (valid) credentials available, let the user log in.
        if not creds or not creds.valid:
            if creds and creds.expired and creds.refresh_token:
                creds.refresh(Request())
            else:
                flow = InstalledAppFlow.from_client_secrets_file(
                    './script/credentials.json', SCOPES)
                creds = flow.run_local_server(port=0)
            # Save the credentials for the next run
            with open('./script/token.json', 'w') as token:
                token.write(creds.to_json())

        service = build('calendar', 'v3', credentials=creds)

        # Call the Calendar API
        first_day = date(this_year, this_month, 1)
        if this_month == 12:
            end_day = date(this_year + 1, 1, 1) - timedelta(days=1)
        else:
            end_day = date(this_year, this_month+1, 1) - timedelta(days=1)

        events_result = service.events().list(calendarId='primary',
                                            timeMin=str(first_day)+"T00:00:00+00:00",
                                            timeMax=str(end_day)+"T00:00:00+00:00",
                                            singleEvents=True,
                                            orderBy='startTime').execute()
        events = events_result.get('items', [])
        
        # ログ出力
        logger.info('get date succeed')
    except:
        # ログ出力
        logger.exception('get date failed')

    return events

if __name__ == '__main__':
    print("===交通費を求める===")
    expences = input('片道の交通費： ')
    this_year = input('求めたい年： ')
    this_month = input('求めたい月： ')

    # ロガー呼び出し
    current_dir = os.path.dirname(__file__)
    sys.path.append(os.path.join(current_dir, ".."))
    log_path = Path(current_dir, "..\\log")
    with open('./config/log_config.json', 'r') as f:
        log_conf = json.load(f)
    log_conf["handlers"]["fileHandler"]["filename"] = Path(log_path, f"{this_year}_{this_month}.log")
    logConfig.dictConfig(log_conf)
    logger = getLogger("__main__")

    month_events = get_events(int(this_month), int(this_year))
    calc = Calc(month_events, int(expences))
    month_transportation_expenses, go_company_days = calc.calculate_transportation_expenses()
    #month_transportatin_expenses, go_company_days = calculate_transportation_expenses(month_events, int(expences))

    #print(month_transportatin_expenses)
    print("")
    print("===結果===")
    print("{0}年{1}月の交通費：{2}円".format(this_year, this_month, month_transportation_expenses))
    print("出社日数：{0}日".format(go_company_days))

    # ログ出力
    logger.info(f"{this_year}年{this_month}月の交通費：{month_transportation_expenses}円")
    logger.info(f"出社日数：{go_company_days}日")

calculate.py

from logging import getLogger
from logging import config

calc_loger = getLogger('__main__.calc')

class Calc():
    def __init__(self, events, expense):
        self.events = events
        self.expense = expense

        # ログ作成用
        self.logger = getLogger('__main__.calc.Calc')

    #グーグルカレンダーから取得した情報と片道の交通費を引数にして、月の交通費を計算する
    def calculate_transportation_expenses(self):
        go_company_days = []
        month_transportation_expenses = 0

        for event in self.events:
            #print(event['location'])
            date = event['start'].get('date')
            if date != None and event['summary'] == "出社":
                #print(date, event['summary'])
                go_company_days.append(date)
        
        #print(len(go_company_days))
        month_transportation_expenses = 2 * self.expense * len(go_company_days)
        
        # ログ出力
        self.logger.info('calclate_transportation_expenses')

        return month_transportation_expenses, len(go_company_days)

7. まとめ

今回pythonでのロギング手法について一通り使い方をまとめました。自分でロギングをやろうと思った際、正直公式リファレンスも読みづらく使い方がまとまっている記事もなかなか見つからず、しかも人によって使い方がバラバラで苦労したためこの記事が誰かの一助になれば嬉しいです。公式リファレンスを読むともっといろいろな機能がありそうなのでそちらもいずれじっくり読み込みたいと思っています。
実際ログを出力するようになってデバッグ作業が捗るようになったので皆さんもロギングの素晴らしさを体感してみましょう！