From 89053225e3d4af71b2d344486c68441a3d565635 Mon Sep 17 00:00:00 2001 From: theirix Date: Sun, 28 May 2023 14:06:48 +0300 Subject: [PATCH] Handle microseconds with custom logging.Formatter (#10991) --- AUTHORS | 1 + changelog/10991.improvement.rst | 2 + src/_pytest/logging.py | 31 +++++++++- testing/logging/test_reporting.py | 97 +++++++++++++++++++++++++++++++ 4 files changed, 128 insertions(+), 3 deletions(-) create mode 100644 changelog/10991.improvement.rst diff --git a/AUTHORS b/AUTHORS index 30908870783..f40c2fd04af 100644 --- a/AUTHORS +++ b/AUTHORS @@ -131,6 +131,7 @@ Eric Siegerman Erik Aronesty Erik M. Bray Evan Kepner +Evgeny Seliverstov Fabien Zarifian Fabio Zadrozny Felix Hofstätter diff --git a/changelog/10991.improvement.rst b/changelog/10991.improvement.rst new file mode 100644 index 00000000000..40ae9eda49c --- /dev/null +++ b/changelog/10991.improvement.rst @@ -0,0 +1,2 @@ +Added handling of ``%f`` directive to print microseconds in log format options, such as ``log-date-format``. +Added helper :class:`pytest.logging.DatetimeFormatter <_pytest.logging.DatetimeFormatter>` which overrides :class:`logging.Formatter` behaviour to print log records with a microsecond-aware function :func:`datetime.strftime` instead of :func:`time.strftime`. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 95774dd1472..4c5c53a1409 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -5,7 +5,11 @@ 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,28 @@ 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 __init__(self, *args, **kwargs) -> None: + super().__init__(*args, **kwargs) + + 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 +650,7 @@ def __init__(self, config: Config) -> None: 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 +694,7 @@ def _create_formatter(self, log_format, log_date_format, auto_indent): 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 diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index ae2f53277fb..14b77236ab2 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1234,3 +1234,100 @@ def test_log_cli_works(caplog): "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"] + )