def test_console_to_str_warning(monkeypatch): some_bytes = b"a\xE9b" def check_warning(msg, *args, **kwargs): assert msg.startswith( "Subprocess output does not appear to be encoded as") monkeypatch.setattr(locale, 'getpreferredencoding', lambda: 'utf-8') monkeypatch.setattr(pip_compat.logger, 'warning', check_warning) console_to_str(some_bytes)
def test_console_to_str(monkeypatch): some_bytes = b"a\xE9\xC3\xE9b" encodings = ('ascii', 'utf-8', 'iso-8859-1', 'iso-8859-5', 'koi8_r', 'cp850') for e in encodings: monkeypatch.setattr(locale, 'getpreferredencoding', lambda: e) result = console_to_str(some_bytes) assert result.startswith("a") assert result.endswith("b")
def call_subprocess( cmd, # type: Union[List[str], CommandArgs] show_stdout=False, # type: bool cwd=None, # type: Optional[str] on_returncode='raise', # type: str extra_ok_returncodes=None, # type: Optional[Iterable[int]] command_desc=None, # type: Optional[str] extra_environ=None, # type: Optional[Mapping[str, Any]] unset_environ=None, # type: Optional[Iterable[str]] spinner=None, # type: Optional[SpinnerInterface] log_failed_cmd=True # type: Optional[bool] ): # type: (...) -> Text """ Args: show_stdout: if true, use INFO to log the subprocess's stderr and stdout streams. Otherwise, use DEBUG. Defaults to False. extra_ok_returncodes: an iterable of integer return codes that are acceptable, in addition to 0. Defaults to None, which means []. unset_environ: an iterable of environment variable names to unset prior to calling subprocess.Popen(). log_failed_cmd: if false, failed commands are not logged, only raised. """ if extra_ok_returncodes is None: extra_ok_returncodes = [] if unset_environ is None: unset_environ = [] # Most places in pip use show_stdout=False. What this means is-- # # - We connect the child's output (combined stderr and stdout) to a # single pipe, which we read. # - We log this output to stderr at DEBUG level as it is received. # - If DEBUG logging isn't enabled (e.g. if --verbose logging wasn't # requested), then we show a spinner so the user can still see the # subprocess is in progress. # - If the subprocess exits with an error, we log the output to stderr # at ERROR level if it hasn't already been displayed to the console # (e.g. if --verbose logging wasn't enabled). This way we don't log # the output to the console twice. # # If show_stdout=True, then the above is still done, but with DEBUG # replaced by INFO. if show_stdout: # Then log the subprocess output at INFO level. log_subprocess = subprocess_logger.info used_level = logging.INFO else: # Then log the subprocess output using DEBUG. This also ensures # it will be logged to the log file (aka user_log), if enabled. log_subprocess = subprocess_logger.debug used_level = logging.DEBUG # Whether the subprocess will be visible in the console. showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level # Only use the spinner if we're not showing the subprocess output # and we have a spinner. use_spinner = not showing_subprocess and spinner is not None if command_desc is None: command_desc = format_command_args(cmd) log_subprocess("Running command %s", command_desc) env = os.environ.copy() if extra_environ: env.update(extra_environ) for name in unset_environ: env.pop(name, None) try: proc = subprocess.Popen( # Convert HiddenText objects to the underlying str. reveal_command_args(cmd), stderr=subprocess.STDOUT, stdin=subprocess.PIPE, stdout=subprocess.PIPE, cwd=cwd, env=env, ) proc.stdin.close() except Exception as exc: if log_failed_cmd: subprocess_logger.critical( "Error %s while executing command %s", exc, command_desc, ) raise all_output = [] while True: # The "line" value is a unicode string in Python 2. line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + '\n') # Show the line immediately. log_subprocess(line) # Update the spinner. if use_spinner: spinner.spin() try: proc.wait() finally: if proc.stdout: proc.stdout.close() proc_had_error = (proc.returncode and proc.returncode not in extra_ok_returncodes) if use_spinner: if proc_had_error: spinner.finish("error") else: spinner.finish("done") if proc_had_error: if on_returncode == 'raise': if not showing_subprocess and log_failed_cmd: # Then the subprocess streams haven't been logged to the # console yet. msg = make_subprocess_output_error( cmd_args=cmd, cwd=cwd, lines=all_output, exit_status=proc.returncode, ) subprocess_logger.error(msg) exc_msg = ('Command errored out with exit status {}: {} ' 'Check the logs for full command output.').format( proc.returncode, command_desc) raise InstallationError(exc_msg) elif on_returncode == 'warn': subprocess_logger.warning( 'Command "{}" had error code {} in {}'.format( command_desc, proc.returncode, cwd)) elif on_returncode == 'ignore': pass else: raise ValueError( 'Invalid value: on_returncode={!r}'.format(on_returncode)) return ''.join(all_output)
def call_subprocess( cmd, # type: Union[List[str], CommandArgs] cwd=None, # type: Optional[str] extra_environ=None, # type: Optional[Mapping[str, Any]] extra_ok_returncodes=None, # type: Optional[Iterable[int]] log_failed_cmd=True, # type: Optional[bool] ): # type: (...) -> Text """ Args: extra_ok_returncodes: an iterable of integer return codes that are acceptable, in addition to 0. Defaults to None, which means []. log_failed_cmd: if false, failed commands are not logged, only raised. """ if extra_ok_returncodes is None: extra_ok_returncodes = [] # log the subprocess output at DEBUG level. log_subprocess = subprocess_logger.debug env = os.environ.copy() if extra_environ: env.update(extra_environ) # Whether the subprocess will be visible in the console. showing_subprocess = True command_desc = format_command_args(cmd) try: proc = subprocess.Popen( # Convert HiddenText objects to the underlying str. reveal_command_args(cmd), stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=cwd, ) if proc.stdin: proc.stdin.close() except Exception as exc: if log_failed_cmd: subprocess_logger.critical( "Error %s while executing command %s", exc, command_desc, ) raise all_output = [] while True: # The "line" value is a unicode string in Python 2. line = None if proc.stdout: line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + "\n") # Show the line immediately. log_subprocess(line) try: proc.wait() finally: if proc.stdout: proc.stdout.close() proc_had_error = proc.returncode and proc.returncode not in extra_ok_returncodes if proc_had_error: if not showing_subprocess and log_failed_cmd: # Then the subprocess streams haven't been logged to the # console yet. msg = make_subprocess_output_error( cmd_args=cmd, cwd=cwd, lines=all_output, exit_status=proc.returncode, ) subprocess_logger.error(msg) exc_msg = ( "Command errored out with exit status {}: {} " "Check the logs for full command output." ).format(proc.returncode, command_desc) raise SubProcessError(exc_msg) return "".join(all_output)
def call_subprocess( cmd, # type: List[str] show_stdout=False, # type: bool cwd=None, # type: Optional[str] on_returncode='raise', # type: str extra_ok_returncodes=None, # type: Optional[Iterable[int]] command_desc=None, # type: Optional[str] extra_environ=None, # type: Optional[Mapping[str, Any]] unset_environ=None, # type: Optional[Iterable[str]] spinner=None # type: Optional[SpinnerInterface] ): # type: (...) -> Optional[Text] """ Args: extra_ok_returncodes: an iterable of integer return codes that are acceptable, in addition to 0. Defaults to None, which means []. unset_environ: an iterable of environment variable names to unset prior to calling subprocess.Popen(). """ if extra_ok_returncodes is None: extra_ok_returncodes = [] if unset_environ is None: unset_environ = [] # This function's handling of subprocess output is confusing and I # previously broke it terribly, so as penance I will write a long comment # explaining things. # # The obvious thing that affects output is the show_stdout= # kwarg. show_stdout=True means, let the subprocess write directly to our # stdout. It is almost never used # inside pip (and should not be used in new code without a very good # reason); as of 2016-02-22 it is only used in a few places inside the VCS # wrapper code. Ideally we should get rid of it entirely, because it # creates a lot of complexity here for a rarely used feature. # # Most places in pip use show_stdout=False. What this means is: # - We connect the child stdout to a pipe, which we read. # - By default, we hide the output but show a spinner -- unless the # subprocess exits with an error, in which case we show the output. # - If the --verbose option was passed (= loglevel is DEBUG), then we show # the output unconditionally. (But in this case we don't want to show # the output a second time if it turns out that there was an error.) # # stderr is always merged with stdout (even if show_stdout=True). if show_stdout: stdout = None else: stdout = subprocess.PIPE if command_desc is None: command_desc = format_command_args(cmd) logger.debug("Running command %s", command_desc) env = os.environ.copy() if extra_environ: env.update(extra_environ) for name in unset_environ: env.pop(name, None) try: proc = subprocess.Popen( cmd, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, stdout=stdout, cwd=cwd, env=env, ) proc.stdin.close() except Exception as exc: logger.critical( "Error %s while executing command %s", exc, command_desc, ) raise all_output = [] if stdout is not None: while True: line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + '\n') if logger.getEffectiveLevel() <= std_logging.DEBUG: # Show the line immediately logger.debug(line) else: # Update the spinner if spinner is not None: spinner.spin() try: proc.wait() finally: if proc.stdout: proc.stdout.close() if spinner is not None: if proc.returncode: spinner.finish("error") else: spinner.finish("done") if proc.returncode and proc.returncode not in extra_ok_returncodes: if on_returncode == 'raise': if (logger.getEffectiveLevel() > std_logging.DEBUG and not show_stdout): logger.info( 'Complete output from command %s:', command_desc, ) # The all_output value already ends in a newline. logger.info(''.join(all_output) + LOG_DIVIDER) raise InstallationError( 'Command "%s" failed with error code %s in %s' % (command_desc, proc.returncode, cwd)) elif on_returncode == 'warn': logger.warning( 'Command "%s" had error code %s in %s', command_desc, proc.returncode, cwd, ) elif on_returncode == 'ignore': pass else: raise ValueError('Invalid value: on_returncode=%s' % repr(on_returncode)) if not show_stdout: return ''.join(all_output) return None
def call_subprocess( cmd, # type: List[str] show_stdout=False, # type: bool cwd=None, # type: Optional[str] on_returncode='raise', # type: str extra_ok_returncodes=None, # type: Optional[Iterable[int]] command_desc=None, # type: Optional[str] extra_environ=None, # type: Optional[Mapping[str, Any]] unset_environ=None, # type: Optional[Iterable[str]] spinner=None # type: Optional[SpinnerInterface] ): # type: (...) -> Optional[Text] """ Args: show_stdout: if true, use INFO to log the subprocess's stderr and stdout streams. Otherwise, use DEBUG. Defaults to False. extra_ok_returncodes: an iterable of integer return codes that are acceptable, in addition to 0. Defaults to None, which means []. unset_environ: an iterable of environment variable names to unset prior to calling subprocess.Popen(). """ if extra_ok_returncodes is None: extra_ok_returncodes = [] if unset_environ is None: unset_environ = [] # Most places in pip use show_stdout=False. What this means is-- # # - We connect the child's output (combined stderr and stdout) to a # single pipe, which we read. # - We log this output to stderr at DEBUG level as it is received. # - If DEBUG logging isn't enabled (e.g. if --verbose logging wasn't # requested), then we show a spinner so the user can still see the # subprocess is in progress. # - If the subprocess exits with an error, we log the output to stderr # at ERROR level if it hasn't already been displayed to the console # (e.g. if --verbose logging wasn't enabled). This way we don't log # the output to the console twice. # # If show_stdout=True, then the above is still done, but with DEBUG # replaced by INFO. if show_stdout: # Then log the subprocess output at INFO level. log_subprocess = subprocess_logger.info used_level = std_logging.INFO else: # Then log the subprocess output using DEBUG. This also ensures # it will be logged to the log file (aka user_log), if enabled. log_subprocess = subprocess_logger.debug used_level = std_logging.DEBUG # Whether the subprocess will be visible in the console. showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level # Only use the spinner if we're not showing the subprocess output # and we have a spinner. use_spinner = not showing_subprocess and spinner is not None if command_desc is None: command_desc = format_command_args(cmd) log_subprocess("Running command %s", command_desc) env = os.environ.copy() if extra_environ: env.update(extra_environ) for name in unset_environ: env.pop(name, None) # iOS: store previous directory currentDir = os.getcwd() try: proc = subprocess.Popen( cmd, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, stdout=subprocess.PIPE, cwd=cwd, env=env, ) proc.stdin.close() except Exception as exc: subprocess_logger.critical( "Error %s while executing command %s", exc, command_desc, ) raise all_output = [] while True: line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + '\n') # Show the line immediately. log_subprocess(line) # Update the spinner. if use_spinner: spinner.spin() try: proc.wait() finally: if proc.stdout: proc.stdout.close() # iOS: change back to previous directory os.chdir(currentDir) proc_had_error = (proc.returncode and proc.returncode not in extra_ok_returncodes) if use_spinner: if proc_had_error: spinner.finish("error") else: spinner.finish("done") if proc_had_error: if on_returncode == 'raise': if not showing_subprocess: # Then the subprocess streams haven't been logged to the # console yet. subprocess_logger.error( 'Complete output from command %s:', command_desc, ) # The all_output value already ends in a newline. subprocess_logger.error(''.join(all_output) + LOG_DIVIDER) raise InstallationError( 'Command "%s" failed with error code %s in %s' % (command_desc, proc.returncode, cwd)) elif on_returncode == 'warn': subprocess_logger.warning( 'Command "%s" had error code %s in %s', command_desc, proc.returncode, cwd, ) elif on_returncode == 'ignore': pass else: raise ValueError('Invalid value: on_returncode=%s' % repr(on_returncode)) return ''.join(all_output)
def call_subprocess( cmd, show_stdout=True, cwd=None, on_returncode="raise", command_desc=None, extra_environ=None, unset_environ=None, spinner=None, ): """ Args: unset_environ: an iterable of environment variable names to unset prior to calling subprocess.Popen(). """ if unset_environ is None: unset_environ = [] # This function's handling of subprocess output is confusing and I # previously broke it terribly, so as penance I will write a long comment # explaining things. # # The obvious thing that affects output is the show_stdout= # kwarg. show_stdout=True means, let the subprocess write directly to our # stdout. Even though it is nominally the default, it is almost never used # inside pip (and should not be used in new code without a very good # reason); as of 2016-02-22 it is only used in a few places inside the VCS # wrapper code. Ideally we should get rid of it entirely, because it # creates a lot of complexity here for a rarely used feature. # # Most places in pip set show_stdout=False. What this means is: # - We connect the child stdout to a pipe, which we read. # - By default, we hide the output but show a spinner -- unless the # subprocess exits with an error, in which case we show the output. # - If the --verbose option was passed (= loglevel is DEBUG), then we show # the output unconditionally. (But in this case we don't want to show # the output a second time if it turns out that there was an error.) # # stderr is always merged with stdout (even if show_stdout=True). if show_stdout: stdout = None else: stdout = subprocess.PIPE if command_desc is None: cmd_parts = [] for part in cmd: if " " in part or "\n" in part or '"' in part or "'" in part: part = '"%s"' % part.replace('"', '\\"') cmd_parts.append(part) command_desc = " ".join(cmd_parts) logger.debug("Running command %s", command_desc) env = os.environ.copy() if extra_environ: env.update(extra_environ) for name in unset_environ: env.pop(name, None) try: proc = subprocess.Popen( cmd, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, stdout=stdout, cwd=cwd, env=env, ) proc.stdin.close() except Exception as exc: logger.critical("Error %s while executing command %s", exc, command_desc) raise all_output = [] if stdout is not None: while True: line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + "\n") if logger.getEffectiveLevel() <= std_logging.DEBUG: # Show the line immediately logger.debug(line) else: # Update the spinner if spinner is not None: spinner.spin() try: proc.wait() finally: if proc.stdout: proc.stdout.close() if spinner is not None: if proc.returncode: spinner.finish("error") else: spinner.finish("done") if proc.returncode: if on_returncode == "raise": if logger.getEffectiveLevel( ) > std_logging.DEBUG and not show_stdout: logger.info("Complete output from command %s:", command_desc) logger.info("".join(all_output) + "\n----------------------------------------") raise InstallationError( 'Command "%s" failed with error code %s in %s' % (command_desc, proc.returncode, cwd)) elif on_returncode == "warn": logger.warning( 'Command "%s" had error code %s in %s', command_desc, proc.returncode, cwd, ) elif on_returncode == "ignore": pass else: raise ValueError("Invalid value: on_returncode=%s" % repr(on_returncode)) if not show_stdout: return "".join(all_output)
cwd=cwd ) if proc.stdin: proc.stdin.close() except Exception as exc: if log_failed_cmd: subprocess_logger.critical( "Error %s while executing command %s", exc, command_desc, ) raise all_output = [] while True: # The "line" value is a unicode string in Python 2. line = None if proc.stdout: line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + '\n') # Show the line immediately. log_subprocess(line) try: proc.wait() finally: if proc.stdout: proc.stdout.close() <<<<<<< HEAD if proc.stderr: proc.stderr.close()
def call_subprocess( cmd, # type: List[str] show_stdout=False, # type: bool cwd=None, # type: Optional[str] on_returncode='raise', # type: str extra_ok_returncodes=None, # type: Optional[Iterable[int]] command_desc=None, # type: Optional[str] extra_environ=None, # type: Optional[Mapping[str, Any]] unset_environ=None, # type: Optional[Iterable[str]] spinner=None # type: Optional[SpinnerInterface] ): # type: (...) -> Optional[Text] """ Args: show_stdout: if true, use INFO to log the subprocess's stderr and stdout streams. Otherwise, use DEBUG. Defaults to False. extra_ok_returncodes: an iterable of integer return codes that are acceptable, in addition to 0. Defaults to None, which means []. unset_environ: an iterable of environment variable names to unset prior to calling subprocess.Popen(). """ if extra_ok_returncodes is None: extra_ok_returncodes = [] if unset_environ is None: unset_environ = [] # Most places in pip use show_stdout=False. What this means is-- # # - We connect the child's output (combined stderr and stdout) to a # single pipe, which we read. # - We log this output to stderr at DEBUG level as it is received. # - If DEBUG logging isn't enabled (e.g. if --verbose logging wasn't # requested), then we show a spinner so the user can still see the # subprocess is in progress. # - If the subprocess exits with an error, we log the output to stderr # at ERROR level if it hasn't already been displayed to the console # (e.g. if --verbose logging wasn't enabled). This way we don't log # the output to the console twice. # # If show_stdout=True, then the above is still done, but with DEBUG # replaced by INFO. if show_stdout: # Then log the subprocess output at INFO level. log_subprocess = subprocess_logger.info used_level = std_logging.INFO else: # Then log the subprocess output using DEBUG. This also ensures # it will be logged to the log file (aka user_log), if enabled. log_subprocess = subprocess_logger.debug used_level = std_logging.DEBUG # Whether the subprocess will be visible in the console. showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level # Only use the spinner if we're not showing the subprocess output # and we have a spinner. use_spinner = not showing_subprocess and spinner is not None if command_desc is None: command_desc = format_command_args(cmd) log_subprocess("Running command %s", command_desc) env = os.environ.copy() if extra_environ: env.update(extra_environ) for name in unset_environ: env.pop(name, None) try: proc = subprocess.Popen( cmd, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, stdout=subprocess.PIPE, cwd=cwd, env=env, ) proc.stdin.close() except Exception as exc: subprocess_logger.critical( "Error %s while executing command %s", exc, command_desc, ) raise all_output = [] while True: line = console_to_str(proc.stdout.readline()) if not line: break line = line.rstrip() all_output.append(line + '\n') # Show the line immediately. log_subprocess(line) # Update the spinner. if use_spinner: spinner.spin() try: proc.wait() finally: if proc.stdout: proc.stdout.close() proc_had_error = ( proc.returncode and proc.returncode not in extra_ok_returncodes ) if use_spinner: if proc_had_error: spinner.finish("error") else: spinner.finish("done") if proc_had_error: if on_returncode == 'raise': if not showing_subprocess: # Then the subprocess streams haven't been logged to the # console yet. subprocess_logger.error( 'Complete output from command %s:', command_desc, ) # The all_output value already ends in a newline. subprocess_logger.error(''.join(all_output) + LOG_DIVIDER) raise InstallationError( 'Command "%s" failed with error code %s in %s' % (command_desc, proc.returncode, cwd)) elif on_returncode == 'warn': subprocess_logger.warning( 'Command "%s" had error code %s in %s', command_desc, proc.returncode, cwd, ) elif on_returncode == 'ignore': pass else: raise ValueError('Invalid value: on_returncode=%s' % repr(on_returncode)) return ''.join(all_output)