Handle microseconds with custom logging.Formatter (#11047)

Added handling of %f directive to print microseconds in log format options, such as log-date-format. It is impossible to do with a standard logging.Formatter because it uses time.strftime which doesn't know about milliseconds and %f. In this PR I added a custom Formatter which converts LogRecord to a datetime.datetime object and formats it with %f flag. This behaviour is enabled only if a microsecond flag is specified in a format string.

Also added a few tests to check the standard and changed behavior.

Closes #10991

AUTHORS

@@ -131,6 +131,7 @@ Eric Siegerman
 Erik Aronesty
 Erik M. Bray
 Evan Kepner
+Evgeny Seliverstov
 Fabien Zarifian
 Fabio Zadrozny
 Felix Hofstätter

changelog/10991.improvement.rst

@@ -0,0 +1 @@
+Added handling of ``%f`` directive to print microseconds in log format options, such as ``log-date-format``.

src/_pytest/logging.py

@@ -5,7 +5,11 @@ import os
 import re
 from contextlib import contextmanager
 from contextlib import nullcontext
+from datetime import datetime
+from datetime import timedelta
+from datetime import timezone
 from io import StringIO
+from logging import LogRecord
 from pathlib import Path
 from typing import AbstractSet
 from typing import Dict
@@ -53,7 +57,25 @@ def _remove_ansi_escape_sequences(text: str) -> str:
     return _ANSI_ESCAPE_SEQ.sub("", text)
 
 
-class ColoredLevelFormatter(logging.Formatter):
+class DatetimeFormatter(logging.Formatter):
+    """A logging formatter which formats record with
+    :func:`datetime.datetime.strftime` formatter instead of
+    :func:`time.strftime` in case of microseconds in format string.
+    """
+
+    def formatTime(self, record: LogRecord, datefmt=None) -> str:
+        if datefmt and "%f" in datefmt:
+            ct = self.converter(record.created)
+            tz = timezone(timedelta(seconds=ct.tm_gmtoff), ct.tm_zone)
+            # Construct `datetime.datetime` object from `struct_time`
+            # and msecs information from `record`
+            dt = datetime(*ct[0:6], microsecond=round(record.msecs * 1000), tzinfo=tz)
+            return dt.strftime(datefmt)
+        # Use `logging.Formatter` for non-microsecond formats
+        return super().formatTime(record, datefmt)
+
+
+class ColoredLevelFormatter(DatetimeFormatter):
     """A logging formatter which colorizes the %(levelname)..s part of the
     log format passed to __init__."""
 
@@ -625,7 +647,7 @@ class LoggingPlugin:
             config, "log_file_date_format", "log_date_format"
         )
 
-        log_file_formatter = logging.Formatter(
+        log_file_formatter = DatetimeFormatter(
             log_file_format, datefmt=log_file_date_format
         )
         self.log_file_handler.setFormatter(log_file_formatter)
@@ -669,7 +691,7 @@ class LoggingPlugin:
                 create_terminal_writer(self._config), log_format, log_date_format
             )
         else:
-            formatter = logging.Formatter(log_format, log_date_format)
+            formatter = DatetimeFormatter(log_format, log_date_format)
 
         formatter._style = PercentStyleMultiline(
             formatter._style._fmt, auto_indent=auto_indent

testing/logging/test_reporting.py

@@ -1234,3 +1234,100 @@ def test_log_disabling_works_with_log_cli(pytester: Pytester) -> None:
         "WARNING  disabled:test_log_disabling_works_with_log_cli.py:7 This string will be suppressed."
     )
     assert not result.stderr.lines
+
+
+def test_without_date_format_log(pytester: Pytester) -> None:
+    """Check that date is not printed by default."""
+    pytester.makepyfile(
+        """
+        import logging
+
+        logger = logging.getLogger(__name__)
+
+        def test_foo():
+            logger.warning('text')
+            assert False
+        """
+    )
+    result = pytester.runpytest()
+    assert result.ret == 1
+    result.stdout.fnmatch_lines(
+        ["WARNING  test_without_date_format_log:test_without_date_format_log.py:6 text"]
+    )
+
+
+def test_date_format_log(pytester: Pytester) -> None:
+    """Check that log_date_format affects output."""
+    pytester.makepyfile(
+        """
+        import logging
+
+        logger = logging.getLogger(__name__)
+
+        def test_foo():
+            logger.warning('text')
+            assert False
+        """
+    )
+    pytester.makeini(
+        """
+        [pytest]
+        log_format=%(asctime)s; %(levelname)s; %(message)s
+        log_date_format=%Y-%m-%d %H:%M:%S
+    """
+    )
+    result = pytester.runpytest()
+    assert result.ret == 1
+    result.stdout.re_match_lines([r"^[0-9-]{10} [0-9:]{8}; WARNING; text"])
+
+
+def test_date_format_percentf_log(pytester: Pytester) -> None:
+    """Make sure that microseconds are printed in log."""
+    pytester.makepyfile(
+        """
+        import logging
+
+        logger = logging.getLogger(__name__)
+
+        def test_foo():
+            logger.warning('text')
+            assert False
+        """
+    )
+    pytester.makeini(
+        """
+        [pytest]
+        log_format=%(asctime)s; %(levelname)s; %(message)s
+        log_date_format=%Y-%m-%d %H:%M:%S.%f
+    """
+    )
+    result = pytester.runpytest()
+    assert result.ret == 1
+    result.stdout.re_match_lines([r"^[0-9-]{10} [0-9:]{8}.[0-9]{6}; WARNING; text"])
+
+
+def test_date_format_percentf_tz_log(pytester: Pytester) -> None:
+    """Make sure that timezone and microseconds are properly formatted together."""
+    pytester.makepyfile(
+        """
+        import logging
+
+        logger = logging.getLogger(__name__)
+
+        def test_foo():
+            logger.warning('text')
+            assert False
+        """
+    )
+    pytester.makeini(
+        """
+        [pytest]
+        log_format=%(asctime)s; %(levelname)s; %(message)s
+        log_date_format=%Y-%m-%d %H:%M:%S.%f%z
+    """
+    )
+    result = pytester.runpytest()
+    assert result.ret == 1
+    result.stdout.re_match_lines(
+        [r"^[0-9-]{10} [0-9:]{8}.[0-9]{6}[+-][0-9\.]+; WARNING; text"]
+    )