loggingモジュールで複数の出力先に別のログレベルで出力する
要求仕様:
- 標準エラー出力には処理に失敗したファイル名を表示
- ログファイルには失敗した物だけでなく処理したファイルの一覧全てを表示
これを実装するためにloggingモジュールを用いた。
まず、 http://www.python.jp/doc/release/lib/multiple-destinations.html を参考にして次のように書いた。baseConfigで標準エラー出力の方を指定しているのは、コマンドラインオプションでログファイルに出力するか切り替えられるようにしたかったからである。
import logging logging.basicConfig(level=logging.WARNING, format='%(message)s') logfile=logging.FileHandler("/tmp/test-logfile", "w"); logfile.setLevel(logging.INFO) logging.getLogger('').addHandler(logfile) logging.debug('A debug message') logging.info('Some information') logging.warning('A shot across the bows')
しかし、これを実行すると標準エラー出力の方は問題ないのだがログファイルにも
/tmp/test-logfile: A shot across the bows
しか記録されていない。親で設定されているログレベルよりも低い物は出力されないという仕様でもあるのかと思いドキュメントを流し読みしたがそのような記述は見られなかった。
LoggerオブジェクトのsetLevelにはログ記録しようとするメッセージで、lvl よりも深刻でないものは無視されます。
と説明があるので、ルートロガーのレベルがwarningになっているせいだと思いsetLevel(logging.DEBUG)したLoggerを別に作ってみた。
import logging logging.basicConfig(level=logging.WARNING, format='%(message)s') logfile=logging.FileHandler("/tmp/test-logfile", "w"); logfile.setLevel(logging.INFO) logging.getLogger('').addHandler(logfile) logger1 = logging.getLogger("hoge") logger1.setLevel(logging.DEBUG) logger1.debug('A debug message') logger1.info('Some information') logger1.warning('A shot across the bows')
すると今度は標準エラー出力にデバッグメッセージまで出力されるようになってしまった。
stderr: A debug message Some information A shot across the bows
いよいよわからないのでソースを読んでみることにする。
/usr/lib/python2.6/logging/__init__py:
class Logger(Filterer): .... def warning(self, msg, *args, **kwargs): """ Log 'msg % args' with severity 'WARNING'. To pass exception information, use the keyword argument exc_info with a true value, e.g. logger.warning("Houston, we have a %s", "bit of a problem", exc_info=1) """ if self.isEnabledFor(WARNING): self._log(WARNING, msg, args, **kwargs) .... def isEnabledFor(self, level): """ Is this logger enabled for level 'level'? """ if self.manager.disable >= level: return 0 return level >= self.getEffectiveLevel() ....
Loggerのログレベルに満たないメッセージはどこにも渡されることなく無視されている。これがLoggerオブジェクトのsetLevelのドキュメントに書いてある挙動だろう。
ではbaseConfigで設定した出力先はどのように扱われるのかと調べてみた。
def basicConfig(**kwargs): """ (略) """ if len(root.handlers) == 0: filename = kwargs.get("filename") if filename: mode = kwargs.get("filemode", 'a') hdlr = FileHandler(filename, mode) else: stream = kwargs.get("stream") hdlr = StreamHandler(stream) fs = kwargs.get("format", BASIC_FORMAT) dfs = kwargs.get("datefmt", None) fmt = Formatter(fs, dfs) hdlr.setFormatter(fmt) root.addHandler(hdlr) level = kwargs.get("level") if level is not None: root.setLevel(level)
適切なハンドラを生成してハンドラにレベルを設定せずにハンドラを登録している。上で標準エラー出力に全て出力されてしまったのはこのためだろう。callHandlersメソッドでは次のように、親のロガーに引き渡すのではなく先祖のハンドラを直接呼び出し、親のロガーのレベルを無視していた。
class Logger(Filterer): .... def callHandlers(self, record): .... c = self found = 0 while c: for hdlr in c.handlers: found = found + 1 if record.levelno >= hdlr.level: hdlr.handle(record) if not c.propagate: c = None #break out else: c = c.parent ....
しかし、それよりもbaseConfigメソッドで目についた所があった。if len(root.handlers) == 0:である。どうやらハンドラが登録されていればこのメソッドは丸ごと不要らしい。baseConfigは呼び出さなければならないという固定観念にとらわれていたが、確かに考えてみると複数ハンドラを登録して、ロガーのレベルを設定してやれば別に呼び出す必要はない。というわけで次のように書くことでやりたいことを実現できた。
import logging logging.getLogger('').setLevel(logging.DEBUG) logfile=logging.FileHandler("/tmp/test-logfile", "w") logfile.setLevel(logging.INFO) logging.getLogger('').addHandler(logfile) console=logging.StreamHandler(); console.setLevel(logging.WARNING) logging.getLogger('').addHandler(console) logging.debug('A debug message') logging.info('Some information') logging.warning('A shot across the bows')