logging.py 13 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396
  1. from __future__ import annotations
  2. import contextlib
  3. import errno
  4. import logging
  5. import logging.handlers
  6. import os
  7. import sys
  8. import threading
  9. from collections.abc import Generator
  10. from dataclasses import dataclass
  11. from io import StringIO, TextIOWrapper
  12. from logging import Filter
  13. from typing import Any, ClassVar
  14. from pip._vendor.rich.console import (
  15. Console,
  16. ConsoleOptions,
  17. ConsoleRenderable,
  18. RenderableType,
  19. RenderResult,
  20. RichCast,
  21. )
  22. from pip._vendor.rich.highlighter import NullHighlighter
  23. from pip._vendor.rich.logging import RichHandler
  24. from pip._vendor.rich.segment import Segment
  25. from pip._vendor.rich.style import Style
  26. from pip._internal.utils._log import VERBOSE, getLogger
  27. from pip._internal.utils.compat import WINDOWS
  28. from pip._internal.utils.deprecation import DEPRECATION_MSG_PREFIX
  29. from pip._internal.utils.misc import StreamWrapper, ensure_dir
  30. _log_state = threading.local()
  31. _stdout_console = None
  32. _stderr_console = None
  33. subprocess_logger = getLogger("pip.subprocessor")
  34. class BrokenStdoutLoggingError(Exception):
  35. """
  36. Raised if BrokenPipeError occurs for the stdout stream while logging.
  37. """
  38. def _is_broken_pipe_error(exc_class: type[BaseException], exc: BaseException) -> bool:
  39. if exc_class is BrokenPipeError:
  40. return True
  41. # On Windows, a broken pipe can show up as EINVAL rather than EPIPE:
  42. # https://bugs.python.org/issue19612
  43. # https://bugs.python.org/issue30418
  44. if not WINDOWS:
  45. return False
  46. return isinstance(exc, OSError) and exc.errno in (errno.EINVAL, errno.EPIPE)
  47. @contextlib.contextmanager
  48. def capture_logging() -> Generator[StringIO, None, None]:
  49. """Capture all pip logs in a buffer temporarily."""
  50. # Patching sys.std(out|err) directly is not viable as the caller
  51. # may want to emit non-logging output (e.g. a rich spinner). To
  52. # avoid capturing that, temporarily patch the root logging handlers
  53. # to use new rich consoles that write to a StringIO.
  54. handlers = {}
  55. for handler in logging.getLogger().handlers:
  56. if isinstance(handler, RichPipStreamHandler):
  57. # Also store the handler's original console so it can be
  58. # restored on context exit.
  59. handlers[handler] = handler.console
  60. fake_stream = StreamWrapper.from_stream(sys.stdout)
  61. if not handlers:
  62. yield fake_stream
  63. return
  64. # HACK: grab no_color attribute from a random handler console since
  65. # it's a global option anyway.
  66. no_color = next(iter(handlers.values())).no_color
  67. fake_console = PipConsole(file=fake_stream, no_color=no_color, soft_wrap=True)
  68. try:
  69. for handler in handlers:
  70. handler.console = fake_console
  71. yield fake_stream
  72. finally:
  73. for handler, original_console in handlers.items():
  74. handler.console = original_console
  75. @contextlib.contextmanager
  76. def indent_log(num: int = 2) -> Generator[None, None, None]:
  77. """
  78. A context manager which will cause the log output to be indented for any
  79. log messages emitted inside it.
  80. """
  81. # For thread-safety
  82. _log_state.indentation = get_indentation()
  83. _log_state.indentation += num
  84. try:
  85. yield
  86. finally:
  87. _log_state.indentation -= num
  88. def get_indentation() -> int:
  89. return getattr(_log_state, "indentation", 0)
  90. class IndentingFormatter(logging.Formatter):
  91. default_time_format = "%Y-%m-%dT%H:%M:%S"
  92. def __init__(
  93. self,
  94. *args: Any,
  95. add_timestamp: bool = False,
  96. **kwargs: Any,
  97. ) -> None:
  98. """
  99. A logging.Formatter that obeys the indent_log() context manager.
  100. :param add_timestamp: A bool indicating output lines should be prefixed
  101. with their record's timestamp.
  102. """
  103. self.add_timestamp = add_timestamp
  104. super().__init__(*args, **kwargs)
  105. def get_message_start(self, formatted: str, levelno: int) -> str:
  106. """
  107. Return the start of the formatted log message (not counting the
  108. prefix to add to each line).
  109. """
  110. if levelno < logging.WARNING:
  111. return ""
  112. if formatted.startswith(DEPRECATION_MSG_PREFIX):
  113. # Then the message already has a prefix. We don't want it to
  114. # look like "WARNING: DEPRECATION: ...."
  115. return ""
  116. if levelno < logging.ERROR:
  117. return "WARNING: "
  118. return "ERROR: "
  119. def format(self, record: logging.LogRecord) -> str:
  120. """
  121. Calls the standard formatter, but will indent all of the log message
  122. lines by our current indentation level.
  123. """
  124. formatted = super().format(record)
  125. message_start = self.get_message_start(formatted, record.levelno)
  126. formatted = message_start + formatted
  127. prefix = ""
  128. if self.add_timestamp:
  129. prefix = f"{self.formatTime(record)} "
  130. prefix += " " * get_indentation()
  131. formatted = "".join([prefix + line for line in formatted.splitlines(True)])
  132. return formatted
  133. @dataclass
  134. class IndentedRenderable:
  135. renderable: RenderableType
  136. indent: int
  137. def __rich_console__(
  138. self, console: Console, options: ConsoleOptions
  139. ) -> RenderResult:
  140. segments = console.render(self.renderable, options)
  141. lines = Segment.split_lines(segments)
  142. for line in lines:
  143. yield Segment(" " * self.indent)
  144. yield from line
  145. yield Segment("\n")
  146. class PipConsole(Console):
  147. def on_broken_pipe(self) -> None:
  148. # Reraise the original exception, rich 13.8.0+ exits by default
  149. # instead, preventing our handler from firing.
  150. raise BrokenPipeError() from None
  151. def get_console(*, stderr: bool = False) -> Console:
  152. if stderr:
  153. assert _stderr_console is not None, "stderr rich console is missing!"
  154. return _stderr_console
  155. else:
  156. assert _stdout_console is not None, "stdout rich console is missing!"
  157. return _stdout_console
  158. class RichPipStreamHandler(RichHandler):
  159. KEYWORDS: ClassVar[list[str] | None] = []
  160. def __init__(self, console: Console) -> None:
  161. super().__init__(
  162. console=console,
  163. show_time=False,
  164. show_level=False,
  165. show_path=False,
  166. highlighter=NullHighlighter(),
  167. )
  168. # Our custom override on Rich's logger, to make things work as we need them to.
  169. def emit(self, record: logging.LogRecord) -> None:
  170. style: Style | None = None
  171. # If we are given a diagnostic error to present, present it with indentation.
  172. if getattr(record, "rich", False):
  173. assert isinstance(record.args, tuple)
  174. (rich_renderable,) = record.args
  175. assert isinstance(
  176. rich_renderable, (ConsoleRenderable, RichCast, str)
  177. ), f"{rich_renderable} is not rich-console-renderable"
  178. renderable: RenderableType = IndentedRenderable(
  179. rich_renderable, indent=get_indentation()
  180. )
  181. else:
  182. message = self.format(record)
  183. renderable = self.render_message(record, message)
  184. if record.levelno is not None:
  185. if record.levelno >= logging.ERROR:
  186. style = Style(color="red")
  187. elif record.levelno >= logging.WARNING:
  188. style = Style(color="yellow")
  189. try:
  190. self.console.print(renderable, overflow="ignore", crop=False, style=style)
  191. except Exception:
  192. self.handleError(record)
  193. def handleError(self, record: logging.LogRecord) -> None:
  194. """Called when logging is unable to log some output."""
  195. exc_class, exc = sys.exc_info()[:2]
  196. # If a broken pipe occurred while calling write() or flush() on the
  197. # stdout stream in logging's Handler.emit(), then raise our special
  198. # exception so we can handle it in main() instead of logging the
  199. # broken pipe error and continuing.
  200. if (
  201. exc_class
  202. and exc
  203. and self.console.file is sys.stdout
  204. and _is_broken_pipe_error(exc_class, exc)
  205. ):
  206. raise BrokenStdoutLoggingError()
  207. return super().handleError(record)
  208. class BetterRotatingFileHandler(logging.handlers.RotatingFileHandler):
  209. def _open(self) -> TextIOWrapper:
  210. ensure_dir(os.path.dirname(self.baseFilename))
  211. return super()._open()
  212. class MaxLevelFilter(Filter):
  213. def __init__(self, level: int) -> None:
  214. self.level = level
  215. def filter(self, record: logging.LogRecord) -> bool:
  216. return record.levelno < self.level
  217. class ExcludeLoggerFilter(Filter):
  218. """
  219. A logging Filter that excludes records from a logger (or its children).
  220. """
  221. def filter(self, record: logging.LogRecord) -> bool:
  222. # The base Filter class allows only records from a logger (or its
  223. # children).
  224. return not super().filter(record)
  225. def setup_logging(verbosity: int, no_color: bool, user_log_file: str | None) -> int:
  226. """Configures and sets up all of the logging
  227. Returns the requested logging level, as its integer value.
  228. """
  229. # Determine the level to be logging at.
  230. if verbosity >= 2:
  231. level_number = logging.DEBUG
  232. elif verbosity == 1:
  233. level_number = VERBOSE
  234. elif verbosity == -1:
  235. level_number = logging.WARNING
  236. elif verbosity == -2:
  237. level_number = logging.ERROR
  238. elif verbosity <= -3:
  239. level_number = logging.CRITICAL
  240. else:
  241. level_number = logging.INFO
  242. level = logging.getLevelName(level_number)
  243. # The "root" logger should match the "console" level *unless* we also need
  244. # to log to a user log file.
  245. include_user_log = user_log_file is not None
  246. if include_user_log:
  247. additional_log_file = user_log_file
  248. root_level = "DEBUG"
  249. else:
  250. additional_log_file = "/dev/null"
  251. root_level = level
  252. # Disable any logging besides WARNING unless we have DEBUG level logging
  253. # enabled for vendored libraries.
  254. vendored_log_level = "WARNING" if level in ["INFO", "ERROR"] else "DEBUG"
  255. # Shorthands for clarity
  256. handler_classes = {
  257. "stream": "pip._internal.utils.logging.RichPipStreamHandler",
  258. "file": "pip._internal.utils.logging.BetterRotatingFileHandler",
  259. }
  260. handlers = ["console", "console_errors", "console_subprocess"] + (
  261. ["user_log"] if include_user_log else []
  262. )
  263. global _stdout_console, stderr_console
  264. _stdout_console = PipConsole(file=sys.stdout, no_color=no_color, soft_wrap=True)
  265. _stderr_console = PipConsole(file=sys.stderr, no_color=no_color, soft_wrap=True)
  266. logging.config.dictConfig(
  267. {
  268. "version": 1,
  269. "disable_existing_loggers": False,
  270. "filters": {
  271. "exclude_warnings": {
  272. "()": "pip._internal.utils.logging.MaxLevelFilter",
  273. "level": logging.WARNING,
  274. },
  275. "restrict_to_subprocess": {
  276. "()": "logging.Filter",
  277. "name": subprocess_logger.name,
  278. },
  279. "exclude_subprocess": {
  280. "()": "pip._internal.utils.logging.ExcludeLoggerFilter",
  281. "name": subprocess_logger.name,
  282. },
  283. },
  284. "formatters": {
  285. "indent": {
  286. "()": IndentingFormatter,
  287. "format": "%(message)s",
  288. },
  289. "indent_with_timestamp": {
  290. "()": IndentingFormatter,
  291. "format": "%(message)s",
  292. "add_timestamp": True,
  293. },
  294. },
  295. "handlers": {
  296. "console": {
  297. "level": level,
  298. "class": handler_classes["stream"],
  299. "console": _stdout_console,
  300. "filters": ["exclude_subprocess", "exclude_warnings"],
  301. "formatter": "indent",
  302. },
  303. "console_errors": {
  304. "level": "WARNING",
  305. "class": handler_classes["stream"],
  306. "console": _stderr_console,
  307. "filters": ["exclude_subprocess"],
  308. "formatter": "indent",
  309. },
  310. # A handler responsible for logging to the console messages
  311. # from the "subprocessor" logger.
  312. "console_subprocess": {
  313. "level": level,
  314. "class": handler_classes["stream"],
  315. "console": _stderr_console,
  316. "filters": ["restrict_to_subprocess"],
  317. "formatter": "indent",
  318. },
  319. "user_log": {
  320. "level": "DEBUG",
  321. "class": handler_classes["file"],
  322. "filename": additional_log_file,
  323. "encoding": "utf-8",
  324. "delay": True,
  325. "formatter": "indent_with_timestamp",
  326. },
  327. },
  328. "root": {
  329. "level": root_level,
  330. "handlers": handlers,
  331. },
  332. "loggers": {"pip._vendor": {"level": vendored_log_level}},
  333. }
  334. )
  335. return level_number