Pythonのロギングを覚えた

# いつも忘れてしまうので・・・

簡単なスクリプトを書くときでも、きちんと``logging``しておくとあとあと便利だと思うのですが、いつもやり方を忘れてしまいます。
なので、[Loggingクックブック](https://docs.python.org/ja/3/howto/logging-cookbook.html#logging-cookbook)を参考に、ロガー作成の要素を整理してみました。また、毎回ファイルの冒頭に同じことを書くのもアレなので、``setup_logger``という関数にしました

```python:loggerを初期化する関数
def setup_logger(name, logfile='LOGFILENAME.txt'):
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)

    # create file handler which logs even DEBUG messages
    fh = logging.FileHandler(logfile)
    fh.setLevel(logging.DEBUG)
    fh_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')
    fh.setFormatter(fh_formatter)

    # create console handler with a INFO log level
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    ch_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')
    ch.setFormatter(ch_formatter)

    # add the handlers to the logger
    logger.addHandler(fh)
    logger.addHandler(ch)
    return logger
```

```python:使い方
# 各モジュールの最初のほうで、グローバルに宣言しておく
logger = setup_logger(__name__)
```

## ロガー作成のポイント

自分なりに理解したポイントは以下の3点。

1. ``logging``というルートにあるロガーではなく、``getLogger``して個別のを作るほうがよい
2. ``logger``全体のレベルを設定（とりあえず``DEBUG``に設定）
3. ``logger``にハンドラーを追加する

この3つの手順を覚えておき、あとは必要なハンドラ（``logging.handlers``）を設定し追加していくだけです。おぉ、整理してみると簡単！。

```python:loggerを作成している部分
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    ...
    logger.addHandler(fh)
    logger.addHandler(ch)
```

## ハンドラ作成のポイント

ハンドラ作成時のポイントは以下の3点。

1. ハンドラを選ぶ : [logging.handlers](https://docs.python.org/ja/3/library/logging.handlers.html) から自分に必要なものを探す
1. ハンドラのログレベルを設定する : ログレベルとその使い時は、[基本ロギングチュートリアル](https://docs.python.org/ja/3/howto/logging.html#basic-logging-tutorial)を参照
- ハンドラの``formatter``を設定する : ``logging.Formatter``を使う

ログに表示する内容のテンプレートの詳細な設定は [フォーマッタオブジェクト](https://docs.python.org/ja/3/library/logging.html#formatter-objects)を読むとよいでしょう。
テンプレートに使える変数は[LogRecord属性](https://docs.python.org/ja/3/library/logging.html#logrecord-attributes)の表から選びます。
また、2つめの引数に日付フォーマット（``datefmt``）を指定できることも知っておくと便利。

今回は、ファイル用のログ出力は冗長にし、コンソール用のログ出力はシンプルにしたかったので、それぞれ別のフォーマッタを設定しました。

```python:ハンドラを作成している部分
    # create file handler which logs even DEBUG messages
    fh = logging.FileHandler(logfile)
    fh.setLevel(logging.DEBUG)
    fh_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')
    fh.setFormatter(fh_formatter)

    # create console handler with a INFO log level
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    ch_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')
    ch.setFormatter(ch_formatter)
```

## ログの出力結果

実際のログ出力を載せておきます。

```bash:ログファイルへの出力

## Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')

2019-06-03 11:12:38,692 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 16 - 1.82 MB
2019-06-03 11:12:40,860 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 17 - 1.82 MB
2019-06-03 11:12:42,832 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 18 - 1.82 MB
2019-06-03 11:12:45,220 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 19 - 1.82 MB
2019-06-03 11:12:47,006 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 20 - 1.82 MB
2019-06-03 11:12:48,396 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 21 - 1.82 MB
2019-06-03 11:12:49,767 - DEBUG - parsers.py - __main__ - parse_chunk - Parsed : Chunk# 22 - 1.82 MB
```

```bash:コンソールへの出力

## Formatter('%(asctime)s - %(levelname)s - %(message)s', '%Y-%m-%d %H:%M:%S')

2019-06-03 11:11:58 - INFO - --------------------------------------------------
2019-06-03 11:11:58 - INFO - In  : data/weblogs/ssl_access_log.20190601.gz
2019-06-03 11:11:58 - INFO - Out : data/parsed/ssl_access_log_20190601.parsed.gz
2019-06-03 11:11:58 - INFO - --------------------------------------------------
2019-06-03 11:11:58 - INFO - Read data/weblogs/ccprod02_ssl_access_log.20190601.gz with chunks (size=10000)
```

# おまけ：ログファイルのローテーション

プログラムを作成＆デバッグしている段階から、そこそこ常用する段階になってくると、（正常時はほとんど確認する必要のない）ログファイルがどんどんと肥大化してしまうのが少し気になっていました。これまでは、気づいたときにログファイルを削除して、プログラムを実行していたのですが、今回、ハンドラについて理解したので、きちんとログファイルをローテーションするように変更しました。

今回は``RotatingFileHandler``を使って``100kB``のファイルを``10個``まで保管するようにしました。

1. ``RotatingFileHandler``は``logging.handlers``の下にあるので``import logging.handlers``を追記
2. ファイル出力用ハンドラ``fh``を``logging.FileHandler``から``logging.handlers.RotatingFileHnadler``に変更
3. ログファイルのサイズを``100kB``（``maxBytes=100000``）に設定
4. ログファイルを保存する数は10個（``backupCount=10``）に設定


```python:ハンドラの種類を変更
import logging.handlers

#fh = logging.FileHandler(logfile)
fh = logging.handlers.RotatingFileHandler(logfile, maxBytes=100000, backupCount=10)
fh.setLevel(logging.DEBUG)
fh_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(filename)s - %(name)s - %(funcName)s - %(message)s')
fh.setFormatter(fh_formatter)
```

下は何回かログを出力させた結果です。
最も新しいのが``log_rotate.txt``で、100kBを目安にファイルがバックアップが作成されていることが確認できました。

```bash:ログローテーションできていることを確認
95K Jun  4 09:45 log_rotate.txt
98K Jun  4 08:26 log_rotate.txt.1
98K Jun  4 09:08 log_rotate.txt.2
98K Jun  3 16:06 log_rotate.txt.3
98K Jun  3 14:49 log_rotate.txt.4
```

# おわりに

よし、これでロギングも怖くない！

# おわりのおまけ

この記事がぽつりぽつりとストック／いいねされているようなので、最近はもっぱら[Loguru](https://loguru.readthedocs.io/en/stable/index.html)を使っていることを追記しておきます。（2023/06/22）

```python
from loguru import logger

logger.debug("これだけでいいかんじ！")
```

この記事の設定は``from loguru import logger``のたった一行にほぼ置き換えられるくらい簡単で便利なパッケージです。ありがたや✨



# 参考ページ

1. [logging --- Python用ロギング機能](https://docs.python.org/ja/3/library/logging.html)
2. [Loggingクックブック](https://docs.python.org/ja/3/howto/logging-cookbook.html)
3. [Logging HOWTO](https://docs.python.org/ja/3/howto/logging.html)