logging.py 33 KB

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