logging ログ出力 その1

pythonの標準ライブラリにはloggingというログ出力用のモジュールが用意されています。ここではpythonのログ出力について学習します。

loggingの基本的な使い方

logginモジュールに用意されているログレベルに応じたメソッドでログ出力をすることができます。処理が多岐に渡るアプリケーションでは、次回ご説明するloggerを生成して使用するのが一般的で、loggingを直接使用することはお行儀が悪いとされています。ですが、シングルスレッドのバッチアプリケーションや小規模なアプリケーションであればそれほど問題ないでしょう。まずは基本ということでloggingからの直接ログ出力について学習しましょう。

まずは使ってみる

まずは基本的な使い方です。ログレベルに応じたメソッドが用意されていますので、引数にログメッセージを指定してメソッドを実行します。

import logging

logging.warning('警告です') # 警告ログの出力
logging.error('エラーが発生しました') # エラーログの出力

上のコードを実行すると、以下のように出力されます。

WARNING:root:警告です
ERROR:root:エラーが発生しました

ログレベル

一般的なプログラムにはログには用途に応じたレベルが用意されています。pythonのログには代表的なものとして以下のレベルが用意されています。以下は公式ドキュメントからの抜粋となります。

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

では早速他のレベルのログも出力してみましょう。デフォルトの設定ではwarning以上のレベルのログしか出力されませんのでbasicConfigメソッドでログのレベルを指定します。

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:処理の続行がません!!

フォーマット

さて、実際に運用でログを使用する場合、エラー等が起こった時刻が知りたいですね。また、頻繁にエラーの分析が必要なシステムでは区切り文字を変えたりして可読性をあげたほうがよいかもしれません。さらに、マルチプロセスやマルチスレッドの場合はプロセスIDやスレッドIDを参照する必要が出てくるかもしれません。

こういった要求を満たすため、一般的なプログラミング言語ではフォーマットを整える機能がついていますが、当然pythonにもログのフォーマットを整える機能があります。

以下がフォーマットしたログを出力するサンプルとなります。basicConfigのformat引数でログのフォーマットを指定します。

import logging

# basicConfigのformat引数でログのフォーマットを指定する 
log_fmt = '%(asctime)s- %(name)s - %(levelname)s - %(message)s'
logging.basicConfig(format=log_fmt, level=logging.DEBUG)
logging.error('エラーが発生しました')

以下のように出力されます。

2017-03-16 21:45:53,974- root - ERROR - エラーが発生しました

フォーマット文字列の%()sで囲まれた部分で何を出力するかを指定します。asctimeが時間、nameがloggerの名称、(loggerについては後ほど説明します。)levelnameがログレベルの名称、messageがメッセージとなります。その他、以下のものが用意されています。標準ライブラリのlogging/__init__.pyのコメントから抜粋しました。

%(name)s logger名
%(levelno)s ログレベル番号
%(levelname)s ログレベル名
%(pathname)s (利用可能であれば)ソースファイルのフルパス
%(filename)s ソースファイル名
%(module)s モジュール名
%(lineno)d (利用可能であれば)行番号
%(funcName)s 関数、メソッド名
%(created)f Time when the LogRecord was created (time.time()return value)
%(asctime)s ログレコードが作成された時間のテキスト形式
%(msecs)d Millisecond portion of the creation time
%(relativeCreated)d Time in milliseconds when the LogRecord was created, relative to the time the logging module was loaded (typically at application startup time)
%(thread)d (利用可能であれば)スレッドID
%(threadName)s (利用可能であれば)スレッド名
%(process)d (利用可能であれば)プロセスID
%(message)s メッセージ

ログメッセージへの変数埋め込み

変数出力する場合は以下のようにstrのフォーマットを使用します。

logging.error('引数の値に%s と %sが指定されました', 'aaaa', 'bbbb')

ファイル出力

今まで設定したログは標準出力への出力のみでしたが、basicConfigにfilenameを指定することでファイル出力をすることもできます。

import logging

# basicConfigのformat引数でログファイルの出力先を指定する
log_fmt = '%(asctime)s- %(name)s - %(levelname)s - %(message)s'
logging.basicConfig(filename='example.log', format=log_fmt)
logging.error('エラーが発生しました')

example.logにログが出力されます。

複数モジュールの場合

さて、loggingを使用する際、basicConfigで設定を行ってきました。モジュールが複数に渡る場合、予め一箇所でbasicConfigを設定すると、後から他の場所でloggingを使う場合basicConfigの設定は不要になります。以下の2つのモジュールを準備して確認してみましょう。

# mod1.py
import logging

def sample():
    logging.error("エラー発生")
# sample.py

import logging
import mod1

log_fmt = '%(asctime)s- %(name)s - %(levelname)s - %(message)s'
logging.basicConfig(format=log_fmt)
mod1.sample()

sample.pyからmod1.pyを呼び出します。mod1.pyの方ではbasicConfigの設定を行っていませんが、フォーマットされたログが出力されていることを確認することができます。

次のステップについて

冒頭に書いたとおり、一般的にloggingを直接使用するのはお行儀が悪いとされています。次回loggerについて学習し、複雑なアプリケーションの場合でも適切なログの使用方法について学習しましょう。