logging入門

# logging入門

## はじめに

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


### 対象者

+ ライブラリを作成するのに、loggingを活用したい人

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

### 本記事の特長

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

[^logging]: 殊loggingに関してそうなってしまうのは、どうしてなんでしょうか？

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

## 基本の使い方

原点に立ち返るという意味で、loggingのことが書いてある[PEP282](https://www.python.org/dev/peps/pep-0282/)に基づいて説明します。

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

[^level]: https://docs.python.jp/3/howto/logging.html#when-to-use-logging のレベル - いつ使うかの対応表にdebug, info, warningの使い分けについて書いてあります。

### ライブラリ側

ライブラリ側では、先頭に`logger = logging.getLogger(__name__)`を指定して[^logger-name]、loggingしたい場所に`logger.debug(msg)`みたいなふうに書くだけです。(`__name__`は、ライブラリのモジュールの名前です。詳しくは、[インポート関連のモジュール属性](https://docs.python.jp/3/reference/import.html?highlight=__name__#__name__) を参照のこと)。
細かな出力方法はユーザー側で設定するので、それ以外のコーディングは必要ないです[^logger-library]。

[^logger-library]: https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library のNoteに書いてある。後述するrequestsライブラリもこの書き方を踏襲しています。

[^logger-name]: 最後の補足に、getLoggerの引数についてちょこっと書きました。

```python: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のパターンについて見ていきます[^cookbook]。

[^cookbook]: これら、ユーザー側の使い方については、https://docs.python.jp/3/howto/logging-cookbook.html を参照しました。

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

```txt:ライブラリの構造(例)
repo_name
  │ 
  ├── my_pac
  │   ├── __init__.py
  │   ├── mod01.py
  │   ├── mod02.py
  │   └── mod03.py
  ├──  setup.py
  ├──  README.md
  └── .gitignore
```

---

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

```python: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`のものも出力してくれます)[^basicConfig]

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

[^basicConfig]: https://docs.python.jp/3/library/logging.html#logging.basicConfig にあるように、basicConfigを最初に呼び出す必要があります。ちなみに、basicConfigの戻り値はないです。

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

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

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

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


[^cookbook_log_file]: https://docs.python.jp/3/howto/logging-cookbook.html#logging-to-multiple-destinations を参考のこと

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

[^append]: 実行するたびにlogが新規上書きされたら、そもそもlogとる意義ないですよね、という意味。

---

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

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

## 例

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

### gensim.word2vec

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

[^data_science]: ここのところ、自然言語処理することが多かったので。

[^date]: 2017/10/19現在での最新のdevelopブランチのコードです

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

例えばですが、[128行目](https://github.com/RaRe-Technologies/gensim/blob/e92b45d3f83ad670da9cf6ae20ae86a2a1c8558c/gensim/models/word2vec.py#L128) で`logger = logging.getLogger(__name__)`を作っていて、
必要なところに、`info`とか`debug`とか挟んでいます(例えば、[504-507行目](https://github.com/RaRe-Technologies/gensim/blob/e92b45d3f83ad670da9cf6ae20ae86a2a1c8558c/gensim/models/word2vec.py#L504-L507))
user側(`__main__`部)がどのように実装されているかというと、[1720-1722行目](https://github.com/RaRe-Technologies/gensim/blob/e92b45d3f83ad670da9cf6ae20ae86a2a1c8558c/gensim/models/word2vec.py#L1720-L1722) にこんな感じで実装されていて、上記で述べたloggingの使い方と合致してます。


### requests

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

[^request-null]: これは正確でなく、実際には、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 を見ると良いです。

```python: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に詳細な情報を出力してくれるようにしているみたいで[^request_logging]、

```python: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/')
```

とすることで、


```log: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モジュールで管理できないので、どうかな？というのはあります)

[^request_logging]: http://docs.python-requests.org/en/master/api/#api-changes のlogの部分を参照した 


### google-api-python-client

続いては、[google-api-python-client](https://github.com/google/google-api-python-client)です。こちらは
INFOレベル以上のログ出力を指定してもログが結構大量に出てきてしまう、logging的には始末が悪いライブラリです[^google_debug]。

[^google_debug]: それ、DEBUG levelで出してよ〜、というやつです


```python: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が大量にでてきてしまいました[^format]:

[^format]: 一部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が送出されます。

```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のコードのこの部分](https://github.com/google/google-api-python-client/blob/36d4e1b4bb9378821a116cd8cd86126522d4b839/googleapiclient/discovery_cache/__init__.py#L44)にあるように`logging.info/debug`メソッドの`exc_info`オプションを`True`にしているからです[^exc-info]。

[^exc-info]: https://docs.python.jp/3/library/logging.html#logging.debug にも、exc_info オプションを取れるよ~　と書いてあります。https://qiita.com/podhmo/items/6ee3ae0929765e929c83 も参考になる。

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

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

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

```python: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単位でログを出す感じですね..