logging.py 13 KB

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