Merge pull request #6290 from cjerdonek/add-format-command

Add format_command_args().

news/6290.feature

@@ -0,0 +1,2 @@
+Command arguments in ``subprocess`` log messages are now quoted using
+``shlex.quote()``.

src/pip/_internal/utils/misc.py

@@ -22,7 +22,7 @@ from pip._vendor import pkg_resources
 #       why we ignore the type on this import.
 from pip._vendor.retrying import retry  # type: ignore
 from pip._vendor.six import PY2
-from pip._vendor.six.moves import input
+from pip._vendor.six.moves import input, shlex_quote
 from pip._vendor.six.moves.urllib import parse as urllib_parse
 from pip._vendor.six.moves.urllib.parse import unquote as urllib_unquote
 
@@ -66,6 +66,8 @@ __all__ = ['rmtree', 'display_path', 'backup_dir',
 
 logger = std_logging.getLogger(__name__)
 
+LOG_DIVIDER = '----------------------------------------'
+
 WHEEL_EXTENSION = '.whl'
 BZ2_EXTENSIONS = ('.tar.bz2', '.tbz')
 XZ_EXTENSIONS = ('.tar.xz', '.txz', '.tlz', '.tar.lz', '.tar.lzma')
@@ -647,6 +649,14 @@ def unpack_file(
         )
 
 
+def format_command_args(args):
+    # type: (List[str]) -> str
+    """
+    Format command arguments for display.
+    """
+    return ' '.join(shlex_quote(arg) for arg in args)
+
+
 def call_subprocess(
     cmd,  # type: List[str]
     show_stdout=False,  # type: bool
@@ -696,12 +706,8 @@ def call_subprocess(
     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)
+        command_desc = format_command_args(cmd)
+
     logger.debug("Running command %s", command_desc)
     env = os.environ.copy()
     if extra_environ:
@@ -751,10 +757,8 @@ def call_subprocess(
                 logger.info(
                     'Complete output from command %s:', command_desc,
                 )
-                logger.info(
-                    ''.join(all_output) +
-                    '\n----------------------------------------'
-                )
+                # 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))

src/pip/_internal/wheel.py

@@ -33,7 +33,8 @@ from pip._internal.locations import (
 from pip._internal.models.link import Link
 from pip._internal.utils.logging import indent_log
 from pip._internal.utils.misc import (
-    call_subprocess, captured_stdout, ensure_dir, read_chunks,
+    LOG_DIVIDER, call_subprocess, captured_stdout, ensure_dir,
+    format_command_args, read_chunks,
 )
 from pip._internal.utils.setuptools_build import SETUPTOOLS_SHIM
 from pip._internal.utils.temp_dir import TempDirectory
@@ -785,7 +786,7 @@ def should_use_ephemeral_cache(
     return True
 
 
-def format_command(
+def format_command_result(
     command_args,  # type: List[str]
     command_output,  # type: str
 ):
@@ -793,7 +794,8 @@ def format_command(
     """
     Format command information for logging.
     """
-    text = 'Command arguments: {}\n'.format(command_args)
+    command_desc = format_command_args(command_args)
+    text = 'Command arguments: {}\n'.format(command_desc)
 
     if not command_output:
         text += 'Command output: None'
@@ -802,10 +804,7 @@ def format_command(
     else:
         if not command_output.endswith('\n'):
             command_output += '\n'
-        text += (
-            'Command output:\n{}'
-            '-----------------------------------------'
-        ).format(command_output)
+        text += 'Command output:\n{}{}'.format(command_output, LOG_DIVIDER)
 
     return text
 
@@ -827,7 +826,7 @@ def get_legacy_build_wheel_path(
         msg = (
             'Legacy build of wheel for {!r} created no files.\n'
         ).format(req.name)
-        msg += format_command(command_args, command_output)
+        msg += format_command_result(command_args, command_output)
         logger.warning(msg)
         return None
 
@@ -836,7 +835,7 @@ def get_legacy_build_wheel_path(
             'Legacy build of wheel for {!r} created more than one file.\n'
             'Filenames (choosing first): {}\n'
         ).format(req.name, names)
-        msg += format_command(command_args, command_output)
+        msg += format_command_result(command_args, command_output)
         logger.warning(msg)
 
     return os.path.join(temp_dir, names[0])

tests/unit/test_utils.py

@@ -24,10 +24,11 @@ from pip._internal.utils.encoding import auto_decode
 from pip._internal.utils.glibc import check_glibc_version
 from pip._internal.utils.hashes import Hashes, MissingHashes
 from pip._internal.utils.misc import (
-    call_subprocess, egg_link_path, ensure_dir, get_installed_distributions,
-    get_prog, make_vcs_requirement_url, normalize_path, redact_netloc,
-    redact_password_from_url, remove_auth_from_url, rmtree,
-    split_auth_from_netloc, untar_file, unzip_file,
+    call_subprocess, egg_link_path, ensure_dir, format_command_args,
+    get_installed_distributions, get_prog, make_vcs_requirement_url,
+    normalize_path, redact_netloc, redact_password_from_url,
+    remove_auth_from_url, rmtree, split_auth_from_netloc, untar_file,
+    unzip_file,
 )
 from pip._internal.utils.packaging import check_dist_requires_python
 from pip._internal.utils.temp_dir import AdjacentTempDirectory, TempDirectory
@@ -724,6 +725,16 @@ class TestGetProg(object):
         assert get_prog() == expected
 
 
+@pytest.mark.parametrize('args, expected', [
+    (['pip', 'list'], 'pip list'),
+    (['foo', 'space space', 'new\nline', 'double"quote', "single'quote"],
+     """foo 'space space' 'new\nline' 'double"quote' 'single'"'"'quote'"""),
+])
+def test_format_command_args(args, expected):
+    actual = format_command_args(args)
+    assert actual == expected
+
+
 def test_call_subprocess_works__no_keyword_arguments():
     result = call_subprocess(
         [sys.executable, '-c', 'print("Hello")'],

tests/unit/test_wheel.py

@@ -99,15 +99,15 @@ def test_should_use_ephemeral_cache__issue_6197(
     assert ephem_cache is expected
 
 
-def test_format_command__INFO(caplog):
-
+def test_format_command_result__INFO(caplog):
     caplog.set_level(logging.INFO)
-    actual = wheel.format_command(
-        command_args=['arg1', 'arg2'],
+    actual = wheel.format_command_result(
+        # Include an argument with a space to test argument quoting.
+        command_args=['arg1', 'second arg'],
         command_output='output line 1\noutput line 2\n',
     )
     assert actual.splitlines() == [
-        "Command arguments: ['arg1', 'arg2']",
+        "Command arguments: arg1 'second arg'",
         'Command output: [use --verbose to show]',
     ]
 
@@ -118,30 +118,30 @@ def test_format_command__INFO(caplog):
     # Test no trailing newline.
     'output line 1\noutput line 2',
 ])
-def test_format_command__DEBUG(caplog, command_output):
+def test_format_command_result__DEBUG(caplog, command_output):
     caplog.set_level(logging.DEBUG)
-    actual = wheel.format_command(
+    actual = wheel.format_command_result(
         command_args=['arg1', 'arg2'],
         command_output=command_output,
     )
     assert actual.splitlines() == [
-        "Command arguments: ['arg1', 'arg2']",
+        "Command arguments: arg1 arg2",
         'Command output:',
         'output line 1',
         'output line 2',
-        '-----------------------------------------',
+        '----------------------------------------',
     ]
 
 
 @pytest.mark.parametrize('log_level', ['DEBUG', 'INFO'])
-def test_format_command__empty_output(caplog, log_level):
+def test_format_command_result__empty_output(caplog, log_level):
     caplog.set_level(log_level)
-    actual = wheel.format_command(
+    actual = wheel.format_command_result(
         command_args=['arg1', 'arg2'],
         command_output='',
     )
     assert actual.splitlines() == [
-        "Command arguments: ['arg1', 'arg2']",
+        "Command arguments: arg1 arg2",
         'Command output: None',
     ]
 
@@ -172,7 +172,7 @@ def test_get_legacy_build_wheel_path__no_names(caplog):
     assert record.levelname == 'WARNING'
     assert record.message.splitlines() == [
         "Legacy build of wheel for 'pendulum' created no files.",
-        "Command arguments: ['arg1', 'arg2']",
+        "Command arguments: arg1 arg2",
         'Command output: [use --verbose to show]',
     ]
 
@@ -189,7 +189,7 @@ def test_get_legacy_build_wheel_path__multiple_names(caplog):
     assert record.message.splitlines() == [
         "Legacy build of wheel for 'pendulum' created more than one file.",
         "Filenames (choosing first): ['name1', 'name2']",
-        "Command arguments: ['arg1', 'arg2']",
+        "Command arguments: arg1 arg2",
         'Command output: [use --verbose to show]',
     ]