pythonのlogger奮闘記 ～簡単な使い方から複数ファイルを跨る使い方まで～

# はじめに
pythonのloggerを使ってログ出力をキレイにやりたいなー、と思って調べたら難しかった。
でも実際に使ってみると、何とかなった。

なのでこれからloggerを使う方向けに大雑把に理解した使い方を、サンプルと共に書き連ねます。
もっとよい使い方を知りたいのでツッコミ大歓迎です。

# 前提知識

* logging…loggerの大本。これをいじると影響範囲が広すぎるので使わない。
* logger…loggingの子分。1つのを使いまわす、子供も作る、複数作るなど使いやすいので基本的にこれを使う。
* handler…loggerにログの出力先や出力するフォーマットに関係するもの。めっちゃ重要。

# 使い方

基本的には、
(1)ログを管理するloggerを作成
(2)ログ出力を管理するhandlerを作成
(3)任意のhandlerをloggerにセット。
という風に使っていきます。

上手い言葉で説明できるほど理解はしていないので、実際のコードを見せながら解説します。

## ログを標準出力する簡単な使い方

任意のログを標準出力するサンプルです。
単一ファイルなのでJupyter Notebookに貼り付けてそのまま実行することもできます。

```python3:sample.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, Formatter

# --------------------------------
# 1.loggerの設定
# --------------------------------
# loggerオブジェクトの宣言
logger = getLogger("LogTest")

# loggerのログレベル設定(ハンドラに渡すエラーメッセージのレベル)
logger.setLevel(logging.DEBUG)

# --------------------------------
# 2.handlerの設定
# --------------------------------
# handlerの生成
stream_handler = StreamHandler()

# handlerのログレベル設定(ハンドラが出力するエラーメッセージのレベル)
stream_handler.setLevel(logging.DEBUG)

# ログ出力フォーマット設定
handler_format = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
stream_handler.setFormatter(handler_format)

# --------------------------------
# 3.loggerにhandlerをセット
# --------------------------------
logger.addHandler(stream_handler)

# --------------------------------
# ログ出力テスト
# --------------------------------
logger.debug("Hello World!")
```

```:実行例
2018-02-06 19:54:57,547 - LogTest - DEBUG - Hello World!
```

### ログレベルについて

上記例ではログレベルの設定(setLevel)を2回(loggerとhandler)実行しています。
これらは次のような違いがあります。

|setLevel|ログへの影響|
|---|---|
|logger|handlerに渡すログの最低レベルを設定|
|handler|出力するログの最低レベルを設定|

* 参考:https://docs.python.jp/3/howto/logging.html#handlers

上記で設定されたログレベル以上のログが対象になります。
ログレベルの順序は以下の通りです。

* 参考：https://docs.python.jp/3/library/logging.html#logging-levels

そのため次のようにloggerのログレベルがERRORの場合、それより低いhandlerのDEBUGは表示されません。

```python3:sample.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, Formatter

# --------------------------------
# 1.loggerの設定
# --------------------------------
# loggerオブジェクトの宣言
logger = getLogger("LogTest")

# loggerのログレベル設定(ハンドラに渡すエラーメッセージのレベル)
# ERRORを設定したためDEBUGは表示されない
logger.setLevel(logging.ERROR)

# --------------------------------
# 2.handlerの設定
# --------------------------------
# handlerの生成
stream_handler = StreamHandler()

# handlerのログレベル設定(ハンドラが出力するエラーメッセージのレベル)
stream_handler.setLevel(logging.DEBUG)

# ログ出力フォーマット設定
handler_format = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
stream_handler.setFormatter(handler_format)

# --------------------------------
# 3.loggerにhandlerをセット
# --------------------------------
logger.addHandler(stream_handler)

# --------------------------------
# ログ出力テスト
# --------------------------------

# こちらDEBUGなため表示されない
logger.debug("Hello World!")

# こちらはERRORなので表示される
logger.error("こんにちは 世界！")
```

```:実行例
2018-02-06 20:13:34,074 - LogTest - ERROR - こんにちは 世界！
```

loggerには複数のhandlerが設定できるため、ログ全体とhandler毎のエラーレベルを別々に設定できるようになっているのだと思います。


### ログ出力フォーマットについて
「Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')」はログの出力形式です。
pythonでは馴染みが薄い気がしますが、やっていることは%による文字列出力です。
出力される規定のメッセージは以下を参考にしてください。

* 参考：https://docs.python.jp/3/library/logging.html#logrecord-attributes


## 複数ファイルに跨る使い方

身も蓋もないことを言えば、以下の参考通りです。

* 参考：https://docs.python.jp/3/howto/logging-cookbook.html

getLogger("<任意の名前>")を宣言した場合、別々のファイルでも同一のloggerを使用します。
またgetLogger("<任意の名前>.<サブ名>")、getLogger("<任意の名前>")..getChild("<サブ名>")と宣言すれば、親loggerを継承した子loggerが生成されます。

```python3:sample01.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, Formatter

# 別ファイルの参照
import child_sample01

# --------------------------------
# 1.loggerの設定
# --------------------------------
# loggerオブジェクトの宣言
logger = getLogger("LogTest")

# loggerのログレベル設定(ハンドラに渡すエラーメッセージのレベル)
logger.setLevel(logging.DEBUG)

# --------------------------------
# 2.handlerの設定
# --------------------------------
# handlerの生成
stream_handler = StreamHandler()

# handlerのログレベル設定(ハンドラが出力するエラーメッセージのレベル)
stream_handler.setLevel(logging.DEBUG)

# ログ出力フォーマット設定
handler_format = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
stream_handler.setFormatter(handler_format)

# --------------------------------
# 3.loggerにhandlerをセット
# --------------------------------
logger.addHandler(stream_handler)

# --------------------------------
# ログ出力テスト
# --------------------------------

# sample01のログ出力
logger.debug("Hello World!")

# 別ファイルのchild_sample01.pyのログ出力
child_sample01.action()
```

```python3:child_sample01.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, Formatter

# sample01で宣言したloggerの子loggerオブジェクトの宣言
logger = getLogger("LogTest").getChild("sub")

def action():
    logger.debug("Hi!")
```

```:実行例
2018-02-06 20:30:30,680 - LogTest - DEBUG - Hello World!
2018-02-06 20:30:30,681 - LogTest.sub - DEBUG - Hi!
```

見ての通り同一のloggerの親と子を使っているため、同一の出力先にログが吐かれます。
ただしそのままでは、どちらでログが吐かれたか分かりにくいため、「getLogger("LogTest").getChild("sub")」と宣言することで、child_sample01.pyをわかりやすくしています。

### ログの出力先を別ファイルで定義したい

loggerが複数ファイルに跨がれることを利用して、ログ設定を別ファイルで実施可能です。

```python3:sample02.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, Formatter

# 別ファイルの参照
import conf_sample02

# loggerオブジェクトの宣言
# loggerの設定は別ファイルで実施
logger = getLogger("LogTest")

# --------------------------------
# ログ出力テスト
# --------------------------------

# loggerが未設定なため出力されない
logger.debug("Hello World!")

# 別ファイルのconf_sample02.pyによるloggerの設定を実施
conf_sample02.action()

# loggerが設定されたため出力される
logger.debug("こんにちは 世界！")
```

```python3:conf_sample02.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, Formatter

# sample01で宣言したloggerの子loggerオブジェクトの宣言
logger = getLogger("LogTest").getChild("sub")


def action():
    # --------------------------------
    # 1.loggerの設定
    # --------------------------------
    # 親loggerのログレベル設定(ハンドラに渡すエラーメッセージのレベル)
    logger.parent.setLevel(logging.DEBUG)

    # --------------------------------
    # 2.handlerの設定
    # --------------------------------
    # handlerの生成
    stream_handler = StreamHandler()

    # handlerのログレベル設定(ハンドラが出力するエラーメッセージのレベル)
    stream_handler.setLevel(logging.DEBUG)

    # ログ出力フォーマット設定
    handler_format = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    stream_handler.setFormatter(handler_format)

    # --------------------------------
    # 3.loggerにhandlerをセット
    # --------------------------------
    # 親loggerにhandlerをセット
    logger.parent.addHandler(stream_handler)

    # --------------------------------
    # ログ出力テスト
    # --------------------------------

    # 子loggerとしてログ出力
    logger.debug("logger conf complete!")
```

```:実行例
2018-02-06 20:47:16,784 - LogTest.sub - DEBUG - logger conf complete!
2018-02-06 20:47:16,784 - LogTest - DEBUG - こんにちは 世界！
```

今回、conf_sample02.pyは子loggerを宣言しています。
そのためsample02.pyで使用している親loggerへ設定を反映するために、「.parent」を利用していいます。
これにより子loggerを宣言した側でも親loggerの設定が可能です。
(親loggerの設定は子loggerに引き継がれますが、子loggerのみにした設定は親には当然引き継がれません)


## 出力先を複数設定

handlerを複数設定することで、同一のログを複数の出力先に吐き出せます。
今回は標準出力と、テキストファイルの2つにログを吐かせてみます。

```python3:sample03.py
# coding:utf-8

# ログのライブラリ
import logging
from logging import getLogger, StreamHandler, FileHandler, Formatter

# --------------------------------
# 1.loggerの設定
# --------------------------------
# loggerオブジェクトの宣言
logger = getLogger("LogTest")

# loggerのログレベル設定(ハンドラに渡すエラーメッセージのレベル)
logger.setLevel(logging.DEBUG)

# --------------------------------
# 2.handlerの設定
# --------------------------------
# ログ出力フォーマット設定
handler_format = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# ---- 2-1.標準出力のhandler ----
# handlerの生成
stream_handler = StreamHandler()

# handlerのログレベル設定(ハンドラが出力するエラーメッセージのレベル)
stream_handler.setLevel(logging.DEBUG)

# ログ出力フォーマット設定
stream_handler.setFormatter(handler_format)

# ---- 2-2.テキスト出力のhandler ----
# handlerの生成
file_handler = FileHandler('sample03.log', 'a')

# handlerのログレベル設定(ハンドラが出力するエラーメッセージのレベル)
file_handler.setLevel(logging.DEBUG)

# ログ出力フォーマット設定
file_handler.setFormatter(handler_format)

# --------------------------------
# 3.loggerにhandlerをセット
# --------------------------------
# 標準出力のhandlerをセット
logger.addHandler(stream_handler)
# テキスト出力のhandlerをセット
logger.addHandler(file_handler)

# --------------------------------
# ログ出力テスト
# --------------------------------
logger.debug("Hello World!")
```

```:実行例
2018-02-06 20:55:02,425 - LogTest - DEBUG - Hello World!
```

```text:sample03.log
2018-02-06 20:55:02,425 - LogTest - DEBUG - Hello World!
```

上記の通り同じログを別々の出力先で確認できます。
利用できる出力先については以下を参照ください。

* 参考：https://docs.python.jp/3/howto/logging.html#useful-handlers