logging入門

はじめに

Pythonのloggingについて検索すると、qiitaの記事だとhttps://qiita.com/amedama/items/b856b2f30c2f38665701 が上位にくるんですが、正直わかりにくくなっているだけだと思います。本記事では、基本の使い方と、実際の有名所のライブラリのloggingの活用例(3つ)の2部構成で説明していきたいです。

対象者

ライブラリを作成するのに、loggingを活用したい人
そろそろprintデバッグやめたいけど、loggingの玉石混交の解説を見て、半ば諦め気味の人. どれが本当に正しい説明なのか、あんまり良くわかってない人

本記事の特長

いろんなブログの説明や記事を見ると、オレオレ視点でこうしよう、みたいに書かれている内容のものが多すぎる¹ので、可能な限り公式の引用元を明示した。

本記事の「基本の使い方」の説明をカバーするために、有名所の外部ライブラリ(gensim.word2vec, requests, google-api-python-client)が実際どのようにloggingを使っているかと、これらのライブラリのloggingを使用者側(ユーザー側)がどのように扱えばよいかを書いた。

基本の使い方

原点に立ち返るという意味で、loggingのことが書いてあるPEP282に基づいて説明します。

まず、ライブラリ側とそれを使う側(ユーザー側)でloggingの書き方が違います。ここをごっちゃにすると、話が絶対に錯綜するので、必ず意識するようにします。
ライブラリ側では、module毎にloggerを定義しておいて、logとして出したい情報に関して、debug, info, (warning)等を使い分けます²：

ライブラリ側

ライブラリ側では、先頭にlogger = logging.getLogger(__name__)を指定して³、loggingしたい場所にlogger.debug(msg)みたいなふうに書くだけです。(__name__は、ライブラリのモジュールの名前です。詳しくは、インポート関連のモジュール属性を参照のこと)。
細かな出力方法はユーザー側で設定するので、それ以外のコーディングは必要ないです⁴。

mod.py

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のパターンについて見ていきます⁵。

説明のために、こんなようなライブラリ構造を想定します。

ライブラリの構造(例)

repo_name
  │ 
  ├── my_pac
  │   ├── __init__.py
  │   ├── mod01.py
  │   ├── mod02.py
  │   └── mod03.py
  ├──  setup.py
  ├──  README.md
  └── .gitignore

my_pacのmod01のみに絞ってsys.stderrにlogを出す場合

test.pyやtest.ipynbなど

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のものも出力してくれます)⁶

念の為ですが、from my_pac import mod01してようがしてまいが、my_pac.mod01という風に、パッケージ名を省略せずに書いてください。

複数のモジュール(この場合は、my_pacのmod01, mod02)に対して、logを出したい

test.pyやtest.ipynbなど

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を出したい

test.pyやtest.ipynbなど

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にあげる)

test.pyやtest.ipynbなど

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の設定をする必要があるということです⁷。sys.stderrのloggerの設定はその後に個別で対応します。

test.pyやtest.ipynbなど

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の性質上当たり前⁸なのですが、open関数とかのmodeのデフォルト値と違っているので、ちょっとだけ注意です。

よく使うのは、こんなかんじですかね？

追記) ライブラリ側とユーザー側が1ファイルにまとまっている場合、つまり、if __name__ == "__main__":以下でスクリプトとして実行する場合も考え方は同じです。詳しくは、
https://gist.github.com/podhmo/7fcc1024dec64b42074c3d3d5c789f98
をみてください。

例

ここでは、有名なライブラリがどのようにloggingを使っているかと、どのようにこれらのlogを扱えばよいのかを解説します。
普通のやつ、loggingがないやつ、めんどくさいやつの3つ紹介します

gensim.word2vec

まずは普通のやつから。自分がそれなりに使用している外部のlibraryでどんなふうにloggingが使われているか見ます。
gensim自体は巨大なライブラリ群になっているので、今回はword2vec.pyのコードを参照したいと思います⁹！
=> https://github.com/RaRe-Technologies/gensim/blob/e92b45d3f83ad670da9cf6ae20ae86a2a1c8558c/gensim/models/word2vec.py ¹⁰

githubのリンク貼ってあるので、気になったら飛んでくださいね

例えばですが、128行目でlogger = logging.getLogger(__name__)を作っていて、
必要なところに、infoとかdebugとか挟んでいます(例えば、504-507行目)
user側(__main__部)がどのように実装されているかというと、1720-1722行目にこんな感じで実装されていて、上記で述べたloggingの使い方と合致してます。

requests

お次は、みんな一度は使用したことがあるであろうrequestsライブラリ。これは、公式のurllib3のラッパーです。
requests本体には、loggingは含まれていません¹¹。なので、logging.getLogger("requests").setLevel(level=logging.DEBUG)と書いても何も起こりません。urllib3由来のlogを吐き出したい場合は、以下の設定をユーザー側で行います。

test.pyやtest.ipynbなど

import logging
logging.basicConfig()
logging.getLogger("urllib3").setLevel(level=logging.DEBUG)

# put in your code!
import requests
r = requests.get('http://google.com/')

を実行することで、

sys.stderr

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に詳細な情報を出力してくれるようにしているみたいで¹²、

test.pyやtest.ipynbなど

# 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/')

とすることで、

sys.stdout

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的には始末が悪いライブラリです¹³。

test.pyやtest.ipynbなど

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が大量にでてきてしまいました¹⁴:

sys.stderr

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にしているからです¹⁵。

このimportの警告文はgoogleapiclient.discovery_cacheに起因しているみたいなので、これだけを抑制したいときは、ユーザー側で以下のように指定すれば良いです(基本の使い方 > ユーザー側 > loggingを抑制したいを参照のこと)：

test.pyやtest.ipynbなど

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の識別をすることは普通はしないということです。

一応、やろうと思えば実現できて、

mod.py

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 も参考になる。 ↩