Coverage for /usr/local/lib/python3.7/site-packages/_pytest/logging.py : 32%

Hot-keys on this page
r m x p toggle line displays
j k next/prev highlighted chunk
0 (zero) top of page
1 (one) first highlighted chunk
1""" Access and control log capturing. """
2import logging
3import re
4from contextlib import contextmanager
5from io import StringIO
6from typing import AbstractSet
7from typing import Dict
8from typing import List
9from typing import Mapping
11import pytest
12from _pytest.compat import nullcontext
13from _pytest.config import _strtobool
14from _pytest.config import create_terminal_writer
15from _pytest.pathlib import Path
17DEFAULT_LOG_FORMAT = "%(levelname)-8s %(name)s:%(filename)s:%(lineno)d %(message)s"
18DEFAULT_LOG_DATE_FORMAT = "%H:%M:%S"
19_ANSI_ESCAPE_SEQ = re.compile(r"\x1b\[[\d;]+m")
22def _remove_ansi_escape_sequences(text):
23 return _ANSI_ESCAPE_SEQ.sub("", text)
26class ColoredLevelFormatter(logging.Formatter):
27 """
28 Colorize the %(levelname)..s part of the log format passed to __init__.
29 """
31 LOGLEVEL_COLOROPTS = {
32 logging.CRITICAL: {"red"},
33 logging.ERROR: {"red", "bold"},
34 logging.WARNING: {"yellow"},
35 logging.WARN: {"yellow"},
36 logging.INFO: {"green"},
37 logging.DEBUG: {"purple"},
38 logging.NOTSET: set(),
39 } # type: Mapping[int, AbstractSet[str]]
40 LEVELNAME_FMT_REGEX = re.compile(r"%\(levelname\)([+-.]?\d*s)")
42 def __init__(self, terminalwriter, *args, **kwargs) -> None:
43 super().__init__(*args, **kwargs)
44 self._original_fmt = self._style._fmt
45 self._level_to_fmt_mapping = {} # type: Dict[int, str]
47 assert self._fmt is not None
48 levelname_fmt_match = self.LEVELNAME_FMT_REGEX.search(self._fmt)
49 if not levelname_fmt_match:
50 return
51 levelname_fmt = levelname_fmt_match.group()
53 for level, color_opts in self.LOGLEVEL_COLOROPTS.items():
54 formatted_levelname = levelname_fmt % {
55 "levelname": logging.getLevelName(level)
56 }
58 # add ANSI escape sequences around the formatted levelname
59 color_kwargs = {name: True for name in color_opts}
60 colorized_formatted_levelname = terminalwriter.markup(
61 formatted_levelname, **color_kwargs
62 )
63 self._level_to_fmt_mapping[level] = self.LEVELNAME_FMT_REGEX.sub(
64 colorized_formatted_levelname, self._fmt
65 )
67 def format(self, record):
68 fmt = self._level_to_fmt_mapping.get(record.levelno, self._original_fmt)
69 self._style._fmt = fmt
70 return super().format(record)
73class PercentStyleMultiline(logging.PercentStyle):
74 """A logging style with special support for multiline messages.
76 If the message of a record consists of multiple lines, this style
77 formats the message as if each line were logged separately.
78 """
80 def __init__(self, fmt, auto_indent):
81 super().__init__(fmt)
82 self._auto_indent = self._get_auto_indent(auto_indent)
84 @staticmethod
85 def _update_message(record_dict, message):
86 tmp = record_dict.copy()
87 tmp["message"] = message
88 return tmp
90 @staticmethod
91 def _get_auto_indent(auto_indent_option) -> int:
92 """Determines the current auto indentation setting
94 Specify auto indent behavior (on/off/fixed) by passing in
95 extra={"auto_indent": [value]} to the call to logging.log() or
96 using a --log-auto-indent [value] command line or the
97 log_auto_indent [value] config option.
99 Default behavior is auto-indent off.
101 Using the string "True" or "on" or the boolean True as the value
102 turns auto indent on, using the string "False" or "off" or the
103 boolean False or the int 0 turns it off, and specifying a
104 positive integer fixes the indentation position to the value
105 specified.
107 Any other values for the option are invalid, and will silently be
108 converted to the default.
110 :param any auto_indent_option: User specified option for indentation
111 from command line, config or extra kwarg. Accepts int, bool or str.
112 str option accepts the same range of values as boolean config options,
113 as well as positive integers represented in str form.
115 :returns: indentation value, which can be
116 -1 (automatically determine indentation) or
117 0 (auto-indent turned off) or
118 >0 (explicitly set indentation position).
119 """
121 if type(auto_indent_option) is int:
122 return int(auto_indent_option)
123 elif type(auto_indent_option) is str:
124 try:
125 return int(auto_indent_option)
126 except ValueError:
127 pass
128 try:
129 if _strtobool(auto_indent_option):
130 return -1
131 except ValueError:
132 return 0
133 elif type(auto_indent_option) is bool:
134 if auto_indent_option:
135 return -1
137 return 0
139 def format(self, record):
140 if "\n" in record.message:
141 if hasattr(record, "auto_indent"):
142 # passed in from the "extra={}" kwarg on the call to logging.log()
143 auto_indent = self._get_auto_indent(record.auto_indent)
144 else:
145 auto_indent = self._auto_indent
147 if auto_indent:
148 lines = record.message.splitlines()
149 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__
163def get_option_ini(config, *names):
164 for name in names:
165 ret = config.getoption(name) # 'default' arg won't work as expected
166 if ret is None:
167 ret = config.getini(name)
168 if ret:
169 return ret
172def pytest_addoption(parser):
173 """Add options to control log capturing."""
174 group = parser.getgroup("logging")
176 def add_option_ini(option, dest, default=None, type=None, **kwargs):
177 parser.addini(
178 dest, default=default, type=type, help="default value for " + option
179 )
180 group.addoption(option, dest=dest, **kwargs)
182 add_option_ini(
183 "--no-print-logs",
184 dest="log_print",
185 action="store_const",
186 const=False,
187 default=True,
188 type="bool",
189 help="disable printing caught logs on failed tests.",
190 )
191 add_option_ini(
192 "--log-level",
193 dest="log_level",
194 default=None,
195 help="logging level used by the logging module",
196 )
197 add_option_ini(
198 "--log-format",
199 dest="log_format",
200 default=DEFAULT_LOG_FORMAT,
201 help="log format as used by the logging module.",
202 )
203 add_option_ini(
204 "--log-date-format",
205 dest="log_date_format",
206 default=DEFAULT_LOG_DATE_FORMAT,
207 help="log date format as used by the logging module.",
208 )
209 parser.addini(
210 "log_cli",
211 default=False,
212 type="bool",
213 help='enable log display during test run (also known as "live logging").',
214 )
215 add_option_ini(
216 "--log-cli-level", dest="log_cli_level", default=None, help="cli logging level."
217 )
218 add_option_ini(
219 "--log-cli-format",
220 dest="log_cli_format",
221 default=None,
222 help="log format as used by the logging module.",
223 )
224 add_option_ini(
225 "--log-cli-date-format",
226 dest="log_cli_date_format",
227 default=None,
228 help="log date format as used by the logging module.",
229 )
230 add_option_ini(
231 "--log-file",
232 dest="log_file",
233 default=None,
234 help="path to a file when logging will be written to.",
235 )
236 add_option_ini(
237 "--log-file-level",
238 dest="log_file_level",
239 default=None,
240 help="log file logging level.",
241 )
242 add_option_ini(
243 "--log-file-format",
244 dest="log_file_format",
245 default=DEFAULT_LOG_FORMAT,
246 help="log format as used by the logging module.",
247 )
248 add_option_ini(
249 "--log-file-date-format",
250 dest="log_file_date_format",
251 default=DEFAULT_LOG_DATE_FORMAT,
252 help="log date format as used by the logging module.",
253 )
254 add_option_ini(
255 "--log-auto-indent",
256 dest="log_auto_indent",
257 default=None,
258 help="Auto-indent multiline messages passed to the logging module. Accepts true|on, false|off or an integer.",
259 )
262@contextmanager
263def catching_logs(handler, formatter=None, level=None):
264 """Context manager that prepares the whole logging machinery properly."""
265 root_logger = logging.getLogger()
267 if formatter is not None:
268 handler.setFormatter(formatter)
269 if level is not None:
270 handler.setLevel(level)
272 # Adding the same handler twice would confuse logging system.
273 # Just don't do that.
274 add_new_handler = handler not in root_logger.handlers
276 if add_new_handler:
277 root_logger.addHandler(handler)
278 if level is not None:
279 orig_level = root_logger.level
280 root_logger.setLevel(min(orig_level, level))
281 try:
282 yield handler
283 finally:
284 if level is not None:
285 root_logger.setLevel(orig_level)
286 if add_new_handler:
287 root_logger.removeHandler(handler)
290class LogCaptureHandler(logging.StreamHandler):
291 """A logging handler that stores log records and the log text."""
293 def __init__(self) -> None:
294 """Creates a new log handler."""
295 logging.StreamHandler.__init__(self, StringIO())
296 self.records = [] # type: List[logging.LogRecord]
298 def emit(self, record: logging.LogRecord) -> None:
299 """Keep the log records in a list in addition to the log text."""
300 self.records.append(record)
301 logging.StreamHandler.emit(self, record)
303 def reset(self) -> None:
304 self.records = []
305 self.stream = StringIO()
308class LogCaptureFixture:
309 """Provides access and control of log capturing."""
311 def __init__(self, item) -> None:
312 """Creates a new funcarg."""
313 self._item = item
314 # dict of log name -> log level
315 self._initial_log_levels = {} # type: Dict[str, int]
317 def _finalize(self) -> None:
318 """Finalizes the fixture.
320 This restores the log levels changed by :meth:`set_level`.
321 """
322 # restore log levels
323 for logger_name, level in self._initial_log_levels.items():
324 logger = logging.getLogger(logger_name)
325 logger.setLevel(level)
327 @property
328 def handler(self):
329 """
330 :rtype: LogCaptureHandler
331 """
332 return self._item.catch_log_handler
334 def get_records(self, when):
335 """
336 Get the logging records for one of the possible test phases.
338 :param str when:
339 Which test phase to obtain the records from. Valid values are: "setup", "call" and "teardown".
341 :rtype: List[logging.LogRecord]
342 :return: the list of captured records at the given stage
344 .. versionadded:: 3.4
345 """
346 handler = self._item.catch_log_handlers.get(when)
347 if handler:
348 return handler.records
349 else:
350 return []
352 @property
353 def text(self):
354 """Returns the formatted log text."""
355 return _remove_ansi_escape_sequences(self.handler.stream.getvalue())
357 @property
358 def records(self):
359 """Returns the list of log records."""
360 return self.handler.records
362 @property
363 def record_tuples(self):
364 """Returns a list of a stripped down version of log records intended
365 for use in assertion comparison.
367 The format of the tuple is:
369 (logger_name, log_level, message)
370 """
371 return [(r.name, r.levelno, r.getMessage()) for r in self.records]
373 @property
374 def messages(self):
375 """Returns a list of format-interpolated log messages.
377 Unlike 'records', which contains the format string and parameters for interpolation, log messages in this list
378 are all interpolated.
379 Unlike 'text', which contains the output from the handler, log messages in this list are unadorned with
380 levels, timestamps, etc, making exact comparisons more reliable.
382 Note that traceback or stack info (from :func:`logging.exception` or the `exc_info` or `stack_info` arguments
383 to the logging functions) is not included, as this is added by the formatter in the handler.
385 .. versionadded:: 3.7
386 """
387 return [r.getMessage() for r in self.records]
389 def clear(self):
390 """Reset the list of log records and the captured log text."""
391 self.handler.reset()
393 def set_level(self, level, logger=None):
394 """Sets the level for capturing of logs. The level will be restored to its previous value at the end of
395 the test.
397 :param int level: the logger to level.
398 :param str logger: the logger to update the level. If not given, the root logger level is updated.
400 .. versionchanged:: 3.4
401 The levels of the loggers changed by this function will be restored to their initial values at the
402 end of the test.
403 """
404 logger_name = logger
405 logger = logging.getLogger(logger_name)
406 # save the original log-level to restore it during teardown
407 self._initial_log_levels.setdefault(logger_name, logger.level)
408 logger.setLevel(level)
410 @contextmanager
411 def at_level(self, level, logger=None):
412 """Context manager that sets the level for capturing of logs. After the end of the 'with' statement the
413 level is restored to its original value.
415 :param int level: the logger to level.
416 :param str logger: the logger to update the level. If not given, the root logger level is updated.
417 """
418 logger = logging.getLogger(logger)
419 orig_level = logger.level
420 logger.setLevel(level)
421 try:
422 yield
423 finally:
424 logger.setLevel(orig_level)
427@pytest.fixture
428def caplog(request):
429 """Access and control log capturing.
431 Captured logs are available through the following properties/methods::
433 * caplog.messages -> list of format-interpolated log messages
434 * caplog.text -> string containing formatted log output
435 * caplog.records -> list of logging.LogRecord instances
436 * caplog.record_tuples -> list of (logger_name, level, message) tuples
437 * caplog.clear() -> clear captured records and formatted log output string
438 """
439 result = LogCaptureFixture(request.node)
440 yield result
441 result._finalize()
444def get_actual_log_level(config, *setting_names):
445 """Return the actual logging level."""
447 for setting_name in setting_names:
448 log_level = config.getoption(setting_name)
449 if log_level is None:
450 log_level = config.getini(setting_name)
451 if log_level:
452 break
453 else:
454 return
456 if isinstance(log_level, str):
457 log_level = log_level.upper()
458 try:
459 return int(getattr(logging, log_level, log_level))
460 except ValueError:
461 # Python logging does not recognise this as a logging level
462 raise pytest.UsageError(
463 "'{}' is not recognized as a logging level name for "
464 "'{}'. Please consider passing the "
465 "logging level num instead.".format(log_level, setting_name)
466 )
469# run after terminalreporter/capturemanager are configured
470@pytest.hookimpl(trylast=True)
471def pytest_configure(config):
472 config.pluginmanager.register(LoggingPlugin(config), "logging-plugin")
475class LoggingPlugin:
476 """Attaches to the logging module and captures log messages for each test.
477 """
479 def __init__(self, config):
480 """Creates a new plugin to capture log messages.
482 The formatter can be safely shared across all handlers so
483 create a single one for the entire test session here.
484 """
485 self._config = config
487 self.print_logs = get_option_ini(config, "log_print")
488 self.formatter = self._create_formatter(
489 get_option_ini(config, "log_format"),
490 get_option_ini(config, "log_date_format"),
491 get_option_ini(config, "log_auto_indent"),
492 )
493 self.log_level = get_actual_log_level(config, "log_level")
495 self.log_file_level = get_actual_log_level(config, "log_file_level")
496 self.log_file_format = get_option_ini(config, "log_file_format", "log_format")
497 self.log_file_date_format = get_option_ini(
498 config, "log_file_date_format", "log_date_format"
499 )
500 self.log_file_formatter = logging.Formatter(
501 self.log_file_format, datefmt=self.log_file_date_format
502 )
504 log_file = get_option_ini(config, "log_file")
505 if log_file:
506 self.log_file_handler = logging.FileHandler(
507 log_file, mode="w", encoding="UTF-8"
508 )
509 self.log_file_handler.setFormatter(self.log_file_formatter)
510 else:
511 self.log_file_handler = None
513 self.log_cli_handler = None
515 self.live_logs_context = lambda: nullcontext()
516 # Note that the lambda for the live_logs_context is needed because
517 # live_logs_context can otherwise not be entered multiple times due
518 # to limitations of contextlib.contextmanager.
520 if self._log_cli_enabled():
521 self._setup_cli_logging()
523 def _create_formatter(self, log_format, log_date_format, auto_indent):
524 # color option doesn't exist if terminal plugin is disabled
525 color = getattr(self._config.option, "color", "no")
526 if color != "no" and ColoredLevelFormatter.LEVELNAME_FMT_REGEX.search(
527 log_format
528 ):
529 formatter = ColoredLevelFormatter(
530 create_terminal_writer(self._config), log_format, log_date_format
531 ) # type: logging.Formatter
532 else:
533 formatter = logging.Formatter(log_format, log_date_format)
535 formatter._style = PercentStyleMultiline(
536 formatter._style._fmt, auto_indent=auto_indent
537 )
539 return formatter
541 def _setup_cli_logging(self):
542 config = self._config
543 terminal_reporter = config.pluginmanager.get_plugin("terminalreporter")
544 if terminal_reporter is None:
545 # terminal reporter is disabled e.g. by pytest-xdist.
546 return
548 capture_manager = config.pluginmanager.get_plugin("capturemanager")
549 # if capturemanager plugin is disabled, live logging still works.
550 log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter, capture_manager)
552 log_cli_formatter = self._create_formatter(
553 get_option_ini(config, "log_cli_format", "log_format"),
554 get_option_ini(config, "log_cli_date_format", "log_date_format"),
555 get_option_ini(config, "log_auto_indent"),
556 )
558 log_cli_level = get_actual_log_level(config, "log_cli_level", "log_level")
559 self.log_cli_handler = log_cli_handler
560 self.live_logs_context = lambda: catching_logs(
561 log_cli_handler, formatter=log_cli_formatter, level=log_cli_level
562 )
564 def set_log_path(self, fname):
565 """Public method, which can set filename parameter for
566 Logging.FileHandler(). Also creates parent directory if
567 it does not exist.
569 .. warning::
570 Please considered as an experimental API.
571 """
572 fname = Path(fname)
574 if not fname.is_absolute():
575 fname = Path(self._config.rootdir, fname)
577 if not fname.parent.exists():
578 fname.parent.mkdir(exist_ok=True, parents=True)
580 self.log_file_handler = logging.FileHandler(
581 str(fname), mode="w", encoding="UTF-8"
582 )
583 self.log_file_handler.setFormatter(self.log_file_formatter)
585 def _log_cli_enabled(self):
586 """Return True if log_cli should be considered enabled, either explicitly
587 or because --log-cli-level was given in the command-line.
588 """
589 return self._config.getoption(
590 "--log-cli-level"
591 ) is not None or self._config.getini("log_cli")
593 @pytest.hookimpl(hookwrapper=True, tryfirst=True)
594 def pytest_collection(self):
595 with self.live_logs_context():
596 if self.log_cli_handler:
597 self.log_cli_handler.set_when("collection")
599 if self.log_file_handler is not None:
600 with catching_logs(self.log_file_handler, level=self.log_file_level):
601 yield
602 else:
603 yield
605 @contextmanager
606 def _runtest_for(self, item, when):
607 with self._runtest_for_main(item, when):
608 if self.log_file_handler is not None:
609 with catching_logs(self.log_file_handler, level=self.log_file_level):
610 yield
611 else:
612 yield
614 @contextmanager
615 def _runtest_for_main(self, item, when):
616 """Implements the internals of pytest_runtest_xxx() hook."""
617 with catching_logs(
618 LogCaptureHandler(), formatter=self.formatter, level=self.log_level
619 ) as log_handler:
620 if self.log_cli_handler:
621 self.log_cli_handler.set_when(when)
623 if item is None:
624 yield # run the test
625 return
627 if not hasattr(item, "catch_log_handlers"):
628 item.catch_log_handlers = {}
629 item.catch_log_handlers[when] = log_handler
630 item.catch_log_handler = log_handler
631 try:
632 yield # run test
633 finally:
634 if when == "teardown":
635 del item.catch_log_handler
636 del item.catch_log_handlers
638 if self.print_logs:
639 # Add a captured log section to the report.
640 log = log_handler.stream.getvalue().strip()
641 item.add_report_section(when, "log", log)
643 @pytest.hookimpl(hookwrapper=True)
644 def pytest_runtest_setup(self, item):
645 with self._runtest_for(item, "setup"):
646 yield
648 @pytest.hookimpl(hookwrapper=True)
649 def pytest_runtest_call(self, item):
650 with self._runtest_for(item, "call"):
651 yield
653 @pytest.hookimpl(hookwrapper=True)
654 def pytest_runtest_teardown(self, item):
655 with self._runtest_for(item, "teardown"):
656 yield
658 @pytest.hookimpl(hookwrapper=True)
659 def pytest_runtest_logstart(self):
660 if self.log_cli_handler:
661 self.log_cli_handler.reset()
662 with self._runtest_for(None, "start"):
663 yield
665 @pytest.hookimpl(hookwrapper=True)
666 def pytest_runtest_logfinish(self):
667 with self._runtest_for(None, "finish"):
668 yield
670 @pytest.hookimpl(hookwrapper=True)
671 def pytest_runtest_logreport(self):
672 with self._runtest_for(None, "logreport"):
673 yield
675 @pytest.hookimpl(hookwrapper=True, tryfirst=True)
676 def pytest_sessionfinish(self):
677 with self.live_logs_context():
678 if self.log_cli_handler:
679 self.log_cli_handler.set_when("sessionfinish")
680 if self.log_file_handler is not None:
681 try:
682 with catching_logs(
683 self.log_file_handler, level=self.log_file_level
684 ):
685 yield
686 finally:
687 # Close the FileHandler explicitly.
688 # (logging.shutdown might have lost the weakref?!)
689 self.log_file_handler.close()
690 else:
691 yield
693 @pytest.hookimpl(hookwrapper=True, tryfirst=True)
694 def pytest_sessionstart(self):
695 with self.live_logs_context():
696 if self.log_cli_handler:
697 self.log_cli_handler.set_when("sessionstart")
698 if self.log_file_handler is not None:
699 with catching_logs(self.log_file_handler, level=self.log_file_level):
700 yield
701 else:
702 yield
704 @pytest.hookimpl(hookwrapper=True)
705 def pytest_runtestloop(self, session):
706 """Runs all collected test items."""
708 if session.config.option.collectonly:
709 yield
710 return
712 if self._log_cli_enabled() and self._config.getoption("verbose") < 1:
713 # setting verbose flag is needed to avoid messy test progress output
714 self._config.option.verbose = 1
716 with self.live_logs_context():
717 if self.log_file_handler is not None:
718 with catching_logs(self.log_file_handler, level=self.log_file_level):
719 yield # run all the tests
720 else:
721 yield # run all the tests
724class _LiveLoggingStreamHandler(logging.StreamHandler):
725 """
726 Custom StreamHandler used by the live logging feature: it will write a newline before the first log message
727 in each test.
729 During live logging we must also explicitly disable stdout/stderr capturing otherwise it will get captured
730 and won't appear in the terminal.
731 """
733 def __init__(self, terminal_reporter, capture_manager):
734 """
735 :param _pytest.terminal.TerminalReporter terminal_reporter:
736 :param _pytest.capture.CaptureManager capture_manager:
737 """
738 logging.StreamHandler.__init__(self, stream=terminal_reporter)
739 self.capture_manager = capture_manager
740 self.reset()
741 self.set_when(None)
742 self._test_outcome_written = False
744 def reset(self):
745 """Reset the handler; should be called before the start of each test"""
746 self._first_record_emitted = False
748 def set_when(self, when):
749 """Prepares for the given test phase (setup/call/teardown)"""
750 self._when = when
751 self._section_name_shown = False
752 if when == "start":
753 self._test_outcome_written = False
755 def emit(self, record):
756 ctx_manager = (
757 self.capture_manager.global_and_fixture_disabled()
758 if self.capture_manager
759 else nullcontext()
760 )
761 with ctx_manager:
762 if not self._first_record_emitted:
763 self.stream.write("\n")
764 self._first_record_emitted = True
765 elif self._when in ("teardown", "finish"):
766 if not self._test_outcome_written:
767 self._test_outcome_written = True
768 self.stream.write("\n")
769 if not self._section_name_shown and self._when:
770 self.stream.section("live log " + self._when, sep="-", bold=True)
771 self._section_name_shown = True
772 logging.StreamHandler.emit(self, record)