概要
Pythonでシステム開発等を進めるとき、print文によるデバッグだけではキツくなりloggingモジュールを使おうとするも挫折するのは誰しもが通る道だと思います。又は、使ってはいるけど動作がよくわからないというケースもあるでしょう。
本記事では、loggingのソースコードを追いかけて、loggingの動作をスッキリさせた上で、これらを活用するための関数群を提供します。なお、loggingのバージョンは’0.5.1.2’を使っています。
スクリプトは以下で公開しています。
https://github.com/Rosyuku/RosyukuScript.git
loggingをimportして動かすまで
サンプルコードの確認
公式チュートリアルでは、loggingを動かすためのもっとも単純なコードとして以下が示されています。
サンプルコード1 実行プログラム
import logging
logging.warning('Watch out!') # will print a message to the console
logging.info('I told you so') # will not print anything
実行結果WARNING:root:Watch out!
上記を見ると、loggingをimportして、warningとinfoの出力をすると、コンソールにwarningの文章だけが出力されていることが読み取れます。とりあえず、まぁこんなものかという感じでしょうか。
次に、テキストファイルに出力するための方法として以下が記載されています。
サンプルコード2 実行プログラム
import logging
logging.basicConfig(filename='example.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')
実行結果（example.log）DEBUG:root:This message should go to the log file INFO:root:So should this WARNING:root:And this, too
上記を見ると、 basicConfigでfilenameを指定してloggingの内容を出力しています。ここもそういうものか、と行きたいところですが、実際動作させた人はこの時点で次の2点にハマる／違和感を感じるはずです。
詰まるポイント
- コンソールを再起動しないとファイル出力されない
- ファイル出力するとコンソールにログが出ない
1つ目は、カーネルを再起動しないとサンプルコード1と同じようにコンソール上に出力されて、ファイル出力されないという現象です。2つ目は、カーネルを再起動してファイルに書き込むようにすると、今度はコンソール上に出力されなくなるという現象です。どちらも公式チュートリアルでは何故か？には触れられていないため、ここで？？？となる人が多いと思います。
ソースコード確認
上記2つの違和感を払しょくするために、コードを眺めていきます。loggingの実態はlib/logging/__init__.pyに大体が記載されていて、いろいろ関数やクラスが定義されているのですが、注意深く見ていくと1731行目～、べた書きで以下のコードがあることが分かります。
__init__.py 1731行目～root = RootLogger(WARNING) Logger.root = root Logger.manager = Manager(Logger.root)
どうやらimportした時点でRootLoggerがWARNINGの条件でrootとして定義されていることが分かります。ここでもう一度サンプルコード1を見てみます。
（再掲）サンプルコード1 実行プログラム
import logging
logging.warning('Watch out!') # will print a message to the console
logging.info('I told you so') # will not print anything
実行結果WARNING:root:Watch out!
__init__.pyの内容より、warningだけが出力され、infoが出力されない出力結果になるのはRootLoggerのWARNING設定によるもの（WARNING以上しか出力しない）だということが読み取れます。また、引き続きlogging.warningのコードを見てみましょう。
__init__.py 1878行目～
def warning(msg, *args, **kwargs):
"""
Log a message with severity 'WARNING' on the root logger. If the logger has
no handlers, call basicConfig() to add a console handler with a pre-defined
format.
"""
if len(root.handlers) == 0:
basicConfig()
root.warning(msg, *args, **kwargs)
root.handlersの配列が0の時、basicConfigを読み出し、その後root.warningを読み出すという処理です。ここからも、logging.warningを使った場合、RootLoggerを使ってログを出力しているということが読み取れます。次にbasicConfigを抜粋して見てみましょう。
__init__.py 1739行目～（一部抜粋）
def basicConfig(**kwargs):
・
・
・
try:
if len(root.handlers) == 0:
・
・
・
if handlers is None:
filename = kwargs.pop("filename", None)
mode = kwargs.pop("filemode", 'a')
if filename:
h = FileHandler(filename, mode)
else:
stream = kwargs.pop("stream", None)
h = StreamHandler(stream)
handlers = [h]
・
・
・
for h in handlers:
if h.formatter is None:
h.setFormatter(fmt)
root.addHandler(h)
・
・
・
basicConfigでは、root.handlersの数をチェックして、0の場合だけ処理をするようにしています（else文がない）。また、何も指定がない場合StreamHanderを定義してrootのHandlerとして加えていることが分かります。サンプルコード1の動作結果から、StreamHanderによってメッセージが処理されるとコンソール上に出力されるのだろうと読み取れます。
これより、サンプルコード1では書いたコードの裏で以下のような動作が行われていたことになります。
- import logging → RootLoggerをWARNING 設定でrootとして定義
- logging.warning(‘Watch out!’) → basicConfigでStreamHanderを定義してrootのHandlerに設定し、warning扱いでメッセージを処理
- logging.info(‘I told you so’) → info扱いでメッセージを処理（Handlerが2で追加されたのでbasicConfigはスルー）
次にもう一度サンプルコード2を見てみます。logging.debug等の具体的な書き込み処理をする前に、basicConfigでfilenameとlevelを指定しています。
（再掲）サンプルコード2 実行プログラム
import logging
logging.basicConfig(filename='example.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')
実行結果（example.log）DEBUG:root:This message should go to the log file INFO:root:So should this WARNING:root:And this, too
先ほどbasicConfigの欄で見たように、RootLoggerのハンドル数が0でないとbasicConfigはスルーされてしまうため、違和感１の正体はこれであることが分かります。
また、カーネル再起動後ファイル出力された際には、RootLoggerは今度はFileHanderを持つため、logging.debugでbasicConfigが呼び出されずStreamHanderを持たなくなるためコンソール出力はされないだろうということが分かり、これが違和感2の正体となります。
これより、サンプルコード2では書いたコードの裏で以下のような動作が行われていたことになります。
- import logging → RootLoggerをWARNING 設定でrootとして定義
- logging.basicConfig(filename=’example.log’,level=logging.DEBUG) → basicConfigでFileHanderを定義rootのHandlerに与え、レベルもDEBUGに設定
- logging.debug(‘This message should go to the log file’) → debug扱いでメッセージを処理（Handlerが2で追加されたのでbasicConfigはスルー）
loggerを定義してhandleを設定するまで
サンプルコードの確認
前章で、loggingを定義した時点でRootLoggerが定義され、このhandleには1種類しか設定できない（それ以上割り当てようとしてもbasicConfigがスルーする）ことが分かりました。これで問題なければそれでも良いのですが、コンソールとファイルに同時に出力できない、loggerを他のスクリプトで呼び出す際に使い分けられないといった問題が残ります。
そこで、Loggerを任意に定義してFileHanderやStreamHandlerを手動で与えることが必要になりますが、その例として以下のコードが示されています。
サンプルコード3 実行プログラム
import logging
# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
# add formatter to ch
ch.setFormatter(formatter)
# add ch to logger
logger.addHandler(ch)
# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
実行結果2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message 2005-03-19 15:10:26,620 - simple_example - INFO - info message 2005-03-19 15:10:26,695 - simple_example - WARNING - warn message 2005-03-19 15:10:26,697 - simple_example - ERROR - error message 2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message
上記では、logging.getLogger(‘simple_example’)のように、ロガーに名前を使えてインスタンスを作成し、そこにlogging.StreamHandler()等で定義したハンドル（ch)をlogger.addHandler(ch)として与えていることが読み取れます。
addHandlerは複数回読み出せばその分だけハンドルが増えていくため、以下コードのように、FileHandlerも定義してaddHandlerすれば、コンソールとファイルの両方に出力することが可能となります。
def getLogger(name, level=logging.DEBUG, saveName="noname.log"):
"""
Loggerを作成する。
name：Loggerの名前（string)
level:Loggingのレベル(int)
saveName：Loggerの保存先（string)
"""
#ロガーの定義
logger = logging.getLogger(name)
logger.setLevel(level)
#フォーマットの定義
formatter = logging.Formatter("%(asctime)s:%(name)s:%(levelname)s:%(message)s")
#ファイル書き込み用
fh = logging.FileHandler(saveName)
fh.setFormatter(formatter)
#コンソール出力用
sh = logging.StreamHandler()
sh.setFormatter(formatter)
#それぞれロガーに追加
logger.addHandler(fh)
logger.addHandler(sh)
return logger
詰まるポイント
これでめでたしめでたしとなればいいのですが、実は1つ問題が残っていて、カーネルを再起動せずに複数回コードを実行すると、ロガーが毎回増えていき、ログがその数だけ出力される、ロガー増殖現象？が発生します。対策は以下のサイト様等にも記載されていますが、気になったのでソースコードを見ていきました。
【Python】 loggerのログが重複する
ソースコード確認
ロガーが増殖するということは、ロガーが消えずに保持されているということになります。そのコードを探すため、まずはgetLoggerを見ていきましょう。
__init__.py 1837行目～
def getLogger(name=None):
"""
Return a logger with the specified name, creating it if necessary.
If no name is specified, return the root logger.
"""
if name:
return Logger.manager.getLogger(name)
else:
return root
これをみると、名前からLogger.managerというのでLoggerが管理されているということが読み取れます。Logger.managerはrootが定義された部分で、Manager(root)という形で定義されていましたので、Managerクラスの該当部分を見てみます。
__init__.py 1144行目～（抜粋）
class Manager(object):
・
・
・
def getLogger(self, name):
・
・
・
try:
if name in self.loggerDict:
rv = self.loggerDict[name]
if isinstance(rv, PlaceHolder):
ph = rv
rv = (self.loggerClass or _loggerClass)(name)
rv.manager = self
self.loggerDict[name] = rv
self._fixupChildren(ph, rv)
self._fixupParents(rv)
else:
rv = (self.loggerClass or _loggerClass)(name)
rv.manager = self
self.loggerDict[name] = rv
self._fixupParents(rv)
return rv
・
・
・
見ると、「if name in self.loggerDict」という部分があり、この部分の分岐でgetLoggerが呼ばれた際にその名前がloggerDictにあれば該当するLogger(rv)を返す、なければ新しくLogger(rv) を作ってloggerDictに登録しているということが分かります。
つまり、サンプルコード3でLoggerを定義していた時、常に新規作成されるわけではなく、過去に同じ名前のLoggerを作っていた場合にはそれを読み出していたということですね。そのため、何度も同じコードを繰り返すと同じLoggerにどんどんハンドルを追加してしまうため、Loggerが増殖しているように見えたということのようです。
ここまでの結果からサンプルコード3の動作をまとめてみます。
- logger = logging.getLogger(name) → Logger.manager.loggerDictを参照し、なければ追加、あれば読み出しする。
- logger.addHandler(ch) → loggerに新しくchハンドルを追加する。
Loggerを増殖させないためには、すでに同じハンドルがある場合は増やさない、またはロギング終了時にloggerDictからLoggerを消しておくことが有効ということが分かります。
Loggingを使いこなすための関数
上記を踏まえて、以下のようなコードを作成しました。
getLoggerは、Loggerを作成するためのものです。ロガー終了時にはkillLoggerを呼び出してloggerDictからLoggerを削除するようにします。また、特定のハンドルだけを削除したいときにはkillhandlerが使えます。
# -*- coding: utf-8 -*-
import logging
def getLogger(name, level=logging.DEBUG, saveName="noname.log"):
"""
Loggerを作成する。
name：Loggerの名前（string)
level:Loggingのレベル(int)
saveName：Loggerの保存先（string)
"""
#ロガーの定義
logger = logging.getLogger(name)
logger.setLevel(level)
#フォーマットの定義
formatter = logging.Formatter("%(asctime)s:%(name)s:%(levelname)s:%(message)s")
#ファイル書き込み用
fh = logging.FileHandler(saveName)
fh.setFormatter(formatter)
#コンソール出力用
sh = logging.StreamHandler()
sh.setFormatter(formatter)
#それぞれロガーに追加
logger.addHandler(fh)
logger.addHandler(sh)
return logger
def killLogger(logger):
"""
loggerを削除する
logger：削除したいロガー(logging.Logger)
"""
name = logger.name
del logging.Logger.manager.loggerDict[name]
return
def killhandler(logger, handles):
"""
loggerから特定のハンドルを削除する
logger：ハンドルを削除したいロガー(logging.Logger)
handles：削除したいハンドル(list)
"""
for handle in handles:
logger.removeHandler(handle)
return
まとめ
loggingで詰まるポイントについて、ソースコードを追いかけて理由を解読し、（多分）スッキリさせることができたと思います。また、使っていくために便利な関数を作成しました。loggingは便利なモジュールなので、どんどん使っていきたいですね。