とりゅふの森

GCPデータエンジニアとして生きる

トップ > Python > 【Python入門】Pythonのロギングと真剣に向き合う

【Python入門】Pythonのロギングと真剣に向き合う

Python Python入門

f:id:true-fly:20211115220343p:plain

こんにちは、将来の夢が最近「ログハウスのサウナ小屋を建てたい」に変わった、とりゅふです。

logという単語は、「丸太」という意味なのですが、ITの世界では、情報の履歴、記録といった意味を持ちます。
blogもweb logの略です。
このlogの語源ですが、時は大航海時代、船乗り達が自分の船の速度を測るために、丸太を船首から海に流し、船尾まで流れる時間を「航海日誌（logbook）」を記録していたことが由来します。

閑話休題、本日のテーマはこちら。

Pythonのログ出力を理解しよう！

よくPythonのコード書いてデバッグ実行するのに、いろんなところにprint()を書いて確認してしまいがちですが、Pythonを始め、各種プログラミング言語にはログ出力用のモジュールがちゃんと備わっています。
今日はこのロギングについて、改めて真剣に向き合って行こうと思います。
※本記事はPython3.7.11で検証しています。

loggingの基本

ログを出力する

Pythonのログは、loggingモジュールで出力することができます。

※loggingモジュールの基本的な使い方を書きますが、非推奨な書き方です。後述のLoggerクラスを利用してください。 
import logging

logging.basicConfig(level=logging.DEBUG)

logging.debug('デバッグ')
logging.info('インフォ')
logging.warning('ワーニング')
logging.error('エラー')
logging.critical('クリティカル')

DEBUG:root:デバッグ
INFO:root:インフォ
WARNING:root:ワーニング
ERROR:root:エラー
CRITICAL:root:クリティカル

ログレベル

Pythonはprint()で情報をコンソール出力することができますが、このloggingを用いることで、ログレベルを設定し、わかりやすい情報を残すことができます。ログレベルとは、ログの重要度を示すものです。以下公式ドキュメントからの引用です。

レベル いつ使うか
DEBUG おもに問題を診断するときにのみ関心があるような、詳細な情報。
INFO 想定された通りのことが起こったことの確認。
WARNING 想定外のことが起こった、または問題が近く起こりそうである (例えば、'disk space low') ことの表示。
ERROR より重大な問題により、ソフトウェアがある機能を実行できないこと。
CRITICAL プログラム自体が実行を続けられないことを表す、重大なエラー。

https://docs.python.org/ja/3/howto/logging.html　より引用

ログレベルは、デフォルトではWARNINGのみを表示するようになっています。DEBUGやINFOはそのままではコンソール出力されません。
そのため、先程のプログラムの3行目のlogging.basicConfig(level=logging.DEBUG)の箇所で、DEBUG以上のログレベルを出力するように設定しています。

ログのフォーマット

次にログのフォーマットを変更してみます。
フォーマットは、`logging.basicConfig(format='ここにフォーマットを指定')で設定できます。
日付やログレベルなどのパラメータも設定可能です。パラメータの詳細は下記で確認できます。
logging --- Python 用ロギング機能 — Python 3.10.0b2 ドキュメント

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s [%(levelname)s] %(filename)s, lines %(lineno)d. %(message)s')

logging.debug('デバッグ')
logging.info('インフォ')
logging.warning('ワーニング')
logging.error('エラー')
logging.critical('クリティカル')

2021-11-15 21:16:20,591 [DEBUG] main.py, lines 7. デバッグ
2021-11-15 21:16:20,591 [INFO] main.py, lines 8. インフォ
2021-11-15 21:16:20,591 [WARNING] main.py, lines 9. ワーニング
2021-11-15 21:16:20,591 [ERROR] main.py, lines 10. エラー
2021-11-15 21:16:20,592 [CRITICAL] main.py, lines 11. クリティカル

ログのファイル出力

デフォルトではログはコンソールに出力されますが、もちろんファイル出力もできます。 、`logging.basicConfig(filename='ここにファイルパスを指定')で設定することで、コンソールには出力されず、ファイルに出力されるようになります。

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s [%(levelname)s] %(filename)s, lines %(lineno)d. %(message)s',
    filename='logs/test.log')

logging.debug('デバッグ')
logging.info('インフォ')
logging.warning('ワーニング')
logging.error('エラー')
logging.critical('クリティカル')

Loggerを使う

loggingとLoggerの違い

これまでloggingモジュールの設定をいじってきましたが、

実際にはloggingをそのまま利用するのは、非推奨とされていて、logging.Loggerクラスを利用するのが推奨されています。

共通モジュールを直接いじらず、logging.Loggerクラスのインスタンスを生成し、利用しましょう。

Loggerクラスの基本

以下サンプルコードです。
Loggerクラスも、loggingと同様にログレベル、フォーマット、出力先などを制御できます。

import logging

# ロガーインスタンス生成
logger = logging.getLogger(__name__)

# ロガーにログレベル設定（ここをDEBUGに設定しないと、その後ハンドラでDEBUG設定しても出力されない）
logger.setLevel(logging.DEBUG)

# ログフォーマット設定
format = '%(asctime)s [%(levelname)s] %(filename)s, lines %(lineno)d. %(message)s'
date_format = '%Y-%m-%d %H:%M:%S'
formatter = logging.Formatter(format, date_format)

# コンソール出力ハンドラを設定、DEBUG以上のレベルを出力
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.DEBUG)
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

# ファイル出力ハンドラを設定、INFO以上のレベルを出力
file_handler = logging.FileHandler('logs/test2.log')
file_handler.setLevel(logging.INFO)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# ログ出力
logger.debug('デバッグ')
logger.info('インフォ')
logger.warning('ワーニング')
logger.error('エラー')
logger.critical('クリティカル')

2021-11-15 21:30:40 [DEBUG] main2.py, lines 25. デバッグ
2021-11-15 21:30:40 [INFO] main2.py, lines 26. インフォ
2021-11-15 21:30:40 [WARNING] main2.py, lines 27. ワーニング
2021-11-15 21:30:40 [ERROR] main2.py, lines 28. エラー
2021-11-15 21:30:40 [CRITICAL] main2.py, lines 29. クリティカル
2021-11-15 21:30:40 [INFO] main2.py, lines 26. インフォ
2021-11-15 21:30:40 [WARNING] main2.py, lines 27. ワーニング
2021-11-15 21:30:40 [ERROR] main2.py, lines 28. エラー
2021-11-15 21:30:40 [CRITICAL] main2.py, lines 29. クリティカル

例外処理でログ出力する

これまではテキストのみをログ出力してきましたが、例外発生時にエラーの詳細、スタックトレースを出力したい場合はどうなるでしょう？
例外を出力するには、logger.exception(e)を用います。以下サンプルコードです。

import logging

# ロガーインスタンス生成
logger = logging.getLogger(__name__)

# ロガーにログレベル設定
logger.setLevel(logging.DEBUG)

# ログフォーマット設定
format = '%(asctime)s [%(levelname)s] %(filename)s, lines %(lineno)d. %(message)s'
date_format = '%Y-%m-%d %H:%M:%S'
formatter = logging.Formatter(format, date_format)


# ファイル出力ハンドラを設定、INFO以上のレベルを出力
file_handler = logging.FileHandler('logs/test3.log')
file_handler.setLevel(logging.INFO)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# ログ出力
try:
    logger.info('ゼロ乗算をします')
    n = 1 / 0
except Exception as e:
    logger.critical('致命的なエラーが発生しました')
    logger.exception(e)

2021-11-15 21:38:26 [INFO] main3.py, lines 23. ゼロ乗算をします
2021-11-15 21:38:26 [CRITICAL] main3.py, lines 26. 致命的なエラーが発生しました
2021-11-15 21:38:26 [ERROR] main3.py, lines 27. division by zero
Traceback (most recent call last):
  File "main3.py", line 24, in <module>
    n = 1 / 0
ZeroDivisionError: division by zero

複数のモジュールでloggerを共有する

最後に複数モジュールで1つのloggerを共有してみます。
log.pyでLoggerインスタンスを生成し、main.pyと、sub.pyでログ出力します。

├── log.py
├── logs
│   └── common.log
├── main.py
└── sub.py
  • log.py
import logging

# ロガーインスタンス生成
logger = logging.getLogger(__name__)

# ロガーにログレベル設定
logger.setLevel(logging.DEBUG)

# ログフォーマット設定
format = '%(asctime)s [%(levelname)s] %(filename)s, lines %(lineno)d. %(message)s'
date_format = '%Y-%m-%d %H:%M:%S'
formatter = logging.Formatter(format, date_format)

# ファイル出力ハンドラを設定、INFO以上のレベルを出力
file_handler = logging.FileHandler('logs/common.log')
file_handler.setLevel(logging.INFO)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)
  • main.py
from log import logger
import sub

try:
    logger.info('mainを実行します')
    sub.execute()
except Exception as e:
    logger.critical('mainで致命的なエラーが発生しました')
    logger.exception(e)
logger.info('mainを終了します')
  • sub.py
from log import logger


def execute():
    logger.info('subを実行します')
    raise Exception('sub内で例外が発生しました。')

2021-11-15 21:41:13 [INFO] main.py, lines 5. mainを実行します
2021-11-15 21:41:13 [INFO] sub.py, lines 5. subを実行します
2021-11-15 21:41:13 [CRITICAL] main.py, lines 8. mainで致命的なエラーが発生しました
2021-11-15 21:41:13 [ERROR] main.py, lines 9. sub内で例外が発生しました。
Traceback (most recent call last):
  File "main.py", line 6, in <module>
    sub.execute()
  File "sub.py", line 6, in execute
    raise Exception('sub内で例外が発生しました。')
Exception: sub内で例外が発生しました。
2021-11-15 21:41:13 [INFO] main.py, lines 10. mainを終了します

まとめ

本日はPythonのloggingとLoggerについてまとめました。
プログラムを効率良く書いたり、実際の業務でシステムを滞りなく運用するためには、ログ出力を理解することが書かせません。
ログ出力を理解し、より品質の高いプログラムを書けるようにしましょう。

スッキリわかるPython入門 スッキリわかるシリーズ

スッキリわかるPython入門 スッキリわかるシリーズ

Amazon

新・明解Python入門 (新・明解シリーズ)

新・明解Python入門 (新・明解シリーズ)

Amazon