logging.py 12 KB

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