pytestで現在時刻を含むlogのテストをする。

# 前提
以下のような「**現在時刻:メッセージ**」の形式で、ログを標準出力に出力するよう設定したとき、**指定した形式通りにログを出力するか検証するテストをpytestで実装**しようと思います。
```
2000-01-02 12:04:05,000: test_message
```

例えば、以下の関数`warn_log`を考えます。

```python:warn_log
def warn_log(): 

    log_dict = {
        "version": 1,
        "disable_existing_loggers": False,
        "formatters": {
            "simple": {
                "format": "%(asctime)s: %(message)s"
            }
        },

        "handlers": {
            "consoleHandler": {
                "class": "logging.StreamHandler",
                "level": "INFO",
                "formatter": "simple",
                "stream": "ext://sys.stdout"
            }
        },

        "loggers": {
            "test": {
                "level": "DEBUG",
                "handlers": ["consoleHandler"],
                "propagate": False
            }
        },
    }
    config.dictConfig(log_dict) 
    logger = getLogger("test")
    logger.warn("test_message")
```


`"format": "%(asctime)s: %(message)s"`でログメッセージのフォーマットを指定しており、`asctime`が現在時刻を示します。
また、`"consoleHandler"`の`"stream": "ext://sys.stdout"`は標準出力へのログ出力を設定しています。（詳細は、公式ドキュメント[^1]やこちらの記事[^2]が参考になるかと思います。）

pytestでログをテストする際、`caplog`をよく利用し、特に、`caplog.records`によって、`asctime`を含む出力ログのLogRecord属性を取得できますが、今回のケースのように指定したフォーマット通りに出力するかの検証には利用しづらいです。

また、**ログメッセージに現在時刻を含む**ため、ただ、出力内容を比較するようなテストでは、実行する時刻によって、検証結果が変わってしまいます。

# 結論：pytest-freezegunで時間を固定し、capfdで標準出力を取得する。
**capfd**[^3]はpytestの組み込みfixtureであり、**標準出力、標準エラー出力をキャプチャ**し、検証に利用できます。
また、**pytest-freezegun**[^4]:はpytestのプラグインであり、時間を固定し、利用によって、簡単に検証の実行時刻に依存しないテストを作成することができます。
なお、pytest-freezegunは以下のように、追加でinstallする必要があります。
```
pip install pytest-freezegun
```

具体的に、関数`warn_log`のテストコード`test_warn_log`を以下に示します。
以下、コードについて、3点に分けて、順に説明していきます。
```python
import pytest
import datetime
from dateutil import tz

@pytest.mark.freeze_time(datetime.datetime(2000, 1, 2, 3, 4, 5))
def test_warn_log(capfd):
    
    # テスト対象の関数
    warn_log()
    
    # キャプチャした標準出力の取得
    stdout, _ = capfd.readouterr()
    stdout_list = stdout.split("\n")
    
    # 検証
    assert stdout_list[0] == f"{datetime.datetime.now(tz.gettz('Asia/Tokyo')).strftime('%Y-%m-%d %H:%M:%S,%f')[:-3]}: test_message"
```

## ①@pytest.mark.freeze_timeで現在時刻を固定
テスト関数のデコレータとして、`@pytest.mark.freeze_time`を指定することで、現在時刻を固定できます。上記の`test_warn_log`では、現在時刻を2000年1月2日3時4分5秒（UTC）に固定しています。
なお、現在時刻は`datatime`の以外でも指定可能で、例えば、以下のように文字列で指定も可能です。
```python
@pytest.mark.freeze_time('2000-01-02 03:04:05')
```

## ②capfd.readouterr()で標準出力を取得
`capfd.readouterr()`は、第一戻り値として、キャプチャした標準出力を、第二戻り値として、標準エラー出力を取得できます。（今回は標準エラー出力は利用しないため、`_`を指定しています。）
注意点としては、**改行コードを含んだ状態で標準出力を取得**するため、検証での利用の際は改行コードに対応するようなテストコードにする必要があります。(`test_warn_log`では`split("\n")`で対応。)

## ③asctimeの検証の際は、ローカルタイムを利用&時刻はミリ秒まで指定
`@pytest.mark.freeze_time`では、UTCで現在時刻を固定しましたが、一方で、pythonのloggerの仕様で、`asctime`にはデフォルトで、`time.localtime()`の値が使用[^5]されます。そのため、**現在時刻の検証の際には、何らかの方法でローカルタイムを取得、利用する**必要があります。(`test_warn_log`では`dateutil.gettz`を利用。)

また、こちらも仕様で、`asctime`はデフォルトで、`'%Y-%m-%d %H:%M:%S,%f`（例：2000-01-02 12:04:05,000）の形式となっており、**検証の際はミリ秒まで指定する**必要があります。`test_warn_log`では、こちら[^6]を参考にして、`strftime`を利用して、現在時刻のミリ秒指定を実現しています。

[^1]: https://docs.python.org/ja/3/library/logging.html#logrecord-attributes
[^2]: https://qiita.com/FukuharaYohei/items/92795107032c8c0bfd19
[^3]: https://docs.pytest.org/en/latest/reference/reference.html#capfd
[^4]: https://github.com/ktosiek/pytest-freezegun 
[^5]: https://docs.python.org/2/library/logging.html#formatter-objects
[^6]: https://www.delftstack.com/ja/howto/python/python-datetime-milliseconds/