logging.py 11 KB

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