rohaniのブログ

ゆるっと自然言語処理奴。ときどき工作系バイト。

外部モジュールのlogging.debug()を画面＆ファイル出力するにはrootLoggerに対してレベルとハンドラーの設定を追加すればいい

Python

背景

Pythonのword2vecモジュール「gensim.models.word2vec」を用いて自前の単語分散表現word2vecを得ようとした。

こちらの記事 【Python】Word2Vecの使い方 - Qiita を参考にしたら、とてもスムーズに学習・類似単語表示の機能を実装できたのだが、 word2vecの学習過程を表示する機能を実装する際に、loggingへの理解が浅かったことが原因で大分ハマってしまった。

ハマりポイントは以下。

  1. メインプログラムのデバッグ文用に自前のloggerを設置していて、logger.debug()等の結果をファイル出力＆画面出力できている。
  2. しかし、loggerは設定できてるはずなのに、word2vecの学習過程ログは出力されない。なんでだろう？
  3. word2vecの学習過程ログをファイルに出力したい。けど、basicConfig()ではファイル出力と画面出力を同時設定できない仕様らしい（←誤解）、どうすればいいんだろう。

上記ハマりポイントについて、順番に解消していく。

gensim.models.word2vecのloggerは「ハンドラーが設定されていないから」画面に現れない

github.com

本家のプログラムを読むと分かるが、gensim.models.word2vecのロギングシステムは、

  • 【グローバル変数】としてloggingをインスタンス化　logger = logging.getLogger(__name__)
  • 【関数Word2Vec()内】でlogger.info()等してログに書き出し
  • 【if __name__ == '__main__'内】でlogging.basicConfig()してハンドラーやレベルを設定

という形になっている。

このうち、外部からfrom gensim.models import word2vec; word2vec.Word2Vec()などとしてWord2Vec()関数を呼び出した場合、実行されるのは１番目と２番目の項目だけなので、loggingはインスタンス化されただけでハンドラーやレベルの設定がされていない状態となるのだ。

学習過程ログはlogger.debug()及びlogger.info()を用いて書き出すように実装されているので、これでは出力されない、ということが分かる。

loggingの使い方おさらい

上の説明で「OK分かったよ」ってなれる人は良いのだけれど、 loggingへの理解が浅かった昨日までの私なら分からなかっただろうと思うので、ここで簡単にloggingの挙動のおさらいをしておく。

logging.debug()を標準出力に出力するためにはレベルの設定が必要

loggingのロギングシステムには、緊急度で４つのレベル分けがされている。

例えば以下のプログラムだと、

""" 全レベルのログを出力しようとしてみる。できない。 """
import logging

logging.debug('でばっぐtest1')
logging.info('いんふぉtest1')
logging.warning('わーにんぐtest1')
logging.error('えらーtest1')

WARNING:root:わーにんぐtest1
ERROR:root:えらーtest1

DEBUGとINFOのログが出力されない。

これはなぜかというと、ルートロガーに対してハンドラが未定義だったために自動でlogging.basicConfig()が呼ばれ、 logging.basicConfig()のデフォルトの設定ではログ出力レベルが「WARNING以上」に設定されているからである。 ついでに、書式もデフォルトの書式'%(levelname)s:%(name)s:%(message)s'で出力されている。

関数 debug(), info(), warning(), error(), critical() は、ルートロガーにハンドラが定義されていない場合に自動的に basicConfig() を呼び出します。
出典：logging --- Python 用ロギング機能 — Python 3.7.4 ドキュメント

したがって、DEBUGやINFOなどWARNING未満のレベルのメッセージを出力したい場合には、その旨を設定してやる必要がある。 設定にはlogging.basicConfig()を使う。

""" ルートロガーにレベルとフォーマットの設定をした。 """
import logging

format_str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
logging.basicConfig(
    format=format_str,
    level=logging.DEBUG
)

logging.debug('でばっぐtest1')
logging.info('いんふぉtest1')
logging.warning('わーにんぐtest1')
logging.error('えらーtest1')

2019-08-22 00:10:46,663 - root - DEBUG - でばっぐtest1
2019-08-22 00:10:46,664 - root - INFO - いんふぉtest1
2019-08-22 00:10:46,664 - root - WARNING - わーにんぐtest1
2019-08-22 00:10:46,664 - root - ERROR - えらーtest1

全レベルのメッセージが標準出力に出力された。

…rootlogger = logging.getLogger()してrootLoggerをインスタンス化して設定を行う方法も思いついたけどなんかあんまりよくない気配がするので今回は触れない。

インスタンスlogger = logging.getLogger(__name__) のハンドラーやレベルを設定するには

loggingは木構造になっていて、ルートロガーの設定が 子ロガー にも継がれる。

だから、これまでと同様にルートロガーにレベルとハンドラーを設定するだけでいい。

""" ルートロガーに設定すれば、子ロガーもその設定を継ぐ """
import logging

format_str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
logging.basicConfig(
    format=format_str,
    level=logging.DEBUG
)

logging.debug('でばっぐtest1')
logging.info('いんふぉtest1')
logging.warning('わーにんぐtest1')
logging.error('えらーtest1')

logger = logging.getLogger(__name__)
logger.debug('でばっぐtest1')
logger.info('いんふぉtest1')
logger.warning('わーにんぐtest1')
logger.error('えらーtest1')

2019-08-22 00:22:05,722 - root - DEBUG - でばっぐtest1
2019-08-22 00:22:05,722 - root - INFO - いんふぉtest1
2019-08-22 00:22:05,722 - root - WARNING - わーにんぐtest1
2019-08-22 00:22:05,722 - root - ERROR - えらーtest1
2019-08-22 00:22:05,722 - __main__ - DEBUG - でばっぐtest1
2019-08-22 00:22:05,722 - __main__ - INFO - いんふぉtest1
2019-08-22 00:22:05,722 - __main__ - WARNING - わーにんぐtest1
2019-08-22 00:22:05,723 - __main__ - ERROR - えらーtest1

ルートロガーに対してレベルやフォーマットの設定を行っただけで、mainと名付けた 子ロガー の全レベルのログメッセージが出力されていることが確認できる。

ちなみに、子ロガーに対してルートロガーと異なる設定を行うこともできる。

""" ルートロガーと子ロガーで異なる設定を行うこともできる """
import logging

format_str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'

# ルートロガーの設定
logging.basicConfig(
    format=format_str,
    level=logging.DEBUG
)

handler_format = Formatter(format_str)
# 標準出力
stream_handler = StreamHandler()
stream_handler.setFormatter(handler_format)

logger = getLogger(__name__)
# 子ロガーの設定
logger.setLevel(logging.INFO)
logger.addHandler(stream_handler)
logger.propagate = False

logging.debug('でばっぐtest1')
logging.info('いんふぉtest1')
logging.warning('わーにんぐtest1')
logging.error('えらーtest1')

logger.debug('でばっぐtest1')
logger.info('いんふぉtest1')
logger.warning('わーにんぐtest1')
logger.error('えらーtest1')

2019-08-22 00:28:52,315 - root - DEBUG - でばっぐtest1
2019-08-22 00:28:52,315 - root - INFO - いんふぉtest1
2019-08-22 00:28:52,315 - root - WARNING - わーにんぐtest1
2019-08-22 00:28:52,315 - root - ERROR - えらーtest1
2019-08-22 00:28:52,315 - __main__ - INFO - いんふぉtest1
2019-08-22 00:28:52,315 - __main__ - WARNING - わーにんぐtest1
2019-08-22 00:28:52,316 - __main__ - ERROR - えらーtest1

ルートロガーは全レベル、子ロガーはINFO以上のレベルのメッセージを表示していることが分かる。

logging.basicConfig()してルートロガーにハンドラーを設定すれば、gensim.models.word2vecのloggerを画面出力させられる

さて、gensim.models.word2vecのloggingのインスタンスloggerにハンドラーが設定されていないのが問題なら、ハンドラーを設定してしまえば解決するはずである。

（´-`）.｡oO（(インスタンスにハンドラーを追加するって、pip installしたgensim.models.word2vec.pyを弄るってこと？)）
（´v`）.｡oO（(ちょっと背徳的でそれもいいねぇ)）
けど、gensim.models.word2vecのloggerにハンドラーを追加するには、インスタンス自体にハンドラーを追加する必要はないのです。

なぜなら、そう、loggingは階層構造なので、ルートロガーに対してハンドラーを設定すればその子ロガーにも設定が継がれるから。

この法則は、外部からファイルを読み込んだ場合にも適応される。 ちなみに外部から呼んだ場合は、__name__の中身がモジュール名になる。

""" test1.py ハンドラー未定義のloggerをもつ。gensim.models.word2vecの立場 """
import logging

def print_debug():
    logger = logging.getLogger(__name__)
    logger.debug('でばっぐtest1')
    logger.info('いんふぉtest1')
    logger.warning('わーにんぐtest1')
    logger.error('えらーtest1')

""" test2.py ルートロガーを設定した。自前のメインプログラムの立場 """
from logging import getLogger, basicConfig, DEBUG
import test1

def set_rootLogger():
    format_str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
    basicConfig(
        format=format_str,
        level=DEBUG
    )

def print_debug():
    logger = getLogger(__name__)
    logger.debug('でばっぐtest2')
    logger.info('いんふぉtest2')
    logger.warning('わーにんぐtest2')
    logger.error('えらーtest2')

if __name__ == '__main__':
    set_rootLogger()
    print_debug()
    test1.print_debug()

$ python3 test2.py

2019-08-22 00:41:13,209 - __main__ - DEBUG - でばっぐtest2
2019-08-22 00:41:13,209 - __main__ - INFO - いんふぉtest2
2019-08-22 00:41:13,209 - __main__ - WARNING - わーにんぐtest2
2019-08-22 00:41:13,210 - __main__ - ERROR - えらーtest2
2019-08-22 00:41:13,210 - test1 - DEBUG - でばっぐtest1
2019-08-22 00:41:13,210 - test1 - INFO - いんふぉtest1
2019-08-22 00:41:13,210 - test1 - WARNING - わーにんぐtest1
2019-08-22 00:41:13,210 - test1 - ERROR - えらーtest1

そういうわけで、最初に述べた参考記事でも紹介されている通り、logging.basicConfig()をしてルートロガーにハンドラーを設定すれば、gensim.models.word2vecのloggerを画面出力させられる。

from gensim.models import word2vec
import logging

logging.basicConfig(format='%(asctime)s : %(levelname)s : %(message)s', level=logging.INFO)

# 以下、word2vecの学習に関するプログラムが続く...
# ...

handlersオプションを使えば、標準出力とファイル出力の両方にログを出力できる

ここまでに紹介したbasicConfig()の設定では、標準出力には出力できるがファイルには出力できない。 両方出力したい、というときには、以下のようにする。

from logging import getLogger, basicConfig, DEBUG, StreamHandler, FileHandler, Formatter

logf = 'test1.log'

format_str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handler_format = Formatter(format_str)
# 標準出力
stream_handler = StreamHandler()
stream_handler.setFormatter(handler_format)
# ファイル出力
file_handler = FileHandler(logf, 'a')
file_handler.setFormatter(handler_format)

logging.basicConfig(
    handlers=[stream_handler, file_handler],
    level=logging.DEBUG
)

logger = getLogger(__name__)
logger.debug('でばっぐtest1')
logger.info('いんふぉtest1')
logger.warning('わーにんぐtest1')
logger.error('えらーtest1')

まとめ

gensim.models.word2vecの学習過程ログを画面＆ファイル出力するにはrootLoggerに対してレベルとハンドラーの設定を追加すればいい

感想

ロギングシステムを実装しようと思って勉強した事はあったけど、 他者が作った他のモジュールのロギングシステムを使おうとしたのは初めてだったので、とても勉強になった。