logging入門
はじめに
Pythonのloggingについて検索すると、qiitaの記事だとhttps://qiita.com/amedama/items/b856b2f30c2f38665701 が上位にくるんですが、正直わかりにくくなっているだけだと思います。本記事では、基本の使い方と、実際の有名所のライブラリのloggingの活用例(3つ)の2部構成で説明していきたいです。
対象者
-
ライブラリを作成するのに、loggingを活用したい人
-
そろそろ
printデバッグやめたいけど、loggingの玉石混交の解説を見て、半ば諦め気味の人. どれが本当に正しい説明なのか、あんまり良くわかってない人
本記事の特長
- いろんなブログの説明や記事を見ると、オレオレ視点でこうしよう、みたいに書かれている内容のものが多すぎる1ので、可能な限り公式の引用元を明示した。
- 本記事の「基本の使い方」の説明をカバーするために、有名所の外部ライブラリ(
gensim.word2vec,requests,google-api-python-client)が実際どのようにloggingを使っているかと、これらのライブラリのloggingを使用者側(ユーザー側)がどのように扱えばよいかを書いた。
基本の使い方
原点に立ち返るという意味で、loggingのことが書いてあるPEP282に基づいて説明します。
まず、ライブラリ側とそれを使う側(ユーザー側)でloggingの書き方が違います。ここをごっちゃにすると、話が絶対に錯綜するので、必ず意識するようにします。
ライブラリ側では、module毎にloggerを定義しておいて、logとして出したい情報に関して、debug, info, (warning)等を使い分けます2：
ライブラリ側
ライブラリ側では、先頭にlogger = logging.getLogger(__name__)を指定して3、loggingしたい場所にlogger.debug(msg)みたいなふうに書くだけです。(__name__は、ライブラリのモジュールの名前です。詳しくは、インポート関連のモジュール属性 を参照のこと)。
細かな出力方法はユーザー側で設定するので、それ以外のコーディングは必要ないです4。
import logging
# __name__はこのモジュールの名前
logger = logging.getLogger(__name__)
class Hoge():
def __init__(self):
pass
def do(self):
# do sth
# おもに問題を診断するときにのみ関心があるような、詳細な情報。
logger.debug("test")
# 想定された通りのことが起こったことの確認。
logger.info("info")
def do():
# do sth
logger.debug("testtest")
簡潔ですね！
ユーザー側
ライブラリ側とは別に、ユーザー側でのloggingの記述の説明に移りたいと思います。ここで、ユーザー側とはライブラリのdeveloperではなく、ライブラリの使用者のことを指すことにします。
ユーザー側では、(必要ならば)ロギングレベルや出力ファイル、モジュールの指定ができます。全く何も書かなければ、warning以上のlogがsys.stderrに吐き出されます。
上記で説明したように、この部分をライブラリ側で実装すべきでないです。
以下、よく使うloggingのパターンについて見ていきます5。
説明のために、こんなようなライブラリ構造を想定します。
repo_name
│
├── my_pac
│ ├── __init__.py
│ ├── mod01.py
│ ├── mod02.py
│ └── mod03.py
├── setup.py
├── README.md
└── .gitignore
my_pacのmod01のみに絞ってsys.stderrにlogを出す場合
import logging
# my_package.my_moduleのみに絞ってsys.stderrにlogを出す
logging.basicConfig() # 最初に呼び出しが必要(注釈も参考のこと)。 defaultはlevel=logging.WARNING
logging.getLogger("my_pac.mod01").setLevel(level=logging.INFO)
このように指定することで、logging.INFO以上の、つまり、logging.INFO, logging.WARNING, logging.ERROR(, logging.CRITICAL)のレベルに当てはまるlogがmy_package.my_moduleに関して出力されます。(setLevelにlogging.DEBUGを指定すれば、logging.DEBUGのものも出力してくれます)6
念の為ですが、from my_pac import mod01してようがしてまいが、my_pac.mod01という風に、パッケージ名を省略せずに書いてください。
複数のモジュール(この場合は、my_pacのmod01, mod02)に対して、logを出したい
import logging
logging.basicConfig() # defaultはlevel=logging.WARNING
module_levels = {"my_pac.mod01": logging.DEBUG, "my_pac.mod02": logging.INFO}
for module, level in module_levels.items():
logging.getLogger(module).setLevel(level=level)
とにかく、logging.basicConfig()の後に、所要のmoduleに関して、logging.getLogger(module).setLevel(level=level)を書けば良いです。
my_pac以下のすべてのmodule(mod01, mod02, mod03)でlogを出したい
import logging
logging.basicConfig(level=logging.ERROR) # WARNINGレベルも出してほしくないときには、levelオプション指定すれば良い。
# my_package以下のすべてのmoduleでDEBUGレベルのlogを出す。(それ以外のmoduleではロギングレベルをERRORと設定しているので、logは出ない)
logging.getLogger("my_pac").setLevel(level=logging.DEBUG)
Note) これらは、init.pyに指定する__all__とは、全く何も関係ありません。(そもそも__all__とは、from my_pac import *を(アスタリスクを用いて)書いたときに何をimportするかを指定するための変数でした)
logging.DEBUGでlogを出したいが、あるモジュールのみ(例えば、my_pac.mod01のみ)loggingを抑制したい(ロギングレベルをlogging.ERRORにあげる)
import logging
logging.basicConfig(level=logging.DEBUG)
logging.getLogger("my_pac.mod01").setLevel(level=logging.ERROR)
logの内容をlogファイルに書き込む(DEBUG levelで)と同時にsys.stderrにも(INFO levelで)書き込む
ここで注意したいのが、ファイルにはすべてのmoduleのlogを出力したいので、basicConfigにfilenameやformatの設定をする必要があるということです7。sys.stderrのloggerの設定はその後に個別で対応します。
import logging
# 書き方は、https://docs.python.jp/3/library/logging.html#logrecord-attributes を参照のこと。
_detail_formatting = "%(relativeCreated)08d[ms] - %(name)s - %(levelname)s - %(processName)-10s - %(threadName)s -\n*** %(message)s"
# まずはファイルの設定 logは詳細に取りたい
logging.basicConfig(
level=logging.DEBUG,
format=_detail_formatting, # 出力のformatも変えられる
filename="./sample.log", # logファイルのありか
)
# つづいて、sys.stderrのloggerの設定
# http://docs.python-guide.org/en/latest/writing/logging/#example-configuration-directly-in-code も参考になる
# log出力先をsys.stderrに
console = logging.StreamHandler()
# 個別にformatの形式を変えられる
console_formatter = logging.Formatter("%(relativeCreated)07d[ms] : %(name)s : %(message)s")
console.setFormatter(console_formatter)
# sys.stderrにはざっくりとしたerror情報で良いので、INFOとする
console.setLevel(logging.INFO)
# consoleという設定logging設定ができたので、適用したいmoduleに対して、addHandlerにその設定を突っ込む
logging.getLogger("my_pac.mod01").addHandler(console)
# 複数のモジュールでlogを出したい場合はこうする(`複数のモジュールでlogを出したい`の例の通り)
# logging.getLogger("my_pac.mod02").addHandler(console)
Note) loggingでファイルに書き込む場合は、デフォルトでa(追記:append)です。これはloggingの性質上当たり前8なのですが、open関数とかのmodeのデフォルト値と違っているので、ちょっとだけ注意です。
よく使うのは、こんなかんじですかね？
追記) ライブラリ側とユーザー側が1ファイルにまとまっている場合、つまり、if __name__ == "__main__":以下でスクリプトとして実行する場合も考え方は同じです。詳しくは、
https://gist.github.com/podhmo/7fcc1024dec64b42074c3d3d5c789f98
をみてください。
例
ここでは、有名なライブラリがどのようにloggingを使っているかと、どのようにこれらのlogを扱えばよいのかを解説します。
普通のやつ、loggingがないやつ、めんどくさいやつの3つ紹介します
gensim.word2vec
まずは普通のやつから。自分がそれなりに使用している外部のlibraryでどんなふうにloggingが使われているか見ます。
gensim自体は巨大なライブラリ群になっているので、今回はword2vec.pyのコードを参照したいと思います9！
=> https://github.com/RaRe-Technologies/gensim/blob/e92b45d3f83ad670da9cf6ae20ae86a2a1c8558c/gensim/models/word2vec.py 10
githubのリンク貼ってあるので、気になったら飛んでくださいね
例えばですが、128行目 でlogger = logging.getLogger(__name__)を作っていて、
必要なところに、infoとかdebugとか挟んでいます(例えば、504-507行目)
user側(__main__部)がどのように実装されているかというと、1720-1722行目 にこんな感じで実装されていて、上記で述べたloggingの使い方と合致してます。
requests
お次は、みんな一度は使用したことがあるであろうrequestsライブラリ。これは、公式のurllib3のラッパーです。
requests本体には、loggingは含まれていません11。なので、logging.getLogger("requests").setLevel(level=logging.DEBUG)と書いても何も起こりません。urllib3由来のlogを吐き出したい場合は、以下の設定をユーザー側で行います。
import logging
logging.basicConfig()
logging.getLogger("urllib3").setLevel(level=logging.DEBUG)
# put in your code!
import requests
r = requests.get('http://google.com/')
を実行することで、
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): google.com
DEBUG:urllib3.connectionpool:http://google.com:80 "GET / HTTP/1.1" 302 268
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): www.google.co.jp
DEBUG:urllib3.connectionpool:http://www.google.co.jp:80 "GET /?gfe_rd=cr&dcr=0&ei=M7PoWZDjG7DEXqujgGA HTTP/1.1" 200 5207
がlogとして出力されます。
または、公式でsys.stdoutに詳細な情報を出力してくれるようにしているみたいで12、
# Enabling debugging at http.client level (requests->urllib3->http.client)
# you will see the REQUEST, including HEADERS and DATA, and RESPONSE with HEADERS but without DATA.
# the only thing missing will be the response.body which is not logged.
try: # for Python 3
from http.client import HTTPConnection
except ImportError:
from httplib import HTTPConnection
HTTPConnection.debuglevel = 1
# put in your code!
import requests
r = requests.get('http://google.com/')
とすることで、
send: b'GET / HTTP/1.1\r\nHost: google.com\r\nUser-Agent: python-requests/2.18.4\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
reply: 'HTTP/1.1 302 Found\r\n'
header: Cache-Control header: Content-Type header: Referrer-Policy header: Location header: Content-Length header: Date send: b'GET /?gfe_rd=cr&dcr=0&ei=ubLoWZ3fFbHEXpy5jagC HTTP/1.1\r\nHost: www.google.co.jp\r\nUser-Agent: python-requests/2.18.4\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Date header: Expires header: Cache-Control header: Content-Type header: P3P header: Content-Encoding header: Server header: Content-Length header: X-XSS-Protection header: X-Frame-Options header: Set-Cookie header: Set-Cookie
という情報を出してくれます。(ただ、これはsys.stderrに吐き出される情報でないし、loggingモジュールで管理できないので、どうかな？というのはあります)
google-api-python-client
続いては、google-api-python-clientです。こちらは
INFOレベル以上のログ出力を指定してもログが結構大量に出てきてしまう、logging的には始末が悪いライブラリです13。
import apiclient, httplib2
import logging
_detail_format = "%(asctime)s - %(levelname)s - line %(lineno)d - %(name)s - %(filename)s - \n*** %(message)s"
logging.basicConfig(
format=_detail_format,
level=logging.DEBUG,
) # defaultはlevel=logging.WARNING
h = httplib2.Http()
refresh_token = "aaaaaaaaaaaaaaaaaa" #適切なものを指定
h.default_headers = {"x-oauth-refreshtoken" : refresh_token}
service = apiclient.discovery.build("analytics", "v3", http=h)
# この後、queryにdict型のデータを突っ込んでレスポンスを得る
# response = service.data().ga().get(**query).execute()
たとえば、これを実行すると、私の環境では、oauth2clientのバージョンが新しいため、importすべきものがないよ、みたいなwarningが大量にでてきてしまいました14:
2017-10-20 14:35:37,819 - WARNING - line 44 - googleapiclient.discovery_cache - __init__.py -
*** file_cache is unavailable when using oauth2client >= 4.0.0
Traceback (most recent call last):
File "/Users/knknkn/Documents/test/venv/lib/python3.6/site-packages/googleapiclient/discovery_cache/__init__.py", line 36, in autodetect
from google.appengine.api import memcache
ModuleNotFoundError: No module named 'google'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/knknkn/Documents/test/venv/lib/python3.6/site-packages/googleapiclient/discovery_cache/file_cache.py", line 33, in <module>
from oauth2client.contrib.locked_file import LockedFile
ModuleNotFoundError: No module named 'oauth2client.contrib.locked_file'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/knknkn/Documents/test/venv/lib/python3.6/site-packages/googleapiclient/discovery_cache/file_cache.py", line 37, in <module>
from oauth2client.locked_file import LockedFile
ModuleNotFoundError: No module named 'oauth2client.locked_file'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/knknkn/Documents/test/venv/lib/python3.6/site-packages/googleapiclient/discovery_cache/__init__.py", line 41, in autodetect
from . import file_cache
File "/Users/knknkn/Documents/test/venv/lib/python3.6/site-packages/googleapiclient/discovery_cache/file_cache.py", line 41, in <module>
'file_cache is unavailable when using oauth2client >= 4.0.0')
ImportError: file_cache is unavailable when using oauth2client >= 4.0.0
2017-10-20 14:35:37,821 - INFO - line 274 - googleapiclient.discovery - discovery.py -
*** URL being requested: GET https://www.googleapis.com/discovery/v1/apis/analytics/v3/rest
ちなみに、tracebackの情報もlogとともに出されるのは、googleapiclientのコードのこの部分にあるようにlogging.info/debugメソッドのexc_infoオプションをTrueにしているからです15。
このimportの警告文はgoogleapiclient.discovery_cacheに起因しているみたいなので、これだけを抑制したいときは、ユーザー側で以下のように指定すれば良いです(基本の使い方 > ユーザー側 > loggingを抑制したいを参照のこと)：
import logging
logging.basicConfig(format="%(asctime)s - %(levelname)s - line %(lineno)d - %(name)s - %(filename)s - \n*** %(message)s") # defaultはlevel=logging.DEBUG)
logging.getLogger("googleapiclient.discovery_cache").setLevel(level=logging.ERROR) # ImportErrorがおびただしく出てくるので、ここのlogは不要
logging.getLogger("googleapiclient.discovery").setLevel(level=logging.DEBUG) # このログは出してほしい
まとめ
loggingに関しては、基本の書き方に沿って書けば大丈夫です。
参考
- https://www.python.org/dev/peps/pep-0282/ PEP282のdocument
- http://docs.python-guide.org/en/latest/writing/logging/ .. loggingのhow-to. かなりわかりやすいです。
- https://docs.python.jp/3/howto/logging-cookbook.html .. loggingのレシピ(公式)
- https://docs.python.jp/3/howto/logging.html .. こっちは文法寄りの説明(公式)
補足
本編で拾えなかったところを書き書きしてます。
logging.getLoggerの第一引数 について
getLoggerの第一引数はloggerにつける識別子で普通はモジュール名を入れます。なので、モジュールごとにlogger = logging.getLogger(__name__)を書く感じです(__name__はモジュールの名前を表します)。
つまり、(回りくどい言い方しないで)、何が言いたかったかというと、クラスレベルでloggerの識別をすることは普通はしないということです。
一応、やろうと思えば実現できて、
class Hoge():
@classmethod
def get_logger(cls):
return logging.getLogger("{}.{}".format(__name__, cls.__name__))
def __init__(self):
pass
def do(self):
# do sth
# おもに問題を診断するときにのみ関心があるような、詳細な情報。
self.get_logger().debug("hoge_test")
という感じで書けますけど、普通はmodule単位でログを出す感じですね..
-
殊loggingに関してそうなってしまうのは、どうしてなんでしょうか？ ↩
-
https://docs.python.jp/3/howto/logging.html#when-to-use-logging のレベル - いつ使うかの対応表にdebug, info, warningの使い分けについて書いてあります。 ↩
-
最後の補足に、getLoggerの引数についてちょこっと書きました。 ↩
-
https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library のNoteに書いてある。後述するrequestsライブラリもこの書き方を踏襲しています。 ↩
-
これら、ユーザー側の使い方については、https://docs.python.jp/3/howto/logging-cookbook.html を参照しました。 ↩
-
https://docs.python.jp/3/library/logging.html#logging.basicConfig にあるように、basicConfigを最初に呼び出す必要があります。ちなみに、basicConfigの戻り値はないです。 ↩
-
https://docs.python.jp/3/howto/logging-cookbook.html#logging-to-multiple-destinations を参考のこと ↩
-
実行するたびにlogが新規上書きされたら、そもそもlogとる意義ないですよね、という意味。 ↩
-
ここのところ、自然言語処理することが多かったので。 ↩
-
2017/10/19現在での最新のdevelopブランチのコードです ↩
-
これは正確でなく、実際には、https://github.com/requests/requests/blob/8c4f78448ab150f336026aa5c74d875c8ad59895/requests/__init__.py#L124-L133 のように、
logging.getLogger(__name__).addHandler(logging.NullHandler())という風にしています。NullHandlerは、ロギング設定がなされていないときにメッセージを表示させないときに用います。詳しくは、https://docs.python.jp/3/howto/logging.html#configuring-logging-for-a-library を見ると良いです。 ↩ -
http://docs.python-requests.org/en/master/api/#api-changes のlogの部分を参照した ↩
-
それ、DEBUG levelで出してよ〜、というやつです ↩
-
一部logの内容を編集してます。python3.6.1、
google-api-python-client==1.6.4です。ちなみに、余談になりますが、ModuleNotFoundErrorと言うのはpython3.6で新しく登場したImportErrorのサブクラスです( https://docs.python.org/ja/3.6/library/exceptions.html#ModuleNotFoundError 参照) python3.5以前で実行すると、ImportErrorが送出されます。 ↩ -
https://docs.python.jp/3/library/logging.html#logging.debug にも、exc_info オプションを取れるよ~ と書いてあります。https://qiita.com/podhmo/items/6ee3ae0929765e929c83 も参考になる。 ↩