ログ出力のための print と import logging はやめてほしい

  • 449
    いいね
  • 6
    コメント

はじめに

http://docs.python.jp/3/howto/logging.html

Python入門系の記事では概して、Pythonのロギング機能の紹介で最初にlogging.debug()といったloggingモジュール付属の関数を呼ぶ方法を案内しています。

Python本家が提供するloggingの「基本チュートリアル」でもこの点で大差ありません。Python本家の基本チュートリアルでは、printを使用する方法も、ロギングの選択肢として有効であるとし、タスクに応じてprintlogging.debug()を使いわけよう、という流れで記述されています。

コマンドラインスクリプトやプログラムで普通に使う、コンソール出力の表示 : print()

そのような「基本」の説明の後「上級」チュートリアルになってようやく、Python言語付属のロギングメカニズムの説明が始まります。「上級」では4+1種類のデータ構造が紹介され、ここで「基本」で多用されていたlogging.debug()の正体が判明します。

ロギングは、 Logger クラスのインスタンス (以下 ロガー) にメソッドを呼び出すことで実行されます。各インスタンスには名前があり、名前空間階層構造に、ドット (ピリオド) をセパレータとして、概念的に並べられています。例えば、 ‘scan’ という名前のロガーは、ロガー ‘scan.text’, ‘scan.html’ および ‘scan.pdf’の親です。ロガー名は、何でも望むものにでき、ロギングされたメッセージが発生した場所を指し示します。
..
ロガーの階層構造の根源は、ルートロガーと呼ばれます。それが、関数 debug(), info(), warning(), error() および critical() によって使われるロガーとなります。これらの関数は単に、ルートロガーの同名のメソッドを呼び出します。これらの関数とメソッドは、同じ署名をもっています。ルートロガーの名前は、ログ出力では ‘root’ と表示されます。

ログ出力のためにprintを使用する実用のPythonアプリケーションも実際に世の中にあります。多分「結構」あると思われます。

以前の筆者もprintでログを表示していました。しかし今では10行に満たない確認用の極小のスクリプトのようなケースを除いてほぼprintによるロギングは避けています。

個人的には、printloggingをログに使う方法は、Python初心者には一切教える・薦めるべきではないと考えています。少なくとも、Python公式の「基本チュートリアル」の教える順序としては適切ではない気がしています。

この記事はどうしてそう考えるに至ったかの説明を試みるものです。

以下を読む場合の注意

この記事を記述している筆者はPythonのコミッターといったほどのPython知識を持っているとは言えません (初版公開時点でもそうでしたし、リバイズした時点でもそうです)。内容に誤りがある場合には是非ご一報ください。

また「筆者自身がloggingモジュールを知ってからもしばらくの間、チュートリアルすらきちんと読んでいなかった」という、本来なら筆者個人の問題とみなすべき事実も、この文を書くきっかけになっています。内容が一部「初心者の遠吠え」に見えなくもないところもドキュメント側の問題であると少し前のめりになっている点、ご容赦ください。

ベストプラクティスだけを知りたい方は Python Logging Best Practices (英語)を読んで下さい。

何故ダメなのか: print

他人の目線で特定のPythonアプリの実装を見た時の話をします。

printでログ出力を行われた際の問題点の1つとして「表示される文字列が、ログ出力なのか、そのコマンドラインツールが本当にユーザに提示したい情報なのか分からない」ことが挙げられます。

Pythonのprintそれ自体を使うのは「ログ目的でなければ」問題はありません。例えば、自分でLinuxのteeコマンドを実装するとします。標準入力で受け取ったデータをファイルに書き出しつつ、標準出力をprintで書き出すのは必ずしも間違いではないでしょう。これは「本当に欲しい出力」の一例です。

「本当に欲しい出力」というのはここでは、そのプログラムが「何か入力を受け取って、何かを出力する」というツール出会った際の出力側の「何か」です。

一方、ログとはその過程で生じるプログラムが動作した「記録」です。

この記事で言いたいのは「ログ出力のため」、つまり「エラっちゃった。ここでエラっちゃったから、教えるよ〜」と記録させたい場合に、生printベースのアプローチはやめてくれということです。

これが10行〜20行くらいのスクリプトならまだマシですし、冒頭に書いたように筆者もそのくらいならばprintを使います。

例えば、0で割った際の挙動を知るサンプルコードを書くなら、

print('started')
a = 1/0
print('ended')

などと書いて問題はないでしょう。このprintは実際、欲しい出力というよりはプログラムの動作した「記録」を示すもので、ログです。しかしこのサイズのコードでloggingモジュールを使うのが冗漫なのは流石に明らかでしょ、ということです。

一方、ファイルが二桁個に渡るような、比較的込み入ったライブラリ・ツールがprintベースのログシステムを独自に完成させていることがあります。

自分が出会った、あるPythonライブラリの話をします(少なくとも見つけた当時は比較的有名なライブラリでした)。そのライブラリではloggingモジュールのLoggerHandlerを組み合わせれば容易に実現出来ることをprintをベースに自前で実装していました。ログレベルに相当する機構はありませんでした。ログの種別を分けるためのタグのような機構がありましたが、タグは出力をするかしないかだけのif分岐に使われるだけで、printに表示される時点では文字列の一部に混ぜ込まれてしまいます。

このようなライブラリ独自のロギング機構には多くの問題があります。まず、出力されるログ内容が「シビアなログ」なのか「デバッグログ的に出力されるものなのか」判別出来ません。。その中にどのカテゴリーに属するエラーなのかも、生文字列を再度正規表現等で振り分ける必要が生じます。これではログに対するまともなコントロールが出来ません。

また、Pythonに慣れ親しんでいるユーザから見ればPythonのloggingとは異なるロギングメカニズムを押し付けられており、その機構の意図と制約を理解するという余計な手順を踏む必要があります。Pythonモジュールに不足を感じるのならまだしも、単なる劣化版を作られると最低です。

Pythonに限らず、stdoutとstderrを分けるだけでは現代的なロギング機構としては合格点は取れないと考えるべきです。

printベースで独自構築したアプリを、loggerの機能利用するために書き換えるのは、結構、というか多分大変面倒です。受け入れ側でstderrの中身を「サルベージ」してloggerに送り直すのも可能かも知れませんが面倒です。どちらにしても、正直不毛です。

利用する側からすると、printベースのアプローチは「下水に全部流しておいたから必要なら取ってきてくれ」みたいに見えてしまいます。

GitHubで公開されてるツールがあったとして、誰かが興味を持った時点でprintデバッグ世界が展開されていたとすると、ツールの本質にちらりとも触れてないのに、ユーザは頭をかきむしることになります。自分は、なった。

# そもそも、そのPythonライブラリの独自ログ機構があまりに劣悪で衝撃を受けたことが、この記事を書くきっかけです。

何故ダメなのか: logging

Pythonのロガーは階層構造・木構造的になっています。木の比喩で言えば、はっぱの方から到達したログ(LogRecordクラスのインスタンス)を、枝に当たる地点(Logger)で受け取って、根っこロガー(「ルートロガー」)に至るまで、複数のロガーで一つのログを繰り返し処理できます。一部の枝から次の(根っこに近い)枝にログを伝播させない事もできます(propagate属性)。細かいところは上級チュートリアルを読むのが良いです。

ここで、

logging.debug()

と書くと、Pythonが持つログの木構造中でもその根っこ「ルートロガー」に直接情報をぶちこむことを意味します。

ルートロガーは起動したPythonランタイムから呼ばれる全モジュールのロギング機構の根っこでもあり、「グローバル変数」そのものです。

各ライブラリがloggingモジュールに付属しているこういった関数(logging.info()等も同様)を直接呼ぶと、暗黙のうちに他のモジュールの世界(名前空間)を汚すことになります。

具体的には、ライブラリAのログを見るためにルートロガーのログレベルをDEBUGにすると、他のライブラリ(ライブラリB・ライブラリC……)がぶちこんだルートロガーへのDEBUGログも不可分に表示されます。分離出来ない点で、printでstderrに流し込まれた名状しがたいログのようなものに似ています。

実は上級チュートリアルや『Python Cookbook』のような(上級者以上向け??)情報源では「ライブラリを構築する場合には」loggingではなくloggerを使うことを考えろと書いてあります。

http://docs.python.jp/3/howto/logging.html#configuring-logging-for-a-library

また、基本チュートリアルでも当然その辺りは記載はされています。

この mylib.py でのパターンは、複数のモジュールに一般化できます。なお、この簡単な使用パターンでは、ログファイルを見ることで、イベントの説明は見られますが、アプリケーションの どこから メッセージが来たのかを知ることはできません。メッセージの位置を追跡したいなら、このチュートリアルレベルを超えたドキュメントが必要になります – 上級ロギングチュートリアル を参照してください。

筆者はPythonを使い始めてからそう短いわけでもないんですが、ここあたりがまともに目に入ったのは数年経ってからです。また、真意を理解できるようになったのも同じくらいのタイミングです。複数の野良記事を見て「そうか……そうだよな、logging直下の関数は良くないよなぁ」と納得して、再度チュートリアルを読んだら、実は書いてあったという。

野良記事の例: Python Logging Best Practice (英語)

個人的に非常にやっかいだと思ったのはチュートリアルでは「logging.debug()printでログ出力できるよ」というひと通りの説明をした後に、より適切なベスト・プラクティスが書かれているということです。

振り返ってみると、先に紹介されているメソッドはそもそも旨みがかなり少ない気がしてきます。そして、全力で全部書き換えることに。

import logging すら腹立たしい

自分のミスも多々絡むんで恥ずかしいのですが……

上のような話題の一部を理解した後、logging.debug()とか使わないほうがいいよね、という常識に一旦たどり着いた後、筆者は各モジュールの先頭部分でlogger = logging.getLogger(__name__)のように書いて、以降のコードでは全てloggerを使うようになっていきました。

しかし書いている途中で、

logger.debug()

logging.debug()

を混ぜて書いてたりするんですよね。それ違う場所に飛んでる〜〜!

大したことないだろうと思うかもしれませんが、ログを見ながらバグの原因を追跡したりする場合、loggerloggingという些末な違いを逃すだけで、関数がどこを辿ったのかが分からなくなってしまうのです。loggerが欲しいレベルのログレベルやログファイル指定をしたLoggerインスタンスを差していたとして、高度に構造化されたログの木構造を作れば作るほど、logging.debug()が指すルートロガーは何も出力しない木偶の坊になりがちです。logger.debug()は意味のある文字列をファイルに出力しlogging.debug()は「ダンマリ」かどこか全く別の場所にこっそりメッセージを残すことになり、ログファイルからの追跡が困難か不可能になります。

ブレークポイントなどを駆使してインタラクティブにデバッグしていなければ、下手をするとloggerloggingという文字列の些末な違いには最後まで気づかないかもしれません。人間は似ている文字列を判別するのは得意じゃないんですよ。あいにくimport loggingした時点でどっちも文法的にはエラーではないですし。エディタのハイライト色が違うことを期待します??

簡単な回避策があります。

# ダメダヨー
import logging
logger = logging.getLogger(__name__)

とは「書かない」ことです。

from logging import getLogger
logger = getLogger(__name__)

と書くことです。

この単純な回避策を思いついた時にはドキッとしました。気づかなかったのが恥ずかしい。

なんで思いつかないかって、昔から

import logging
logging.debug()

を案内されてたからに違いありません。他人のせいにしてますが。

このすり替え問題を最初に「ヤバい」と思ったのは、Django (Webフレームワーク)で長期間動くサービスを作る過程で、上のloggingloggerを間違えて実装していたときでした。

関数の実装を追いかけているとき、何故か一切ログが出ない瞬間があり「何で出ないの、ねぇ、なんでここだけログが出ないの……(゚Д゚)」って顔して調べ……マジでタダのタイポでした。泣けます。繰り返しますけど、人間は似ている文字列を判別するのは得意じゃないんですよ。

ここで、import logging自体を敢えて問題視しています。このモジュールの直下にある関数には

  • グローバルなログ挙動を設定するもの
  • グローバルなログ空間にゴミをぶちまけることを許容(むしろ推奨)するもの

の二つの機能が混じっています。大いに混じっています。

前者はプログラムの全体にごく一瞬だけ限定的に影響を与えるべきです。後者はそもそも確信がない限り使うべきではないです。

どちらのケースでもimport loggingという全部盛りを先頭で許すには微妙すぎ、でもチュートリアルはこれを最初に説明しています。まるで初心者にミスることを推奨しているかのようです。

# ヒューマンエラー回避のために、loggerというオブジェクト名を使うのをやめてlog.debug()としても良いとは思います。ただしこれはloggingなのかloggerなのかやっぱり分かりづらいので、筆者は好みません。

ついでに主要な関数はloggerを受け取ってくれ。デフォルトで自前のロガーを使っていいから

関数がオプショナル引数を経由するなどしてloggerを受け入れられる準備をしてくれると、それをライブラリとして使おうとする場合に柔軟性が増します。いわゆるひとつのDependency Injectionです。

def do_some_great_staff(arg_a, arg_b, logger=None):
    logger = logger or _your_default_logger
    # すっごいこと

Python3ならばオプショナル引数であることを強制してくれてもかまいません。むしろして!

def do_some_great_staff(arg_a, arg_b, *, logger=None):
    logger = logger or _your_default_logger
    # すっごいこと

# Python3では裸の*後は「キーワード専用引数」となります。Python2系にはこの文法はありませんので**kwargsで動的に処理します。詳細は『Effective Python』の「項目21: キーワード専用引数で明確さを高める」や用語集を参照してください。

Loggerオブジェクトを自前で管理して外部に晒さない場合、そのモジュールが持つロガーを他者が必要に応じて入れ替えてログを統一的に管理することができません。

開発者AがgetLogger('service_a.do_something')で作ったLoggerを使って一連の処理をしている最中、外部のライブラリBのAPIを使ったとします。そのライブラリがgetLogger('service_b.do_bad_thing')経由でLoggerを取得しておりこれを入れ替えられない場合、おそらくHandlerもFormatも別管理です。これは関数の実行過程を追跡する上では非常に都合が悪いです。開発者A目線では「ここでは俺のLoggerを使わせてくれ〜」てことになりがちです。

ライブラリ内の各関数を、外部の人が別の目的で別のLoggerにひもづけられることがとても便利なケースがあるのです。

よほど他の事情(パフォーマンスとか)を気にするのでなければ、是非全部logger毎に処理を分離できる構造であって欲しいし、自前で管理する場合にもloggerの木構造をうまく使って系列を名前で分けて欲しいのです。

さらに、そのレベルの対応をGitHubに公開する時点でやっておいて欲しい

筆者としては「自前スクリプトでーす、とりあえず書いて公開してみました!」というお気楽な公開段階でも、気づいたらlogger使ってくれている状態になって欲しいのです。

現状のチュートリアルを「ささっと」読んだ人はprintloggingを選んでしまいますが、ほんの少し説明の順番を変えるだけでLoggerを使えるようになるはず。「使ってみたレベル」ではprintloggerってコストあんまり変わらない気がするんですよね。

以下に例を挙げます。

from logging import getLogger, StreamHandler, DEBUG
logger = getLogger(__name__)
handler = StreamHandler()
handler.setLevel(DEBUG)
logger.setLevel(DEBUG)
logger.addHandler(handler)

logger.debug('hello')

だけで終わります。「おまじない」行としては多い気もしますが、コピペでいいからやれ的な感じがあります。

# 個人的にはここでsetLevel()が二回出てるじゃないですかやだー、という非難を上げさせる方がむしろいいと思うんですよ。あ、この非難は数日前に自分が叫んだことです。喉元過ぎれば略。

この場合、ログを吐き出したくなければStreamHandlerの代わりにNullHandler使うだけですし、
サイズに応じてログローテーションを実行するのならRotatingFileHandlerだってあります。
エラーメッセージ以上をメールしたい場合はSmtpHandlerとかある!

ここでの主張は「そういうおまじないレベルの文言を最初の最初に教えて欲しい」ということです。
逆に、ロギングに関するチュートリアルでprintlogging.debug()でもいいよ、とはヒトコトも書くべきではない。

注: ここでの主張は「初心者に重たいことを要求しておこう」ではありません。「袋小路に容易に突入するような文言をチュートリアルに含めるのはやめとこうぜ」という話です。どうにしたってprintは使う状況では使いますよ。シンプルだから。ただ、その使用方法を後押ししないだけで良い。どうせ最後はそういう方法が便利なケースもあると知ることになるのだから。

注2(2016-11-17追記): なお上のDIをやってしまうとDEBUGログ(パスワードとかをダンプするかも)を外部の人が任意に表示できるようになるわけで、少しセキュリティ的に心配な向きはあるかなぁとは思います。とはいえインスタンスにプライベート変数が事実上ない言語で何言ってんだろう、という気もします。

「教える順序の問題」

引き続き「printlogging.debug()なんてきったないものを最初に教えるな」という話をしています。

何かデバッグしたい時って、とにかくそのバグを潰したい一心でドキュメントを読みます。

そのとき、開発者はシステムの全体系を学ぼうとは思っていません

ドキュメントの最初に、最も簡潔で多分まともだとみんなが信じる方法が書かれているものと信じるはずです。少なくともあとになってから「残念、実は適切な方法じゃないんだ!」みたいなことが書いてあるとはまず期待しません。

一方、現状のPythonのloggingドキュメントは、体系を最後まで学んでくれるという期待のもとに、重要なことが最後に書かれている印象です。あるいは複数の方法があるとして(その時点でPythonとしてはNGな気もしますが)、一つ目を呼んだ時点で読者が納得して去ってしまう構造になっています(「上級」に基礎が書いてあるのです)。

後に書かれた内容の方がより適切なのに、先に推奨されない方法が記載されてしまっているばかりに、初心者がドキュメントを途中で離脱すると推奨されない方法だけがその人に記憶される……

最初にそのようにドキュメントを読んでからしばらくして、利用者は自分が何をやって何でそのログ記録方法を取ったのかを忘れ、またチュートリアルの最初の10行を呼んでlogging.debug()を使う……

あるいは最も良くないケースとして、printでいいと勘違いしたまま、自分の中の独自ログ機構が作り込まれてしまう……

ログに関して言えば、ドキュメントの冒頭に解があるように見えるこの方法は、この点では非常にまずいのでは、という強く思います。そもそもの教え方が「オカシイ」。

そのようにして利用者が誤った形でロギング機構を整えてツールを公開し、ツールがある程度洗練された段階でそれを多くの他者が見るようになる、の、ですが……そのときには割と手遅れということもあります。こうなってしまうのは、必ずしもその開発者がマズイことをしているだけではないと思います。

さらに困るであろうことは、そのツールの開発者や利用者らが本当に解決したい問題とログ機構は通常全く直結していないことです。問題は解決してくれるけど、ひどくいびつなログ機構を内包しているために「欲しいものは揃っているのに何か……なんだか……使いづらいぞ!?」ということに。初めから正解を選んでいなければ、こういう問題は直すモチベーションが全く湧かない問題でもあります。

もちろん、公開されたソースに対して修正案を出すことは当然出来ます。ログがやってるのは普通、コードのどこかに文字列を生成して表示させる関数を呼ぶだけのはずですから、外部の人が「このprintベースのログ機構、Pythonの標準モジュールにあるLoggerで全部入れ替えられるよ」とPR(Pull Request)するのは、出来ますよね。

でも、ログの出力ロジックの修正をその段階でPRするって不毛じゃないですかね……いや、単に鬼の首取りたいのならいいですけどね。

「Pythonロギングの詳細を知らないままでもいいからlogger = getLogger(__name__)使え、以上!」って言った方が、はるかに世界がすっきりする気がしています。それを関数の引数にするのもまだ楽だし、**kwargsやオプショナル引数に引きこむのだって大した手間ではないでしょう。

長くなった

とりあえずPythonロギング初心者だと思うなら、

from logging import getLogger, StreamHandler, DEBUG
logger = getLogger(__name__)
handler = StreamHandler()
handler.setLevel(DEBUG)
logger.setLevel(DEBUG)
logger.addHandler(handler)

logger.debug('hello')

って書け、以上という話です。

ところでそれを伝えるためだけに、なんでこんな長い文章になったんでしょ……

はるか大昔からPythonのロギングチュートリアルは今の構造なので、今更これを書いてどうなるのか、という話に筆者は興味がありません。本家に殴り込むモチベーションもマジありません。しかし、気にしておくべき重大な課題はあると思います。

Pythonに興味があるけどログよく分からん、という場合にはgetLogger(__name__)のことだけ頭の片隅に残しておいていただければと思います。少なくともそれが頭の片隅にでも引っかかってれば、チュートリアルを途中で読むのをやめるということは少なくなるでしょう。

関連

更新 (2016-11-17)

内容を読み直して、一部補足したり日本語がカオスだった部分の修正を試みました。Python3を意識したり、一部具体的なコードを追加したりしています。

とはいえ、当時の筆者が持っていた「勢い」が大事という気もしたので、冗長な文章そのものは手付かずです。

そのうち自分的にベスト・プラクティスと思う方法だけ抽出した文章を別途書こうと思います。