logging.py 29 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826
  1. """Access and control log capturing."""
  2. import io
  3. import logging
  4. import os
  5. import re
  6. from contextlib import contextmanager
  7. from contextlib import nullcontext
  8. from io import StringIO
  9. from pathlib import Path
  10. from typing import AbstractSet
  11. from typing import Dict
  12. from typing import Generator
  13. from typing import List
  14. from typing import Mapping
  15. from typing import Optional
  16. from typing import Tuple
  17. from typing import TYPE_CHECKING
  18. from typing import TypeVar
  19. from typing import Union
  20. from _pytest import nodes
  21. from _pytest._io import TerminalWriter
  22. from _pytest.capture import CaptureManager
  23. from _pytest.compat import final
  24. from _pytest.config import _strtobool
  25. from _pytest.config import Config
  26. from _pytest.config import create_terminal_writer
  27. from _pytest.config import hookimpl
  28. from _pytest.config import UsageError
  29. from _pytest.config.argparsing import Parser
  30. from _pytest.deprecated import check_ispytest
  31. from _pytest.fixtures import fixture
  32. from _pytest.fixtures import FixtureRequest
  33. from _pytest.main import Session
  34. from _pytest.stash import StashKey
  35. from _pytest.terminal import TerminalReporter
  36. if TYPE_CHECKING:
  37. logging_StreamHandler = logging.StreamHandler[StringIO]
  38. else:
  39. logging_StreamHandler = logging.StreamHandler
  40. DEFAULT_LOG_FORMAT = "%(levelname)-8s %(name)s:%(filename)s:%(lineno)d %(message)s"
  41. DEFAULT_LOG_DATE_FORMAT = "%H:%M:%S"
  42. _ANSI_ESCAPE_SEQ = re.compile(r"\x1b\[[\d;]+m")
  43. caplog_handler_key = StashKey["LogCaptureHandler"]()
  44. caplog_records_key = StashKey[Dict[str, List[logging.LogRecord]]]()
  45. def _remove_ansi_escape_sequences(text: str) -> str:
  46. return _ANSI_ESCAPE_SEQ.sub("", text)
  47. class ColoredLevelFormatter(logging.Formatter):
  48. """A logging formatter which colorizes the %(levelname)..s part of the
  49. log format passed to __init__."""
  50. LOGLEVEL_COLOROPTS: Mapping[int, AbstractSet[str]] = {
  51. logging.CRITICAL: {"red"},
  52. logging.ERROR: {"red", "bold"},
  53. logging.WARNING: {"yellow"},
  54. logging.WARN: {"yellow"},
  55. logging.INFO: {"green"},
  56. logging.DEBUG: {"purple"},
  57. logging.NOTSET: set(),
  58. }
  59. LEVELNAME_FMT_REGEX = re.compile(r"%\(levelname\)([+-.]?\d*(?:\.\d+)?s)")
  60. def __init__(self, terminalwriter: TerminalWriter, *args, **kwargs) -> None:
  61. super().__init__(*args, **kwargs)
  62. self._terminalwriter = terminalwriter
  63. self._original_fmt = self._style._fmt
  64. self._level_to_fmt_mapping: Dict[int, str] = {}
  65. for level, color_opts in self.LOGLEVEL_COLOROPTS.items():
  66. self.add_color_level(level, *color_opts)
  67. def add_color_level(self, level: int, *color_opts: str) -> None:
  68. """Add or update color opts for a log level.
  69. :param level:
  70. Log level to apply a style to, e.g. ``logging.INFO``.
  71. :param color_opts:
  72. ANSI escape sequence color options. Capitalized colors indicates
  73. background color, i.e. ``'green', 'Yellow', 'bold'`` will give bold
  74. green text on yellow background.
  75. .. warning::
  76. This is an experimental API.
  77. """
  78. assert self._fmt is not None
  79. levelname_fmt_match = self.LEVELNAME_FMT_REGEX.search(self._fmt)
  80. if not levelname_fmt_match:
  81. return
  82. levelname_fmt = levelname_fmt_match.group()
  83. formatted_levelname = levelname_fmt % {"levelname": logging.getLevelName(level)}
  84. # add ANSI escape sequences around the formatted levelname
  85. color_kwargs = {name: True for name in color_opts}
  86. colorized_formatted_levelname = self._terminalwriter.markup(
  87. formatted_levelname, **color_kwargs
  88. )
  89. self._level_to_fmt_mapping[level] = self.LEVELNAME_FMT_REGEX.sub(
  90. colorized_formatted_levelname, self._fmt
  91. )
  92. def format(self, record: logging.LogRecord) -> str:
  93. fmt = self._level_to_fmt_mapping.get(record.levelno, self._original_fmt)
  94. self._style._fmt = fmt
  95. return super().format(record)
  96. class PercentStyleMultiline(logging.PercentStyle):
  97. """A logging style with special support for multiline messages.
  98. If the message of a record consists of multiple lines, this style
  99. formats the message as if each line were logged separately.
  100. """
  101. def __init__(self, fmt: str, auto_indent: Union[int, str, bool, None]) -> None:
  102. super().__init__(fmt)
  103. self._auto_indent = self._get_auto_indent(auto_indent)
  104. @staticmethod
  105. def _get_auto_indent(auto_indent_option: Union[int, str, bool, None]) -> int:
  106. """Determine the current auto indentation setting.
  107. Specify auto indent behavior (on/off/fixed) by passing in
  108. extra={"auto_indent": [value]} to the call to logging.log() or
  109. using a --log-auto-indent [value] command line or the
  110. log_auto_indent [value] config option.
  111. Default behavior is auto-indent off.
  112. Using the string "True" or "on" or the boolean True as the value
  113. turns auto indent on, using the string "False" or "off" or the
  114. boolean False or the int 0 turns it off, and specifying a
  115. positive integer fixes the indentation position to the value
  116. specified.
  117. Any other values for the option are invalid, and will silently be
  118. converted to the default.
  119. :param None|bool|int|str auto_indent_option:
  120. User specified option for indentation from command line, config
  121. or extra kwarg. Accepts int, bool or str. str option accepts the
  122. same range of values as boolean config options, as well as
  123. positive integers represented in str form.
  124. :returns:
  125. Indentation value, which can be
  126. -1 (automatically determine indentation) or
  127. 0 (auto-indent turned off) or
  128. >0 (explicitly set indentation position).
  129. """
  130. if auto_indent_option is None:
  131. return 0
  132. elif isinstance(auto_indent_option, bool):
  133. if auto_indent_option:
  134. return -1
  135. else:
  136. return 0
  137. elif isinstance(auto_indent_option, int):
  138. return int(auto_indent_option)
  139. elif isinstance(auto_indent_option, str):
  140. try:
  141. return int(auto_indent_option)
  142. except ValueError:
  143. pass
  144. try:
  145. if _strtobool(auto_indent_option):
  146. return -1
  147. except ValueError:
  148. return 0
  149. return 0
  150. def format(self, record: logging.LogRecord) -> str:
  151. if "\n" in record.message:
  152. if hasattr(record, "auto_indent"):
  153. # Passed in from the "extra={}" kwarg on the call to logging.log().
  154. auto_indent = self._get_auto_indent(record.auto_indent) # type: ignore[attr-defined]
  155. else:
  156. auto_indent = self._auto_indent
  157. if auto_indent:
  158. lines = record.message.splitlines()
  159. formatted = self._fmt % {**record.__dict__, "message": lines[0]}
  160. if auto_indent < 0:
  161. indentation = _remove_ansi_escape_sequences(formatted).find(
  162. lines[0]
  163. )
  164. else:
  165. # Optimizes logging by allowing a fixed indentation.
  166. indentation = auto_indent
  167. lines[0] = formatted
  168. return ("\n" + " " * indentation).join(lines)
  169. return self._fmt % record.__dict__
  170. def get_option_ini(config: Config, *names: str):
  171. for name in names:
  172. ret = config.getoption(name) # 'default' arg won't work as expected
  173. if ret is None:
  174. ret = config.getini(name)
  175. if ret:
  176. return ret
  177. def pytest_addoption(parser: Parser) -> None:
  178. """Add options to control log capturing."""
  179. group = parser.getgroup("logging")
  180. def add_option_ini(option, dest, default=None, type=None, **kwargs):
  181. parser.addini(
  182. dest, default=default, type=type, help="default value for " + option
  183. )
  184. group.addoption(option, dest=dest, **kwargs)
  185. add_option_ini(
  186. "--log-level",
  187. dest="log_level",
  188. default=None,
  189. metavar="LEVEL",
  190. help=(
  191. "level of messages to catch/display.\n"
  192. "Not set by default, so it depends on the root/parent log handler's"
  193. ' effective level, where it is "WARNING" by default.'
  194. ),
  195. )
  196. add_option_ini(
  197. "--log-format",
  198. dest="log_format",
  199. default=DEFAULT_LOG_FORMAT,
  200. help="log format as used by the logging module.",
  201. )
  202. add_option_ini(
  203. "--log-date-format",
  204. dest="log_date_format",
  205. default=DEFAULT_LOG_DATE_FORMAT,
  206. help="log date format as used by the logging module.",
  207. )
  208. parser.addini(
  209. "log_cli",
  210. default=False,
  211. type="bool",
  212. help='enable log display during test run (also known as "live logging").',
  213. )
  214. add_option_ini(
  215. "--log-cli-level", dest="log_cli_level", default=None, help="cli logging level."
  216. )
  217. add_option_ini(
  218. "--log-cli-format",
  219. dest="log_cli_format",
  220. default=None,
  221. help="log format as used by the logging module.",
  222. )
  223. add_option_ini(
  224. "--log-cli-date-format",
  225. dest="log_cli_date_format",
  226. default=None,
  227. help="log date format as used by the logging module.",
  228. )
  229. add_option_ini(
  230. "--log-file",
  231. dest="log_file",
  232. default=None,
  233. help="path to a file when logging will be written to.",
  234. )
  235. add_option_ini(
  236. "--log-file-level",
  237. dest="log_file_level",
  238. default=None,
  239. help="log file logging level.",
  240. )
  241. add_option_ini(
  242. "--log-file-format",
  243. dest="log_file_format",
  244. default=DEFAULT_LOG_FORMAT,
  245. help="log format as used by the logging module.",
  246. )
  247. add_option_ini(
  248. "--log-file-date-format",
  249. dest="log_file_date_format",
  250. default=DEFAULT_LOG_DATE_FORMAT,
  251. help="log date format as used by the logging module.",
  252. )
  253. add_option_ini(
  254. "--log-auto-indent",
  255. dest="log_auto_indent",
  256. default=None,
  257. help="Auto-indent multiline messages passed to the logging module. Accepts true|on, false|off or an integer.",
  258. )
  259. _HandlerType = TypeVar("_HandlerType", bound=logging.Handler)
  260. # Not using @contextmanager for performance reasons.
  261. class catching_logs:
  262. """Context manager that prepares the whole logging machinery properly."""
  263. __slots__ = ("handler", "level", "orig_level")
  264. def __init__(self, handler: _HandlerType, level: Optional[int] = None) -> None:
  265. self.handler = handler
  266. self.level = level
  267. def __enter__(self):
  268. root_logger = logging.getLogger()
  269. if self.level is not None:
  270. self.handler.setLevel(self.level)
  271. root_logger.addHandler(self.handler)
  272. if self.level is not None:
  273. self.orig_level = root_logger.level
  274. root_logger.setLevel(min(self.orig_level, self.level))
  275. return self.handler
  276. def __exit__(self, type, value, traceback):
  277. root_logger = logging.getLogger()
  278. if self.level is not None:
  279. root_logger.setLevel(self.orig_level)
  280. root_logger.removeHandler(self.handler)
  281. class LogCaptureHandler(logging_StreamHandler):
  282. """A logging handler that stores log records and the log text."""
  283. def __init__(self) -> None:
  284. """Create a new log handler."""
  285. super().__init__(StringIO())
  286. self.records: List[logging.LogRecord] = []
  287. def emit(self, record: logging.LogRecord) -> None:
  288. """Keep the log records in a list in addition to the log text."""
  289. self.records.append(record)
  290. super().emit(record)
  291. def reset(self) -> None:
  292. self.records = []
  293. self.stream = StringIO()
  294. def handleError(self, record: logging.LogRecord) -> None:
  295. if logging.raiseExceptions:
  296. # Fail the test if the log message is bad (emit failed).
  297. # The default behavior of logging is to print "Logging error"
  298. # to stderr with the call stack and some extra details.
  299. # pytest wants to make such mistakes visible during testing.
  300. raise
  301. @final
  302. class LogCaptureFixture:
  303. """Provides access and control of log capturing."""
  304. def __init__(self, item: nodes.Node, *, _ispytest: bool = False) -> None:
  305. check_ispytest(_ispytest)
  306. self._item = item
  307. self._initial_handler_level: Optional[int] = None
  308. # Dict of log name -> log level.
  309. self._initial_logger_levels: Dict[Optional[str], int] = {}
  310. def _finalize(self) -> None:
  311. """Finalize the fixture.
  312. This restores the log levels changed by :meth:`set_level`.
  313. """
  314. # Restore log levels.
  315. if self._initial_handler_level is not None:
  316. self.handler.setLevel(self._initial_handler_level)
  317. for logger_name, level in self._initial_logger_levels.items():
  318. logger = logging.getLogger(logger_name)
  319. logger.setLevel(level)
  320. @property
  321. def handler(self) -> LogCaptureHandler:
  322. """Get the logging handler used by the fixture.
  323. :rtype: LogCaptureHandler
  324. """
  325. return self._item.stash[caplog_handler_key]
  326. def get_records(self, when: str) -> List[logging.LogRecord]:
  327. """Get the logging records for one of the possible test phases.
  328. :param str when:
  329. Which test phase to obtain the records from. Valid values are: "setup", "call" and "teardown".
  330. :returns: The list of captured records at the given stage.
  331. :rtype: List[logging.LogRecord]
  332. .. versionadded:: 3.4
  333. """
  334. return self._item.stash[caplog_records_key].get(when, [])
  335. @property
  336. def text(self) -> str:
  337. """The formatted log text."""
  338. return _remove_ansi_escape_sequences(self.handler.stream.getvalue())
  339. @property
  340. def records(self) -> List[logging.LogRecord]:
  341. """The list of log records."""
  342. return self.handler.records
  343. @property
  344. def record_tuples(self) -> List[Tuple[str, int, str]]:
  345. """A list of a stripped down version of log records intended
  346. for use in assertion comparison.
  347. The format of the tuple is:
  348. (logger_name, log_level, message)
  349. """
  350. return [(r.name, r.levelno, r.getMessage()) for r in self.records]
  351. @property
  352. def messages(self) -> List[str]:
  353. """A list of format-interpolated log messages.
  354. Unlike 'records', which contains the format string and parameters for
  355. interpolation, log messages in this list are all interpolated.
  356. Unlike 'text', which contains the output from the handler, log
  357. messages in this list are unadorned with levels, timestamps, etc,
  358. making exact comparisons more reliable.
  359. Note that traceback or stack info (from :func:`logging.exception` or
  360. the `exc_info` or `stack_info` arguments to the logging functions) is
  361. not included, as this is added by the formatter in the handler.
  362. .. versionadded:: 3.7
  363. """
  364. return [r.getMessage() for r in self.records]
  365. def clear(self) -> None:
  366. """Reset the list of log records and the captured log text."""
  367. self.handler.reset()
  368. def set_level(self, level: Union[int, str], logger: Optional[str] = None) -> None:
  369. """Set the level of a logger for the duration of a test.
  370. .. versionchanged:: 3.4
  371. The levels of the loggers changed by this function will be
  372. restored to their initial values at the end of the test.
  373. :param int level: The level.
  374. :param str logger: The logger to update. If not given, the root logger.
  375. """
  376. logger_obj = logging.getLogger(logger)
  377. # Save the original log-level to restore it during teardown.
  378. self._initial_logger_levels.setdefault(logger, logger_obj.level)
  379. logger_obj.setLevel(level)
  380. if self._initial_handler_level is None:
  381. self._initial_handler_level = self.handler.level
  382. self.handler.setLevel(level)
  383. @contextmanager
  384. def at_level(
  385. self, level: Union[int, str], logger: Optional[str] = None
  386. ) -> Generator[None, None, None]:
  387. """Context manager that sets the level for capturing of logs. After
  388. the end of the 'with' statement the level is restored to its original
  389. value.
  390. :param int level: The level.
  391. :param str logger: The logger to update. If not given, the root logger.
  392. """
  393. logger_obj = logging.getLogger(logger)
  394. orig_level = logger_obj.level
  395. logger_obj.setLevel(level)
  396. handler_orig_level = self.handler.level
  397. self.handler.setLevel(level)
  398. try:
  399. yield
  400. finally:
  401. logger_obj.setLevel(orig_level)
  402. self.handler.setLevel(handler_orig_level)
  403. @fixture
  404. def caplog(request: FixtureRequest) -> Generator[LogCaptureFixture, None, None]:
  405. """Access and control log capturing.
  406. Captured logs are available through the following properties/methods::
  407. * caplog.messages -> list of format-interpolated log messages
  408. * caplog.text -> string containing formatted log output
  409. * caplog.records -> list of logging.LogRecord instances
  410. * caplog.record_tuples -> list of (logger_name, level, message) tuples
  411. * caplog.clear() -> clear captured records and formatted log output string
  412. """
  413. result = LogCaptureFixture(request.node, _ispytest=True)
  414. yield result
  415. result._finalize()
  416. def get_log_level_for_setting(config: Config, *setting_names: str) -> Optional[int]:
  417. for setting_name in setting_names:
  418. log_level = config.getoption(setting_name)
  419. if log_level is None:
  420. log_level = config.getini(setting_name)
  421. if log_level:
  422. break
  423. else:
  424. return None
  425. if isinstance(log_level, str):
  426. log_level = log_level.upper()
  427. try:
  428. return int(getattr(logging, log_level, log_level))
  429. except ValueError as e:
  430. # Python logging does not recognise this as a logging level
  431. raise UsageError(
  432. "'{}' is not recognized as a logging level name for "
  433. "'{}'. Please consider passing the "
  434. "logging level num instead.".format(log_level, setting_name)
  435. ) from e
  436. # run after terminalreporter/capturemanager are configured
  437. @hookimpl(trylast=True)
  438. def pytest_configure(config: Config) -> None:
  439. config.pluginmanager.register(LoggingPlugin(config), "logging-plugin")
  440. class LoggingPlugin:
  441. """Attaches to the logging module and captures log messages for each test."""
  442. def __init__(self, config: Config) -> None:
  443. """Create a new plugin to capture log messages.
  444. The formatter can be safely shared across all handlers so
  445. create a single one for the entire test session here.
  446. """
  447. self._config = config
  448. # Report logging.
  449. self.formatter = self._create_formatter(
  450. get_option_ini(config, "log_format"),
  451. get_option_ini(config, "log_date_format"),
  452. get_option_ini(config, "log_auto_indent"),
  453. )
  454. self.log_level = get_log_level_for_setting(config, "log_level")
  455. self.caplog_handler = LogCaptureHandler()
  456. self.caplog_handler.setFormatter(self.formatter)
  457. self.report_handler = LogCaptureHandler()
  458. self.report_handler.setFormatter(self.formatter)
  459. # File logging.
  460. self.log_file_level = get_log_level_for_setting(config, "log_file_level")
  461. log_file = get_option_ini(config, "log_file") or os.devnull
  462. if log_file != os.devnull:
  463. directory = os.path.dirname(os.path.abspath(log_file))
  464. if not os.path.isdir(directory):
  465. os.makedirs(directory)
  466. self.log_file_handler = _FileHandler(log_file, mode="w", encoding="UTF-8")
  467. log_file_format = get_option_ini(config, "log_file_format", "log_format")
  468. log_file_date_format = get_option_ini(
  469. config, "log_file_date_format", "log_date_format"
  470. )
  471. log_file_formatter = logging.Formatter(
  472. log_file_format, datefmt=log_file_date_format
  473. )
  474. self.log_file_handler.setFormatter(log_file_formatter)
  475. # CLI/live logging.
  476. self.log_cli_level = get_log_level_for_setting(
  477. config, "log_cli_level", "log_level"
  478. )
  479. if self._log_cli_enabled():
  480. terminal_reporter = config.pluginmanager.get_plugin("terminalreporter")
  481. capture_manager = config.pluginmanager.get_plugin("capturemanager")
  482. # if capturemanager plugin is disabled, live logging still works.
  483. self.log_cli_handler: Union[
  484. _LiveLoggingStreamHandler, _LiveLoggingNullHandler
  485. ] = _LiveLoggingStreamHandler(terminal_reporter, capture_manager)
  486. else:
  487. self.log_cli_handler = _LiveLoggingNullHandler()
  488. log_cli_formatter = self._create_formatter(
  489. get_option_ini(config, "log_cli_format", "log_format"),
  490. get_option_ini(config, "log_cli_date_format", "log_date_format"),
  491. get_option_ini(config, "log_auto_indent"),
  492. )
  493. self.log_cli_handler.setFormatter(log_cli_formatter)
  494. def _create_formatter(self, log_format, log_date_format, auto_indent):
  495. # Color option doesn't exist if terminal plugin is disabled.
  496. color = getattr(self._config.option, "color", "no")
  497. if color != "no" and ColoredLevelFormatter.LEVELNAME_FMT_REGEX.search(
  498. log_format
  499. ):
  500. formatter: logging.Formatter = ColoredLevelFormatter(
  501. create_terminal_writer(self._config), log_format, log_date_format
  502. )
  503. else:
  504. formatter = logging.Formatter(log_format, log_date_format)
  505. formatter._style = PercentStyleMultiline(
  506. formatter._style._fmt, auto_indent=auto_indent
  507. )
  508. return formatter
  509. def set_log_path(self, fname: str) -> None:
  510. """Set the filename parameter for Logging.FileHandler().
  511. Creates parent directory if it does not exist.
  512. .. warning::
  513. This is an experimental API.
  514. """
  515. fpath = Path(fname)
  516. if not fpath.is_absolute():
  517. fpath = self._config.rootpath / fpath
  518. if not fpath.parent.exists():
  519. fpath.parent.mkdir(exist_ok=True, parents=True)
  520. # https://github.com/python/mypy/issues/11193
  521. stream: io.TextIOWrapper = fpath.open(mode="w", encoding="UTF-8") # type: ignore[assignment]
  522. old_stream = self.log_file_handler.setStream(stream)
  523. if old_stream:
  524. old_stream.close()
  525. def _log_cli_enabled(self):
  526. """Return whether live logging is enabled."""
  527. enabled = self._config.getoption(
  528. "--log-cli-level"
  529. ) is not None or self._config.getini("log_cli")
  530. if not enabled:
  531. return False
  532. terminal_reporter = self._config.pluginmanager.get_plugin("terminalreporter")
  533. if terminal_reporter is None:
  534. # terminal reporter is disabled e.g. by pytest-xdist.
  535. return False
  536. return True
  537. @hookimpl(hookwrapper=True, tryfirst=True)
  538. def pytest_sessionstart(self) -> Generator[None, None, None]:
  539. self.log_cli_handler.set_when("sessionstart")
  540. with catching_logs(self.log_cli_handler, level=self.log_cli_level):
  541. with catching_logs(self.log_file_handler, level=self.log_file_level):
  542. yield
  543. @hookimpl(hookwrapper=True, tryfirst=True)
  544. def pytest_collection(self) -> Generator[None, None, None]:
  545. self.log_cli_handler.set_when("collection")
  546. with catching_logs(self.log_cli_handler, level=self.log_cli_level):
  547. with catching_logs(self.log_file_handler, level=self.log_file_level):
  548. yield
  549. @hookimpl(hookwrapper=True)
  550. def pytest_runtestloop(self, session: Session) -> Generator[None, None, None]:
  551. if session.config.option.collectonly:
  552. yield
  553. return
  554. if self._log_cli_enabled() and self._config.getoption("verbose") < 1:
  555. # The verbose flag is needed to avoid messy test progress output.
  556. self._config.option.verbose = 1
  557. with catching_logs(self.log_cli_handler, level=self.log_cli_level):
  558. with catching_logs(self.log_file_handler, level=self.log_file_level):
  559. yield # Run all the tests.
  560. @hookimpl
  561. def pytest_runtest_logstart(self) -> None:
  562. self.log_cli_handler.reset()
  563. self.log_cli_handler.set_when("start")
  564. @hookimpl
  565. def pytest_runtest_logreport(self) -> None:
  566. self.log_cli_handler.set_when("logreport")
  567. def _runtest_for(self, item: nodes.Item, when: str) -> Generator[None, None, None]:
  568. """Implement the internals of the pytest_runtest_xxx() hooks."""
  569. with catching_logs(
  570. self.caplog_handler,
  571. level=self.log_level,
  572. ) as caplog_handler, catching_logs(
  573. self.report_handler,
  574. level=self.log_level,
  575. ) as report_handler:
  576. caplog_handler.reset()
  577. report_handler.reset()
  578. item.stash[caplog_records_key][when] = caplog_handler.records
  579. item.stash[caplog_handler_key] = caplog_handler
  580. yield
  581. log = report_handler.stream.getvalue().strip()
  582. item.add_report_section(when, "log", log)
  583. @hookimpl(hookwrapper=True)
  584. def pytest_runtest_setup(self, item: nodes.Item) -> Generator[None, None, None]:
  585. self.log_cli_handler.set_when("setup")
  586. empty: Dict[str, List[logging.LogRecord]] = {}
  587. item.stash[caplog_records_key] = empty
  588. yield from self._runtest_for(item, "setup")
  589. @hookimpl(hookwrapper=True)
  590. def pytest_runtest_call(self, item: nodes.Item) -> Generator[None, None, None]:
  591. self.log_cli_handler.set_when("call")
  592. yield from self._runtest_for(item, "call")
  593. @hookimpl(hookwrapper=True)
  594. def pytest_runtest_teardown(self, item: nodes.Item) -> Generator[None, None, None]:
  595. self.log_cli_handler.set_when("teardown")
  596. yield from self._runtest_for(item, "teardown")
  597. del item.stash[caplog_records_key]
  598. del item.stash[caplog_handler_key]
  599. @hookimpl
  600. def pytest_runtest_logfinish(self) -> None:
  601. self.log_cli_handler.set_when("finish")
  602. @hookimpl(hookwrapper=True, tryfirst=True)
  603. def pytest_sessionfinish(self) -> Generator[None, None, None]:
  604. self.log_cli_handler.set_when("sessionfinish")
  605. with catching_logs(self.log_cli_handler, level=self.log_cli_level):
  606. with catching_logs(self.log_file_handler, level=self.log_file_level):
  607. yield
  608. @hookimpl
  609. def pytest_unconfigure(self) -> None:
  610. # Close the FileHandler explicitly.
  611. # (logging.shutdown might have lost the weakref?!)
  612. self.log_file_handler.close()
  613. class _FileHandler(logging.FileHandler):
  614. """A logging FileHandler with pytest tweaks."""
  615. def handleError(self, record: logging.LogRecord) -> None:
  616. # Handled by LogCaptureHandler.
  617. pass
  618. class _LiveLoggingStreamHandler(logging_StreamHandler):
  619. """A logging StreamHandler used by the live logging feature: it will
  620. write a newline before the first log message in each test.
  621. During live logging we must also explicitly disable stdout/stderr
  622. capturing otherwise it will get captured and won't appear in the
  623. terminal.
  624. """
  625. # Officially stream needs to be a IO[str], but TerminalReporter
  626. # isn't. So force it.
  627. stream: TerminalReporter = None # type: ignore
  628. def __init__(
  629. self,
  630. terminal_reporter: TerminalReporter,
  631. capture_manager: Optional[CaptureManager],
  632. ) -> None:
  633. super().__init__(stream=terminal_reporter) # type: ignore[arg-type]
  634. self.capture_manager = capture_manager
  635. self.reset()
  636. self.set_when(None)
  637. self._test_outcome_written = False
  638. def reset(self) -> None:
  639. """Reset the handler; should be called before the start of each test."""
  640. self._first_record_emitted = False
  641. def set_when(self, when: Optional[str]) -> None:
  642. """Prepare for the given test phase (setup/call/teardown)."""
  643. self._when = when
  644. self._section_name_shown = False
  645. if when == "start":
  646. self._test_outcome_written = False
  647. def emit(self, record: logging.LogRecord) -> None:
  648. ctx_manager = (
  649. self.capture_manager.global_and_fixture_disabled()
  650. if self.capture_manager
  651. else nullcontext()
  652. )
  653. with ctx_manager:
  654. if not self._first_record_emitted:
  655. self.stream.write("\n")
  656. self._first_record_emitted = True
  657. elif self._when in ("teardown", "finish"):
  658. if not self._test_outcome_written:
  659. self._test_outcome_written = True
  660. self.stream.write("\n")
  661. if not self._section_name_shown and self._when:
  662. self.stream.section("live log " + self._when, sep="-", bold=True)
  663. self._section_name_shown = True
  664. super().emit(record)
  665. def handleError(self, record: logging.LogRecord) -> None:
  666. # Handled by LogCaptureHandler.
  667. pass
  668. class _LiveLoggingNullHandler(logging.NullHandler):
  669. """A logging handler used when live logging is disabled."""
  670. def reset(self) -> None:
  671. pass
  672. def set_when(self, when: str) -> None:
  673. pass
  674. def handleError(self, record: logging.LogRecord) -> None:
  675. # Handled by LogCaptureHandler.
  676. pass