Day8: Pythonでの初めてのログ出力
今日はPythonでのログ出力の話をしようと思う。やはりプログラムの自動化を目指すうえで、実行結果に異常がなかったかを一目で確認できるログ出力機能は必須であろう。
Pythonにはログ記録システムをサポートするloggingモジュールが標準ライブラリとして備えられている。公式のチュートリアル(Logging HOWTO — Python 3.5.1 ドキュメント)もあり、簡単に実装ができる...といいたいところだが、少しクセがあるのでここで噛み砕いて説明できれば、と思う。
まず上のチュートリアルだが、初級と上級のチュートリアルに分かれている。当然のように初級を参照し、「ファイルへのlogging」というセクションを参考にしながら次のようなプログラムを書き上げた。
import fft import logging logging.basicConfig(filename='example.log',level=logging.DEBUG) fft.PATH_TO_DB="./db/P1415.sqlite3" fft.SELENIUM=True try: m=fft.Match(matchID=matchID,doScrape=True) except: logging.error("matchID"+str(matchID)+" scraping failed") else: logging.info("matchID"+str(matchID)+" scraping successed")
fftが自作のスクレイピング用モジュールで、その中にもloggingでログ出力を仕込んだ。ログの出力はlogggin.debug()やlogging.error()などでイベントのレベルを設定でき、最初のbasicConfigでどのレベルまで捉えるか、というのを設定できる。なんだ、簡単じゃないか、と思って実行し、example.logに出力されたログを確認してみると、、、
... DEBUG:selenium.webdriver.remote.remote_connection:Finished Request ...
こんな感じにfftそのもののログだけでなく、fftで使用している外部ライブラリであるseleniumから出力されるログも、大量に流れ込んでしまっているではないか。これではfftモジュールの動作確認が全く一目で分からない。どうやったら分けることができるのか、ぶち切れながらチュートリアルを読み進め、ついには上級まで踏み込んでようやく次のようなことが分かった。
ログ機能は、ログを直接発生させるロガーと、ロガーを受け取って出力先を決定するハンドラがある。上のbasicConfigでやっていたのはDEBUGレベルまで捉えるハンドラをルートにセットする、ということで、fftだけでなくseleniumライブラリにセットされていたロガーの出力も担当してしまっていた。
つまり、fftモジュールのログをseleniumと切り分けて見たいのであれば、fftモジュール内でロガーと独自のハンドラを用意して、そのハンドラで出力先を指定してやればいいということになる。したがって以下のコードをfftモジュールに追加した。
from logging import getLogger,FileHandler,StreamHandler,DEBUG,INFO logger = getLogger(__name__) _fhandler = FileHandler("./log/fft.log",'w') _shandler = StreamHandler() _fhandler.setLevel(DEBUG) _shandler.setLevel(INFO) logger.setLevel(DEBUG) logger.addHandler(_fhandler) logger.addHandler(_shandler)
ファイルハンドラとストリームハンドラの二つのハンドラを用意し、異なるレベルにセットしてあげることで、ストリームでは効率的に状態を確認でき、精査したい場合はファイルのログを確認すれば良い、という仕組みだ。ファイル出力されたfft.logを確認してみると次のようになっていた。
1:BEGIN scrapeing Arsenal 4 - 1 West Bromwich Albion
scraped__init__scrape_summary,took 27.36544179916382
scraped__init__scrape_stats,took 34.192564487457275
scraped__init__scrape_stats,took 30.82896661758423
scraped__init__scrape_passes,took 21.500115394592285
scraped__init__scrape_passes,took 18.02293348312378
1:DONE scraping successfully
Possession: 64.4 - 35.6, Pass: 662 - 391これなら情報も一目で分かる。
なお今回の話については
qiita.com
でも同じように扱われている。参考にさせていただきました。
余談だが、seleniumのログ機能では、ロガーのみが設定されていてハンドラは設定されていない。したがってlogging.basicConfigでルートハンドラを設定しなくては読み取れない、という状況だと思うのだが、これってどうなんだ、と思ったり。
