logging.py 30 KB

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