logging.py 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387
  1. import contextlib
  2. import errno
  3. import logging
  4. import logging.handlers
  5. import os
  6. import sys
  7. from logging import Filter, getLogger
  8. from typing import IO, Any, Callable, Iterator, Optional, TextIO, Type, cast
  9. from pip._internal.utils.compat import WINDOWS
  10. from pip._internal.utils.deprecation import DEPRECATION_MSG_PREFIX
  11. from pip._internal.utils.misc import ensure_dir
  12. try:
  13. import threading
  14. except ImportError:
  15. import dummy_threading as threading # type: ignore
  16. try:
  17. from pip._vendor import colorama
  18. # Lots of different errors can come from this, including SystemError and
  19. # ImportError.
  20. except Exception:
  21. colorama = None
  22. _log_state = threading.local()
  23. subprocess_logger = getLogger("pip.subprocessor")
  24. class BrokenStdoutLoggingError(Exception):
  25. """
  26. Raised if BrokenPipeError occurs for the stdout stream while logging.
  27. """
  28. pass
  29. # BrokenPipeError manifests differently in Windows and non-Windows.
  30. if WINDOWS:
  31. # In Windows, a broken pipe can show up as EINVAL rather than EPIPE:
  32. # https://bugs.python.org/issue19612
  33. # https://bugs.python.org/issue30418
  34. def _is_broken_pipe_error(exc_class, exc):
  35. # type: (Type[BaseException], BaseException) -> bool
  36. """See the docstring for non-Windows below."""
  37. return (exc_class is BrokenPipeError) or (
  38. isinstance(exc, OSError) and exc.errno in (errno.EINVAL, errno.EPIPE)
  39. )
  40. else:
  41. # Then we are in the non-Windows case.
  42. def _is_broken_pipe_error(exc_class, exc):
  43. # type: (Type[BaseException], BaseException) -> bool
  44. """
  45. Return whether an exception is a broken pipe error.
  46. Args:
  47. exc_class: an exception class.
  48. exc: an exception instance.
  49. """
  50. return exc_class is BrokenPipeError
  51. @contextlib.contextmanager
  52. def indent_log(num=2):
  53. # type: (int) -> Iterator[None]
  54. """
  55. A context manager which will cause the log output to be indented for any
  56. log messages emitted inside it.
  57. """
  58. # For thread-safety
  59. _log_state.indentation = get_indentation()
  60. _log_state.indentation += num
  61. try:
  62. yield
  63. finally:
  64. _log_state.indentation -= num
  65. def get_indentation():
  66. # type: () -> int
  67. return getattr(_log_state, "indentation", 0)
  68. class IndentingFormatter(logging.Formatter):
  69. default_time_format = "%Y-%m-%dT%H:%M:%S"
  70. def __init__(
  71. self,
  72. *args, # type: Any
  73. add_timestamp=False, # type: bool
  74. **kwargs, # type: Any
  75. ):
  76. # type: (...) -> None
  77. """
  78. A logging.Formatter that obeys the indent_log() context manager.
  79. :param add_timestamp: A bool indicating output lines should be prefixed
  80. with their record's timestamp.
  81. """
  82. self.add_timestamp = add_timestamp
  83. super().__init__(*args, **kwargs)
  84. def get_message_start(self, formatted, levelno):
  85. # type: (str, int) -> str
  86. """
  87. Return the start of the formatted log message (not counting the
  88. prefix to add to each line).
  89. """
  90. if levelno < logging.WARNING:
  91. return ""
  92. if formatted.startswith(DEPRECATION_MSG_PREFIX):
  93. # Then the message already has a prefix. We don't want it to
  94. # look like "WARNING: DEPRECATION: ...."
  95. return ""
  96. if levelno < logging.ERROR:
  97. return "WARNING: "
  98. return "ERROR: "
  99. def format(self, record):
  100. # type: (logging.LogRecord) -> str
  101. """
  102. Calls the standard formatter, but will indent all of the log message
  103. lines by our current indentation level.
  104. """
  105. formatted = super().format(record)
  106. message_start = self.get_message_start(formatted, record.levelno)
  107. formatted = message_start + formatted
  108. prefix = ""
  109. if self.add_timestamp:
  110. prefix = f"{self.formatTime(record)} "
  111. prefix += " " * get_indentation()
  112. formatted = "".join([prefix + line for line in formatted.splitlines(True)])
  113. return formatted
  114. def _color_wrap(*colors):
  115. # type: (*str) -> Callable[[str], str]
  116. def wrapped(inp):
  117. # type: (str) -> str
  118. return "".join(list(colors) + [inp, colorama.Style.RESET_ALL])
  119. return wrapped
  120. class ColorizedStreamHandler(logging.StreamHandler):
  121. # Don't build up a list of colors if we don't have colorama
  122. if colorama:
  123. COLORS = [
  124. # This needs to be in order from highest logging level to lowest.
  125. (logging.ERROR, _color_wrap(colorama.Fore.RED)),
  126. (logging.WARNING, _color_wrap(colorama.Fore.YELLOW)),
  127. ]
  128. else:
  129. COLORS = []
  130. def __init__(self, stream=None, no_color=None):
  131. # type: (Optional[TextIO], bool) -> None
  132. super().__init__(stream)
  133. self._no_color = no_color
  134. if WINDOWS and colorama:
  135. self.stream = colorama.AnsiToWin32(self.stream)
  136. def _using_stdout(self):
  137. # type: () -> bool
  138. """
  139. Return whether the handler is using sys.stdout.
  140. """
  141. if WINDOWS and colorama:
  142. # Then self.stream is an AnsiToWin32 object.
  143. stream = cast(colorama.AnsiToWin32, self.stream)
  144. return stream.wrapped is sys.stdout
  145. return self.stream is sys.stdout
  146. def should_color(self):
  147. # type: () -> bool
  148. # Don't colorize things if we do not have colorama or if told not to
  149. if not colorama or self._no_color:
  150. return False
  151. real_stream = (
  152. self.stream
  153. if not isinstance(self.stream, colorama.AnsiToWin32)
  154. else self.stream.wrapped
  155. )
  156. # If the stream is a tty we should color it
  157. if hasattr(real_stream, "isatty") and real_stream.isatty():
  158. return True
  159. # If we have an ANSI term we should color it
  160. if os.environ.get("TERM") == "ANSI":
  161. return True
  162. # If anything else we should not color it
  163. return False
  164. def format(self, record):
  165. # type: (logging.LogRecord) -> str
  166. msg = super().format(record)
  167. if self.should_color():
  168. for level, color in self.COLORS:
  169. if record.levelno >= level:
  170. msg = color(msg)
  171. break
  172. return msg
  173. # The logging module says handleError() can be customized.
  174. def handleError(self, record):
  175. # type: (logging.LogRecord) -> None
  176. exc_class, exc = sys.exc_info()[:2]
  177. # If a broken pipe occurred while calling write() or flush() on the
  178. # stdout stream in logging's Handler.emit(), then raise our special
  179. # exception so we can handle it in main() instead of logging the
  180. # broken pipe error and continuing.
  181. if (
  182. exc_class
  183. and exc
  184. and self._using_stdout()
  185. and _is_broken_pipe_error(exc_class, exc)
  186. ):
  187. raise BrokenStdoutLoggingError()
  188. return super().handleError(record)
  189. class BetterRotatingFileHandler(logging.handlers.RotatingFileHandler):
  190. def _open(self):
  191. # type: () -> IO[Any]
  192. ensure_dir(os.path.dirname(self.baseFilename))
  193. return super()._open()
  194. class MaxLevelFilter(Filter):
  195. def __init__(self, level):
  196. # type: (int) -> None
  197. self.level = level
  198. def filter(self, record):
  199. # type: (logging.LogRecord) -> bool
  200. return record.levelno < self.level
  201. class ExcludeLoggerFilter(Filter):
  202. """
  203. A logging Filter that excludes records from a logger (or its children).
  204. """
  205. def filter(self, record):
  206. # type: (logging.LogRecord) -> bool
  207. # The base Filter class allows only records from a logger (or its
  208. # children).
  209. return not super().filter(record)
  210. def setup_logging(verbosity, no_color, user_log_file):
  211. # type: (int, bool, Optional[str]) -> int
  212. """Configures and sets up all of the logging
  213. Returns the requested logging level, as its integer value.
  214. """
  215. # Determine the level to be logging at.
  216. if verbosity >= 1:
  217. level = "DEBUG"
  218. elif verbosity == -1:
  219. level = "WARNING"
  220. elif verbosity == -2:
  221. level = "ERROR"
  222. elif verbosity <= -3:
  223. level = "CRITICAL"
  224. else:
  225. level = "INFO"
  226. level_number = getattr(logging, level)
  227. # The "root" logger should match the "console" level *unless* we also need
  228. # to log to a user log file.
  229. include_user_log = user_log_file is not None
  230. if include_user_log:
  231. additional_log_file = user_log_file
  232. root_level = "DEBUG"
  233. else:
  234. additional_log_file = "/dev/null"
  235. root_level = level
  236. # Disable any logging besides WARNING unless we have DEBUG level logging
  237. # enabled for vendored libraries.
  238. vendored_log_level = "WARNING" if level in ["INFO", "ERROR"] else "DEBUG"
  239. # Shorthands for clarity
  240. log_streams = {
  241. "stdout": "ext://sys.stdout",
  242. "stderr": "ext://sys.stderr",
  243. }
  244. handler_classes = {
  245. "stream": "pip._internal.utils.logging.ColorizedStreamHandler",
  246. "file": "pip._internal.utils.logging.BetterRotatingFileHandler",
  247. }
  248. handlers = ["console", "console_errors", "console_subprocess"] + (
  249. ["user_log"] if include_user_log else []
  250. )
  251. logging.config.dictConfig(
  252. {
  253. "version": 1,
  254. "disable_existing_loggers": False,
  255. "filters": {
  256. "exclude_warnings": {
  257. "()": "pip._internal.utils.logging.MaxLevelFilter",
  258. "level": logging.WARNING,
  259. },
  260. "restrict_to_subprocess": {
  261. "()": "logging.Filter",
  262. "name": subprocess_logger.name,
  263. },
  264. "exclude_subprocess": {
  265. "()": "pip._internal.utils.logging.ExcludeLoggerFilter",
  266. "name": subprocess_logger.name,
  267. },
  268. },
  269. "formatters": {
  270. "indent": {
  271. "()": IndentingFormatter,
  272. "format": "%(message)s",
  273. },
  274. "indent_with_timestamp": {
  275. "()": IndentingFormatter,
  276. "format": "%(message)s",
  277. "add_timestamp": True,
  278. },
  279. },
  280. "handlers": {
  281. "console": {
  282. "level": level,
  283. "class": handler_classes["stream"],
  284. "no_color": no_color,
  285. "stream": log_streams["stdout"],
  286. "filters": ["exclude_subprocess", "exclude_warnings"],
  287. "formatter": "indent",
  288. },
  289. "console_errors": {
  290. "level": "WARNING",
  291. "class": handler_classes["stream"],
  292. "no_color": no_color,
  293. "stream": log_streams["stderr"],
  294. "filters": ["exclude_subprocess"],
  295. "formatter": "indent",
  296. },
  297. # A handler responsible for logging to the console messages
  298. # from the "subprocessor" logger.
  299. "console_subprocess": {
  300. "level": level,
  301. "class": handler_classes["stream"],
  302. "no_color": no_color,
  303. "stream": log_streams["stderr"],
  304. "filters": ["restrict_to_subprocess"],
  305. "formatter": "indent",
  306. },
  307. "user_log": {
  308. "level": "DEBUG",
  309. "class": handler_classes["file"],
  310. "filename": additional_log_file,
  311. "delay": True,
  312. "formatter": "indent_with_timestamp",
  313. },
  314. },
  315. "root": {
  316. "level": root_level,
  317. "handlers": handlers,
  318. },
  319. "loggers": {"pip._vendor": {"level": vendored_log_level}},
  320. }
  321. )
  322. return level_number