diff --git a/AUTHORS b/AUTHORS index 77d64712683..42936552f1d 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..768c08e554c --- /dev/null +++ b/changelog/10991.improvement.rst @@ -0,0 +1 @@ +Added handling of ``%f`` directive to print microseconds in log format options, such as ``log-date-format``. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 95774dd1472..6381e86b01d 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,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 @@ 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 +691,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"] + )