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

前提

以下のような「現在時刻:メッセージ」の形式で、ログを標準出力に出力するよう設定したとき、指定した形式通りにログを出力するか検証するテストをpytestで実装しようと思います。

2000-01-02 12:04:05,000: test_message

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

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"は標準出力へのログ出力を設定しています。（詳細は、公式ドキュメント¹やこちらの記事²が参考になるかと思います。）

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

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

結論：pytest-freezegunで時間を固定し、capfdで標準出力を取得する。

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

pip install pytest-freezegun

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

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の以外でも指定可能で、例えば、以下のように文字列で指定も可能です。

@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()の値が使用⁵されます。そのため、現在時刻の検証の際には、何らかの方法でローカルタイムを取得、利用する必要があります。(test_warn_logではdateutil.gettzを利用。)

また、こちらも仕様で、asctimeはデフォルトで、'%Y-%m-%d %H:%M:%S,%f（例：2000-01-02 12:04:05,000）の形式となっており、検証の際はミリ秒まで指定する必要があります。test_warn_logでは、こちら⁶を参考にして、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/ ↩