You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

822 lines
29KB

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