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)