subprocess.py 9.8 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281
  1. import logging
  2. import os
  3. import shlex
  4. import subprocess
  5. from typing import Any, Callable, Iterable, List, Mapping, Optional, Union
  6. from pip._internal.cli.spinners import SpinnerInterface, open_spinner
  7. from pip._internal.exceptions import InstallationSubprocessError
  8. from pip._internal.utils.logging import VERBOSE, subprocess_logger
  9. from pip._internal.utils.misc import HiddenText
  10. CommandArgs = List[Union[str, HiddenText]]
  11. LOG_DIVIDER = "----------------------------------------"
  12. def make_command(*args):
  13. # type: (Union[str, HiddenText, CommandArgs]) -> CommandArgs
  14. """
  15. Create a CommandArgs object.
  16. """
  17. command_args = [] # type: CommandArgs
  18. for arg in args:
  19. # Check for list instead of CommandArgs since CommandArgs is
  20. # only known during type-checking.
  21. if isinstance(arg, list):
  22. command_args.extend(arg)
  23. else:
  24. # Otherwise, arg is str or HiddenText.
  25. command_args.append(arg)
  26. return command_args
  27. def format_command_args(args):
  28. # type: (Union[List[str], CommandArgs]) -> str
  29. """
  30. Format command arguments for display.
  31. """
  32. # For HiddenText arguments, display the redacted form by calling str().
  33. # Also, we don't apply str() to arguments that aren't HiddenText since
  34. # this can trigger a UnicodeDecodeError in Python 2 if the argument
  35. # has type unicode and includes a non-ascii character. (The type
  36. # checker doesn't ensure the annotations are correct in all cases.)
  37. return " ".join(
  38. shlex.quote(str(arg)) if isinstance(arg, HiddenText) else shlex.quote(arg)
  39. for arg in args
  40. )
  41. def reveal_command_args(args):
  42. # type: (Union[List[str], CommandArgs]) -> List[str]
  43. """
  44. Return the arguments in their raw, unredacted form.
  45. """
  46. return [arg.secret if isinstance(arg, HiddenText) else arg for arg in args]
  47. def make_subprocess_output_error(
  48. cmd_args, # type: Union[List[str], CommandArgs]
  49. cwd, # type: Optional[str]
  50. lines, # type: List[str]
  51. exit_status, # type: int
  52. ):
  53. # type: (...) -> str
  54. """
  55. Create and return the error message to use to log a subprocess error
  56. with command output.
  57. :param lines: A list of lines, each ending with a newline.
  58. """
  59. command = format_command_args(cmd_args)
  60. # We know the joined output value ends in a newline.
  61. output = "".join(lines)
  62. msg = (
  63. # Use a unicode string to avoid "UnicodeEncodeError: 'ascii'
  64. # codec can't encode character ..." in Python 2 when a format
  65. # argument (e.g. `output`) has a non-ascii character.
  66. "Command errored out with exit status {exit_status}:\n"
  67. " command: {command_display}\n"
  68. " cwd: {cwd_display}\n"
  69. "Complete output ({line_count} lines):\n{output}{divider}"
  70. ).format(
  71. exit_status=exit_status,
  72. command_display=command,
  73. cwd_display=cwd,
  74. line_count=len(lines),
  75. output=output,
  76. divider=LOG_DIVIDER,
  77. )
  78. return msg
  79. def call_subprocess(
  80. cmd, # type: Union[List[str], CommandArgs]
  81. show_stdout=False, # type: bool
  82. cwd=None, # type: Optional[str]
  83. on_returncode="raise", # type: str
  84. extra_ok_returncodes=None, # type: Optional[Iterable[int]]
  85. command_desc=None, # type: Optional[str]
  86. extra_environ=None, # type: Optional[Mapping[str, Any]]
  87. unset_environ=None, # type: Optional[Iterable[str]]
  88. spinner=None, # type: Optional[SpinnerInterface]
  89. log_failed_cmd=True, # type: Optional[bool]
  90. stdout_only=False, # type: Optional[bool]
  91. ):
  92. # type: (...) -> str
  93. """
  94. Args:
  95. show_stdout: if true, use INFO to log the subprocess's stderr and
  96. stdout streams. Otherwise, use DEBUG. Defaults to False.
  97. extra_ok_returncodes: an iterable of integer return codes that are
  98. acceptable, in addition to 0. Defaults to None, which means [].
  99. unset_environ: an iterable of environment variable names to unset
  100. prior to calling subprocess.Popen().
  101. log_failed_cmd: if false, failed commands are not logged, only raised.
  102. stdout_only: if true, return only stdout, else return both. When true,
  103. logging of both stdout and stderr occurs when the subprocess has
  104. terminated, else logging occurs as subprocess output is produced.
  105. """
  106. if extra_ok_returncodes is None:
  107. extra_ok_returncodes = []
  108. if unset_environ is None:
  109. unset_environ = []
  110. # Most places in pip use show_stdout=False. What this means is--
  111. #
  112. # - We connect the child's output (combined stderr and stdout) to a
  113. # single pipe, which we read.
  114. # - We log this output to stderr at DEBUG level as it is received.
  115. # - If DEBUG logging isn't enabled (e.g. if --verbose logging wasn't
  116. # requested), then we show a spinner so the user can still see the
  117. # subprocess is in progress.
  118. # - If the subprocess exits with an error, we log the output to stderr
  119. # at ERROR level if it hasn't already been displayed to the console
  120. # (e.g. if --verbose logging wasn't enabled). This way we don't log
  121. # the output to the console twice.
  122. #
  123. # If show_stdout=True, then the above is still done, but with DEBUG
  124. # replaced by INFO.
  125. if show_stdout:
  126. # Then log the subprocess output at INFO level.
  127. log_subprocess = subprocess_logger.info
  128. used_level = logging.INFO
  129. else:
  130. # Then log the subprocess output using VERBOSE. This also ensures
  131. # it will be logged to the log file (aka user_log), if enabled.
  132. log_subprocess = subprocess_logger.verbose
  133. used_level = VERBOSE
  134. # Whether the subprocess will be visible in the console.
  135. showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level
  136. # Only use the spinner if we're not showing the subprocess output
  137. # and we have a spinner.
  138. use_spinner = not showing_subprocess and spinner is not None
  139. if command_desc is None:
  140. command_desc = format_command_args(cmd)
  141. log_subprocess("Running command %s", command_desc)
  142. env = os.environ.copy()
  143. if extra_environ:
  144. env.update(extra_environ)
  145. for name in unset_environ:
  146. env.pop(name, None)
  147. try:
  148. proc = subprocess.Popen(
  149. # Convert HiddenText objects to the underlying str.
  150. reveal_command_args(cmd),
  151. stdin=subprocess.PIPE,
  152. stdout=subprocess.PIPE,
  153. stderr=subprocess.STDOUT if not stdout_only else subprocess.PIPE,
  154. cwd=cwd,
  155. env=env,
  156. errors="backslashreplace",
  157. )
  158. except Exception as exc:
  159. if log_failed_cmd:
  160. subprocess_logger.critical(
  161. "Error %s while executing command %s",
  162. exc,
  163. command_desc,
  164. )
  165. raise
  166. all_output = []
  167. if not stdout_only:
  168. assert proc.stdout
  169. assert proc.stdin
  170. proc.stdin.close()
  171. # In this mode, stdout and stderr are in the same pipe.
  172. while True:
  173. line = proc.stdout.readline() # type: str
  174. if not line:
  175. break
  176. line = line.rstrip()
  177. all_output.append(line + "\n")
  178. # Show the line immediately.
  179. log_subprocess(line)
  180. # Update the spinner.
  181. if use_spinner:
  182. assert spinner
  183. spinner.spin()
  184. try:
  185. proc.wait()
  186. finally:
  187. if proc.stdout:
  188. proc.stdout.close()
  189. output = "".join(all_output)
  190. else:
  191. # In this mode, stdout and stderr are in different pipes.
  192. # We must use communicate() which is the only safe way to read both.
  193. out, err = proc.communicate()
  194. # log line by line to preserve pip log indenting
  195. for out_line in out.splitlines():
  196. log_subprocess(out_line)
  197. all_output.append(out)
  198. for err_line in err.splitlines():
  199. log_subprocess(err_line)
  200. all_output.append(err)
  201. output = out
  202. proc_had_error = proc.returncode and proc.returncode not in extra_ok_returncodes
  203. if use_spinner:
  204. assert spinner
  205. if proc_had_error:
  206. spinner.finish("error")
  207. else:
  208. spinner.finish("done")
  209. if proc_had_error:
  210. if on_returncode == "raise":
  211. if not showing_subprocess and log_failed_cmd:
  212. # Then the subprocess streams haven't been logged to the
  213. # console yet.
  214. msg = make_subprocess_output_error(
  215. cmd_args=cmd,
  216. cwd=cwd,
  217. lines=all_output,
  218. exit_status=proc.returncode,
  219. )
  220. subprocess_logger.error(msg)
  221. raise InstallationSubprocessError(proc.returncode, command_desc)
  222. elif on_returncode == "warn":
  223. subprocess_logger.warning(
  224. 'Command "%s" had error code %s in %s',
  225. command_desc,
  226. proc.returncode,
  227. cwd,
  228. )
  229. elif on_returncode == "ignore":
  230. pass
  231. else:
  232. raise ValueError(f"Invalid value: on_returncode={on_returncode!r}")
  233. return output
  234. def runner_with_spinner_message(message):
  235. # type: (str) -> Callable[..., None]
  236. """Provide a subprocess_runner that shows a spinner message.
  237. Intended for use with for pep517's Pep517HookCaller. Thus, the runner has
  238. an API that matches what's expected by Pep517HookCaller.subprocess_runner.
  239. """
  240. def runner(
  241. cmd, # type: List[str]
  242. cwd=None, # type: Optional[str]
  243. extra_environ=None, # type: Optional[Mapping[str, Any]]
  244. ):
  245. # type: (...) -> None
  246. with open_spinner(message) as spinner:
  247. call_subprocess(
  248. cmd,
  249. cwd=cwd,
  250. extra_environ=extra_environ,
  251. spinner=spinner,
  252. )
  253. return runner