support sub-second granularity/precision in --log-date-format (strftime %f)

[jtmoon79]

tl;dr pytest processing strftime %f specifier from --log-*-date-format arguments would allow me to accurately merge log messages from disparate sub-systems

What's the problem?

Tests I run have pytest log messages that print at the second granularity for the datetimestamp, e.g. 2023-05-11T13:45:34. At the same time, other log file messages not generated by pytest print sub-second datetimestamps, e.g. 2023-05-11T13:45:34.123.

When reviewing the various logs, there are many message from other system components that are printing many log messages per second. Because pytest log messages are lacking sub-second precision, I am unable to align pytest log messages within other system log messages.

contrived example

For example, the system-under-test generates a log file like:

2023-05-11T13:45:34.001 starting the frobulator
2023-05-11T13:45:34.100 wiggling the waggulator
2023-05-11T13:45:34.200 stopping the frobulator
2023-05-11T13:45:34.301 starting the frobulator
2023-05-11T13:45:34.400 poking the prokulator
2023-05-11T13:45:34.450 prokulator response ERROR_NOT_ONLINE
2023-05-11T13:45:34.500 stopping the frobulator
2023-05-11T13:45:34.600 starting the frobulator
2023-05-11T13:45:34.700 juggling some bowling pins
2023-05-11T13:45:34.750 DROPPED A PIN!
2023-05-11T13:45:34.800 stopping the frobulator
2023-05-11T13:45:34.839 ERROR 0x0F009001 STOPPING THE frobulator

and the driver of tests, pytest, generates a log file like:

2023-05-11T13:45:34 checking device
2023-05-11T13:45:34 ping device
2023-05-11T13:45:34 device error!

The pytest log messages cannot be precisely ordered among the other log messages that occurred during the datetime second 2023-05-11T13:45:34, there were many things that occurred in the other system components within that second.

current confusion

Given the following pytest code

import logging
import pytest

logging.basicConfig()
logger = logging.getLogger(__name__)

def test_logger():
    logger.error("test_logger()ERROR")
    logger.warning("test_logger()WARNING")

To add sub-second granularity, it seems sensible to add %f within the --log-cli-date-format

$ python -m pytest \
         -v -v \
         --log-cli-date-format="%Y%m%dT%H%M%S.%f" \
         --capture=tee-sys \
         -k "test_logger"

but then I see the confusing output of

20230511T181007.%f: ERROR : [test_main.py:27 - test_logger()] : test_logger()ERROR
20230511T181007.%f: WARNING : [test_main.py:28 - test_logger()] : test_logger()WARNING

pytest logging is ignoring the strftime %f specifier!

---

pytest feature request

I want pytest log messages to print sub-second granularity, e.g. process strftime %f within --log-date-format="...%f..." settings.

Describe the solution you'd like

Support strftime %f specifier in the various settings for date-format, e.g. --log-date-format, --log-cli-date-format, --log-file-date-format.

In my complex testing system, this means all log messages would be printed to millisecond precision. This allows engineers investigating issues to more accurately merge disparate testing system logs by their natural ordering mechanism of a datetimestamp.

---

Alternative Solutions

I can set the logging format to include %(msecs)03d.
However, it's a little confusing to have to manipulate log datetimestamps by two different mechanisms, --log-cli-format and --log-cli-date-format.

example workaround

On the command-line run:

$ python -m pytest \
         -v -v \
         --log-cli-date-format="%Y%m%dT%H%M%S." \
         --log-cli-format="%(asctime)s%(msecs)03d: %(levelname)s : [%(filename)s:%(lineno)s - %(funcName)s()] : %(message)s" \
         --capture=tee-sys \
         -k "test_logger"

This prints datetimestamps with millisecond precision

20230511T180748.192: ERROR : [test_main.py:27 - test_logger()] : test_logger()ERROR
20230511T180748.195: WARNING : [test_main.py:28 - test_logger()] : test_logger()WARNING

Summary

It is more intuitive for pytest to process the Python strftime %f specifier within all --*-date-format options.

[jtmoon79]

Wow, fantastic! Looking forward to this release! Thanks everyone! @Zac-HD @theirix @nicoddemus