loggingモジュールを使ってみる

最近wordpressもかつてのRaspberryPiサーバから今のサーバに引っ越したのですが、ここのところ大量にエラーが出て対応に追われて大変でした。
フロントにNginxを置いてリバースプロキシでバックエンドのApacheのwordpressに飛ばすという設定にするつもりだったのですが、結局Apacheの設定がわからずにバックエンドもNginxにしてしまいました()

動けばいいんですよ動けば(怠慢

最近またいろいろとPythonプログラムでちょっとおもしろいこと出来ないかな―といじりはじめたのですが、さすがにprintでデバッグするのは面倒だなと。

loggingモジュールの存在自体は知っていたので、今回多少触ってみることにしました。
概要はこのページが分かりやすかったです。→Pythonのlogging機能のしくみ

流れとしては

ロガーを作成
ハンドラーを作成
プログラムからロガーに情報が渡される
ロガーがハンドラーを使って出力

という感じという認識です。

testlog.pyという名前でpythonを書いていきます。

import logging

# testというロガーを作成
logger = logging.getLogger('test')

# ログレベルを設定(デフォルトはWARNING)
logger.setLevel(logging.DEBUG)

# ハンドラーを作成。今回はコンソール出力とファイル出力の2種類。
# コンソールにはERROR以上のみ、ファイルにはDEBUG以上を出力。
# ファイル出力用のハンドラー
fh = logging.FileHandler('test.log')
fh.setLevel(logging.DEBUG)

#コンソール出力用のハンドラー
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)

# ログ出力のフォーマットを決定
formatter = logging.formatter('%(asctime)s - %(funcName)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

# ロガーにハンドラーを設定
logger.addHandler(fh)
logger.addHandler(ch)

def testlog():
    logger.debug('debugメッセージ')
    logger.info('infoメッセージ')
    logger.warning('warningメッセージ')
    logger.error('errorメッセージ')
    logger.critical('criticalメッセージ')
    logger.exception('exceptionメッセージ')

if __name__ == "__main__":
    testlog()

細かい内容は公式のドキュメントを読めばわかります。→15.7. logging — Python 用ロギング機能

このプログラムを実行すると、ERROR以上のメッセージはコンソールに、それ以下はtest.logに記録されていることがわかります。

$ python testlog.py
2016-03-05 13:57:10,294 - testlog - ERROR - errorメッセージ
2016-03-05 13:57:10,294 - testlog - CRITICAL - criticalメッセージ
2016-03-05 13:57:10,294 - testlog - ERROR - exceptionメッセージ
None

$ cat test.log
2016-03-05 13:20:11,402 - testlog - INFO - infoメッセージ
2016-03-05 13:20:11,403 - testlog - DEBUG - debugメッセージ
2016-03-05 13:20:11,403 - testlog - WARNING - warningメッセージ
2016-03-05 13:20:11,403 - testlog - ERROR - errorメッセージ
2016-03-05 13:20:11,403 - testlog - CRITICAL - criticalメッセージ
2016-03-05 13:20:11,403 - testlog - ERROR - exceptionメッセージ
None

exceptionメッセージの下にNoneが出力されているのは、これは通常tryを使った時のexcept文中で用いられるためです。

いちいちこれらをプログラム中に記述するのは面倒なので、設定ファイルにまとめてしまいます。
log.confという名前で設定ファイルを作成しました。

[loggers]
keys=root,test

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=

[logger_test]
level=DEBUG
handlers=fileHandler,consoleHandler
qualname=test

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=simpleFormatter
args=('test.log','w')

[handler_consoleHandler]
class=StreamHandler
level=ERROR
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(funcName)s - %(levelname)s - %(message)s
datefmt=

注意点としてはrootは全てのロガーの親にあたり、これを作成しないと以下の子ロガーに情報がいきません(エラーが出ます)。また、rootのレベルをDEBUGにしないと、その後自分で作成したロガーのレベルをDEBUGにしても情報を受け取ることが出来ません。

あとはloggingを用いたいプログラム中に埋め込みます。

import logging.config
import logging

logging.config.fileConfig('log.conf')
log = logging.getLogger('test')

def testlog():
    logger.debug('debugメッセージ')
    logger.info('infoメッセージ')
    logger.warning('warningメッセージ')
    logger.error('errorメッセージ')
    logger.critical('criticalメッセージ')
    logger.exception('exceptionメッセージ')

if __name__ == "__main__":
    testlog()

実行してみます。

$ python testlog.py
2016-03-05 13:57:10,294 - testlog - ERROR - errorメッセージ
2016-03-05 13:57:10,294 - testlog - CRITICAL - criticalメッセージ
2016-03-05 13:57:10,294 - testlog - ERROR - exceptionメッセージ
None

$ cat test.log
2016-03-05 13:20:11,402 - testlog - INFO - infoメッセージ
2016-03-05 13:20:11,403 - testlog - DEBUG - debugメッセージ
2016-03-05 13:20:11,403 - testlog - WARNING - warningメッセージ
2016-03-05 13:20:11,403 - testlog - ERROR - errorメッセージ
2016-03-05 13:20:11,403 - testlog - CRITICAL - criticalメッセージ
2016-03-05 13:20:11,403 - testlog - ERROR - exceptionメッセージ
None

やったね。

また。ハンドラーにはその他いろいろあり、詳細は公式ドキュメントにあります。使い方次第ではかなり便利に出来そうな気がします。
16.8. logging.handlers — ロギングハンドラ