Python으로 logging 배우기: 로그레벨 설정, 로그 포매팅, 로그 파일출력, 로그 ini파일, log config 파일

Pythonでロギングを学ぼう

logPython3

学習履歴

■はじめに

python でテスト手法について色々と学んできたが、テストと合わせてログの出し方も
覚えておくと便利だ。

ここでは、ロギングの勉強をしよう。

■参考

この記事は、現役シリコンバレーエンジニアが教えるPython 3 入門 + 応用 +アメリカのシリコンバレー流コードスタイルを参考にしています(すごく、おすすめです!)

[その他 プログラム記事]

■環境

python3
pycharm
Anaconda

■ロギング

ロギングの方法を実際にコードを書きながら覚えていこう。

1.ログレベル

python のロギングには、5 つのレベルがある。

1.　CRITICAL
2.　ERROR
3.　WARNING
4.　INFO
5.　DEBUG

デフォルトでは、INFO, DEBUG は、出力されないようになっている。

logger_lesson.py

import logging

logging.critical('critical')
logging.error('error')
logging.warning('warning')
logging.info('info')
logging.debug('debug')

logger.実行結果

CRITICAL:root:critical
ERROR:root:error
WARNING:root:warning

ちなみに、出力結果に root とあるが、これはプログラムで最初に実行される
python ファイルを指していて、ここでは logger_lesson.py が root となる。

これからは、root が出力される処理を main 処理と呼ぶ。

2.ログレベルの変更

ログレベルは、basicConfig で変更することができる。

logger_lesson.py

import logging

# ログレベルを DEBUG に変更
logging.basicConfig(level=logging.DEBUG)

logging.critical('critical')
logging.error('error')
logging.warning('warning')
logging.info('info')
logging.debug('debug')

logger.実行結果

CRITICAL:root:critical
ERROR:root:error
WARNING:root:warning
INFO:root:info
DEBUG:root:debug

3.ロギングのフォーマット

ログの出し方にひと工夫いれられると便利だ。

ロギングのフォーマットを変更してみよう。

logger_lesson.py

import logging

# ログレベルを DEBUG に変更
logging.basicConfig(level=logging.DEBUG)

# 従来の出力
logging.info('error{}'.format('outputting error'))
logging.info('warning %s %s' % ('was', 'outputted'))
# logging のみの書き方
logging.info('info %s %s', 'test', 'test')

このようにフォーマットは、自由に書ける。
ただし、最後のフォーマットだけは、ロギングのみでできるらしい。

logger.実行結果

INFO:root:erroroutputting error
INFO:root:warning was outputted
INFO:root:info test test

4.ログをファイルに出力

ログはファイルに出力して管理するものだ。

basicConfig にファイルパスを指定して、ログを出力してみよう。

logger_lesson.py

import logging

# ログレベルを DEBUG に変更
logging.basicConfig(filename='logfile/logger.log', level=logging.DEBUG)

# 従来の出力
logging.info('error{}'.format('outputting error'))
logging.info('warning %s %s' % ('was', 'outputted'))
# logging のみの書き方
logging.info('info %s %s', 'test', 'test')

指定したログファイルがない場合は、自動的に作成されるはずだ。
※フォルダは自動作成されないので、自分で作成する必要がある

logger.log

INFO:root:erroroutputting error
INFO:root:warning was outputted
INFO:root:info test test

■ロギングフォーマッタ

フォーマットの変更

さっき勉強したフォーマットだが、もう少し掘り下げてみる。

basicConfig にフォーマット情報を渡すことができるんだ。

logger_lesson.py

import logging

# フォーマットを定義
formatter = '%(levelname)s : %(asctime)s : %(message)s'

# ログレベルを DEBUG に変更
logging.basicConfig(level=logging.DEBUG, format=formatter)

logging.info('%s %s', 'test', 'test')

logger.実行結果

INFO : 2018-02-24 18:03:23,364 : test test

asctime は 時間出力できる属性値だ。

他にも色々と種類があって、公式サイトで紹介されている。

C# とか PowerShell とかは、DateTime 的なオブジェクトを取ってきて、
フォーマットで整形してから出力しないといけないから、すごく便利だ。

■ロギング ロガー

basicConfig でログレベルなどを設定できる。

ロガーはこの設定を引き継いで、特定の処理にだけログの設定を変更することが
できる仕組みだ。

1.ロガーの設定

logger_lesson.py

import logging

# ロギングの基本設定(infoレベルを指定)
logging.basicConfig(level=logging.INFO)
logging.info('info')

# 現在のロギングの情報を取得(引数はファイル名)
logger = logging.getLogger(__name__)
# ロギングの設定を DEBUG に変更
logger.setLevel(logging.DEBUG)
logger.debug('debug')

logger.実行結果

INFO:root:info
DEBUG:__main__:debug

2.別の python ファイルで、ロガーを扱う

logging.getLogger(name) の name は、処理を実行したファイル名を
出力してくれるので割と便利。

例えば、別の python ファイルを作ってみよう。

logger_lesson2.py

import logging

logger = logging.getLogger(__name__)

def do_something():
    logger.info('from logger_lesson2')

呼び出し元の logger_leesson.py から呼び出したいのでコードを修正する。

logger_lesson.py

import logging

import logger_lesson2

logging.basicConfig(level=logging.INFO)

logging.info('info')

logger_lesson2.do_something()

logger.実行結果

INFO:root:info
INFO:logger_lesson2:from logger_lesson2

2 番目のログ出力に注目するとちゃんと実行ファイルの名前が確認できる。
これが、ロガーの基本的な使い方だ。

あとは、logger_lesson2.py だけログレベルを debug にしたい場合はこうする。

logger_lesson2.py

import logging

logger = logging.getLogger(__name__)
# setLevel で変更
logger.setLevel(logging.DEBUG)


def do_something():
    logger.info('from logger_lesson2')
    logger.debug('from logger_lesson2_debug')

logger.実行結果

INFO:root:info
INFO:logger_lesson2:from logger_lesson2
DEBUG:logger_lesson2:from logger_lesson2_debug

基本的には、main 処理を記述したファイルに、basicConfig を設定し、
他のファイルは logger を設置して、個々のカスタマイズを加えていく開発が
主流のようだ。

■ロギング ハンドラ

main 処理に記述する basiConfig の filename にログのパスを記述すれば、
ログが書き込まれることについては既に説明した。

main 処理以外のログ情報をファイルに出力する為には、ハンドラを使う必要がある。

1.ハンドラの使い方

ハンドラは、main 処理以外の python ファイルに書くので、logger_lesson2.pyに
書こう。

logger_lesson2.py

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

##ハンドラ取得
get_handler = logging.FileHandler('logfile/logger.log')
logger.addHandler(get_handler)


def do_something():
    logger.info('from logger_lesson2')
    logger.info('from logger_lesson2_debug')

FileHandler にログの出力先パスを渡した状態で変数に格納後、
ハンドラのプロパティとして追加するとログが出力できるようになるらしい。

つまり、ファイルに書き込まれる情報は、常に logger を使う必要がある。

logger.log

from logger_lesson2
from logger_lesson2_debug

2. ハンドラの種類

ハンドラにも色々と種類がある。

詳しくは、公式ページを参照してほしい。

■ログのフィルタ

出力されるログをフィルタリングしたいときがある。
(例えばパスワードなどの情報)

python では、ログのフィルタも可能だ。

フィルタの設定

フィルタの設定手順は以下のようになる。

1. ログ専用クラスを作成し、logging.Filter の情報を継承させる
2. フィルタ条件を設定する
3. logger プロパティにフィルタ情報を追加する

logger_lesson.py

import logging

logging.basicConfig(level=logging.INFO)


# ログ専用クラスを作成し、logging.Filter の情報を継承させる
class NoPassFilter(logging.Filter):
    # フィルタ条件を設定する
    def filter(self, record):
        log_message = record.getMessage()
        return 'password' not in log_message

logger = logging.getLogger(__name__)
# logger プロパティにフィルタ情報を追加する
logger.addFilter(NoPassFilter())
logger.info('from main')
logger.info('from main password = "test')

password という文字列が含まれていたらログ出力しないといった設定だ。
出力結果には、'from main password = "test' が出力されないはずだ。

logger.結果

INFO:__main__:from main

■ロギングコンフィグ

ロギング設定をまとめて管理できれば、大変便利だ。

作り方は、2 種類ある。

1.ini ファイルで作成

logging.ini ファイルに logger の情報を書き出す方法だ。

説明は、コメントに書いてあるので、コピペして実際に動かしてみてほしい。

logging.ini

;---大元の設定
;--ロガーの対象一覧
[loggers]
;logging.getLogger(logger name)のlogger nameに指定する名前
;root は、 mainで実行した時に自動的に取得できる名前
;outputLoggingのように独自のロガー名を追加できる
keys=root, outputLogging

;ハンドラの設定(customStreamHandlerは任意で付けた名前)
[handlers]
keys=customStreamHandler

;フォーマットの設定(customFormatは任意で付けた名前)
[formatters]
keys=customFormat

;---詳細の設定
;logger_[loggers の key 名] とし、詳細を記述していく
[logger_root]
level=WARNING
handlers=customStreamHandler

[logger_outputLogging]
level=DEBUG
handlers=customStreamHandler
qualname=outputLogging
propagate=0

;---詳細の設定に追加するためのオプション
;handler_[handlers の 名前]
[handler_customStreamHandler]
class=StreamHandler
level=DEBUG
formatter=customFormat
args=(sys.stderr,)

;---formatter_[formatter の 名前]
[formatter_customFormat]
format=%(asctime)s %(name)-12s %(levelname)-8s %(message)s

logger_lesson.py(main処理)

import logging.config

import logger_lesson2

# main 処理なので、__name__ には、root が入る
logging.config.fileConfig('logging.ini')
logger = logging.getLogger('__name__')

logger.debug('debug message')
logger.info('info message')
logger.warning('warning message')
logger.error('error message')
logger.critical('critical message')

logger_lesson2.do_something()

logger_lesson2.py

import logging


def do_something():
    # outputLogging を入れてみる
    logger = logging.getLogger('outputLogging')
    logger.debug('debug message')
    logger.info('info message')
    logger.warning('warning message')
    logger.error('error message')
    logger.critical('critical message')

logger.実行結果

2018-02-24 23:36:08,575 __name__     WARNING  warning message
2018-02-24 23:36:08,576 __name__     ERROR    error message
2018-02-24 23:36:08,576 __name__     CRITICAL critical message
2018-02-24 23:36:08,576 outputLogging DEBUG    debug message
2018-02-24 23:36:08,576 outputLogging INFO     info message
2018-02-24 23:36:08,576 outputLogging WARNING  warning message
2018-02-24 23:36:08,576 outputLogging ERROR    error message
2018-02-24 23:36:08,576 outputLogging CRITICAL critical message

2.dictConfigを使う方法

ロガーの dictConfig関数を使って同じようなことができる。

今度は、logger_lesson.py に書いてみる。

logger_lesson.py

import logging.config

import logger_lesson2

logging.config.dictConfig({
    'version': 1,

    # フォーマットの設定
    'formatters': {
        'customFormat': {
            'format': 'format=%(asctime)s %(name)-12s %(levelname)-8s %(message)s'
        },
    },
    # ハンドラの設定
    'handlers': {
        'customStreamHandler': {
            'class': 'logging.StreamHandler',
            'formatter': 'customFormat',
            'level': logging.DEBUG
        }
    },

    # ロガーの対象一覧
    'root': {
        'handlers': ['customStreamHandler'],
        'level': logging.WARNING,
    },
    'loggers': {
        'outputLogging': {
            'handlers': ['customStreamHandler'],
            'level': logging.DEBUG,
            'propagate': 0
        }
    }
})


logger = logging.getLogger('__name__')

logger.debug('debug message')
logger.info('info message')
logger.warning('warning message')
logger.error('error message')
logger.critical('critical message')

logger_lesson2.do_something()

logger_lesson2.py は変更なしだ。

logger.実行結果

format=2018-02-24 23:58:13,602 __name__     WARNING  warning message
format=2018-02-24 23:58:13,602 __name__     ERROR    error message
format=2018-02-24 23:58:13,603 __name__     CRITICAL critical message
format=2018-02-24 23:58:13,603 outputLogging DEBUG    debug message
format=2018-02-24 23:58:13,603 outputLogging INFO     info message
format=2018-02-24 23:58:13,603 outputLogging WARNING  warning message
format=2018-02-24 23:58:13,603 outputLogging ERROR    error message
format=2018-02-24 23:58:13,603 outputLogging CRITICAL critical message

どちらかやりやすい方法で試してみるといいかもしれない。
実際の開発現場だと、dictConfig の方がよくつかわれているらしい。

■まとめ

・ロギングの使用方法について学んだ。