Fix a freeze debug log message.

news/6383.bugfix

@@ -0,0 +1,2 @@
+Fix a debug log message when freezing an editable, non-version controlled
+requirement.

src/pip/_internal/operations/freeze.py

@@ -178,7 +178,7 @@ def get_requirement_info(dist):
     if not vc_type:
         req = dist.as_requirement()
         logger.debug(
-            'No VCS found for editable requirement {!r} in: {!r}', req,
+            'No VCS found for editable requirement "%s" in: %r', req,
             location,
         )
         comments = [

tests/functional/test_freeze.py

@@ -126,7 +126,7 @@ def test_freeze_editable_not_vcs(script, tmpdir):
     # as a VCS directory.
     os.rename(os.path.join(pkg_path, '.git'), os.path.join(pkg_path, '.bak'))
     script.pip('install', '-e', pkg_path)
-    result = script.pip('freeze', expect_stderr=True)
+    result = script.pip('freeze')
 
     # We need to apply os.path.normcase() to the path since that is what
     # the freeze code does.

tests/functional/test_install_vcs_git.py

@@ -40,7 +40,7 @@ def _get_branch_remote(script, package_name, branch):
     return result.stdout.strip()
 
 
-def _github_checkout(url_path, temp_dir, egg=None, scheme=None):
+def _github_checkout(url_path, temp_dir, rev=None, egg=None, scheme=None):
     """
     Call local_checkout() with a GitHub URL, and return the resulting URL.
 
@@ -56,6 +56,8 @@ def _github_checkout(url_path, temp_dir, egg=None, scheme=None):
         scheme = 'https'
     url = 'git+{}://github.com/{}'.format(scheme, url_path)
     local_url = local_checkout(url, temp_dir.join('cache'))
+    if rev is not None:
+        local_url += '@{}'.format(rev)
     if egg is not None:
         local_url += '#egg={}'.format(egg)
 
@@ -150,7 +152,7 @@ def test_install_editable_from_git_with_https(script, tmpdir):
     """
     url_path = 'pypa/pip-test-package.git'
     local_url = _github_checkout(url_path, tmpdir, egg='pip-test-package')
-    result = script.pip('install', '-e', local_url, expect_error=True)
+    result = script.pip('install', '-e', local_url)
     result.assert_installed('pip-test-package', with_files=['.git'])
 
 
@@ -184,9 +186,7 @@ def test_git_with_sha1_revisions(script):
         'git', 'rev-parse', 'HEAD~1',
         cwd=version_pkg_path,
     ).stdout.strip()
-    version = _install_version_pkg(
-        script, version_pkg_path, rev=sha1, expect_stderr=True,
-    )
+    version = _install_version_pkg(script, version_pkg_path, rev=sha1)
     assert '0.1' == version
 
 
@@ -200,9 +200,7 @@ def test_git_with_short_sha1_revisions(script):
         'git', 'rev-parse', 'HEAD~1',
         cwd=version_pkg_path,
     ).stdout.strip()[:7]
-    version = _install_version_pkg(
-        script, version_pkg_path, rev=sha1, expect_stderr=True,
-    )
+    version = _install_version_pkg(script, version_pkg_path, rev=sha1)
     assert '0.1' == version
 
 
@@ -212,11 +210,7 @@ def test_git_with_branch_name_as_revision(script):
     """
     version_pkg_path = _create_test_package(script)
     branch = 'test_branch'
-    script.run(
-        'git', 'checkout', '-b', branch,
-        expect_stderr=True,
-        cwd=version_pkg_path,
-    )
+    script.run('git', 'checkout', '-b', branch, cwd=version_pkg_path)
     _change_test_package_version(script, version_pkg_path)
     version = _install_version_pkg(script, version_pkg_path, rev=branch)
     assert 'some different version' == version
@@ -227,11 +221,7 @@ def test_git_with_tag_name_as_revision(script):
     Git backend should be able to install from tag names
     """
     version_pkg_path = _create_test_package(script)
-    script.run(
-        'git', 'tag', 'test_tag',
-        expect_stderr=True,
-        cwd=version_pkg_path,
-    )
+    script.run('git', 'tag', 'test_tag', cwd=version_pkg_path)
     _change_test_package_version(script, version_pkg_path)
     version = _install_version_pkg(script, version_pkg_path, rev='test_tag')
     assert '0.1' == version
@@ -241,7 +231,7 @@ def _add_ref(script, path, ref):
     """
     Add a new ref to a repository at the given path.
     """
-    script.run('git', 'update-ref', ref, 'HEAD', expect_stderr=True, cwd=path)
+    script.run('git', 'update-ref', ref, 'HEAD', cwd=path)
 
 
 def test_git_install_ref(script):
@@ -253,7 +243,7 @@ def test_git_install_ref(script):
     _change_test_package_version(script, version_pkg_path)
 
     version = _install_version_pkg(
-        script, version_pkg_path, rev='refs/foo/bar', expect_stderr=True,
+        script, version_pkg_path, rev='refs/foo/bar',
     )
     assert '0.1' == version
 
@@ -267,14 +257,12 @@ def test_git_install_then_install_ref(script):
     _add_ref(script, version_pkg_path, 'refs/foo/bar')
     _change_test_package_version(script, version_pkg_path)
 
-    version = _install_version_pkg(
-        script, version_pkg_path, expect_stderr=True,
-    )
+    version = _install_version_pkg(script, version_pkg_path)
     assert 'some different version' == version
 
     # Now install the ref.
     version = _install_version_pkg(
-        script, version_pkg_path, rev='refs/foo/bar', expect_stderr=True,
+        script, version_pkg_path, rev='refs/foo/bar',
     )
     assert '0.1' == version
 
@@ -286,14 +274,13 @@ def test_git_with_tag_name_and_update(script, tmpdir):
     """
     url_path = 'pypa/pip-test-package.git'
     local_url = _github_checkout(url_path, tmpdir, egg='pip-test-package')
-    result = script.pip('install', '-e', local_url, expect_error=True)
+    result = script.pip('install', '-e', local_url)
     result.assert_installed('pip-test-package', with_files=['.git'])
 
     new_local_url = _github_checkout(url_path, tmpdir)
     new_local_url += '@0.1.2#egg=pip-test-package'
     result = script.pip(
         'install', '--global-option=--version', '-e', new_local_url,
-        expect_error=True,
     )
     assert '0.1.2' in result.stdout
 
@@ -306,7 +293,7 @@ def test_git_branch_should_not_be_changed(script, tmpdir):
     """
     url_path = 'pypa/pip-test-package.git'
     local_url = _github_checkout(url_path, tmpdir, egg='pip-test-package')
-    script.pip('install', '-e', local_url, expect_error=True)
+    script.pip('install', '-e', local_url)
     branch = _get_editable_branch(script, 'pip-test-package')
     assert 'master' == branch
 
@@ -316,11 +303,11 @@ def test_git_with_non_editable_unpacking(script, tmpdir):
     """
     Test cloning a git repository from a non-editable URL with a given tag.
     """
-    url_path = 'pypa/[email protected]#egg=pip-test-package'
-    local_url = _github_checkout(url_path, tmpdir)
-    result = script.pip(
-        'install', '--global-option=--version', local_url, expect_error=True,
+    url_path = 'pypa/pip-test-package.git'
+    local_url = _github_checkout(
+        url_path, tmpdir, rev='0.1.2', egg='pip-test-package',
     )
+    result = script.pip('install', '--global-option=--version', local_url)
     assert '0.1.2' in result.stdout
 
 
@@ -388,13 +375,8 @@ def test_editable__branch_with_sha_same_as_default(script):
     """
     version_pkg_path = _create_test_package(script)
     # Create a second branch with the same SHA.
-    script.run(
-        'git', 'branch', 'develop', expect_stderr=True,
-        cwd=version_pkg_path,
-    )
-    _install_version_pkg_only(
-        script, version_pkg_path, rev='develop', expect_stderr=True
-    )
+    script.run('git', 'branch', 'develop', cwd=version_pkg_path)
+    _install_version_pkg_only(script, version_pkg_path, rev='develop')
 
     branch = _get_editable_branch(script, 'version-pkg')
     assert branch == 'develop'
@@ -410,16 +392,11 @@ def test_editable__branch_with_sha_different_from_default(script):
     """
     version_pkg_path = _create_test_package(script)
     # Create a second branch.
-    script.run(
-        'git', 'branch', 'develop', expect_stderr=True,
-        cwd=version_pkg_path,
-    )
+    script.run('git', 'branch', 'develop', cwd=version_pkg_path)
     # Add another commit to the master branch to give it a different sha.
     _change_test_package_version(script, version_pkg_path)
 
-    version = _install_version_pkg(
-        script, version_pkg_path, rev='develop', expect_stderr=True
-    )
+    version = _install_version_pkg(script, version_pkg_path, rev='develop')
     assert version == '0.1'
 
     branch = _get_editable_branch(script, 'version-pkg')
@@ -437,10 +414,7 @@ def test_editable__non_master_default_branch(script):
     version_pkg_path = _create_test_package(script)
     # Change the default branch of the remote repo to a name that is
     # alphabetically after "master".
-    script.run(
-        'git', 'checkout', '-b', 'release', expect_stderr=True,
-        cwd=version_pkg_path,
-    )
+    script.run('git', 'checkout', '-b', 'release', cwd=version_pkg_path)
     _install_version_pkg_only(script, version_pkg_path)
 
     branch = _get_editable_branch(script, 'version-pkg')
@@ -492,7 +466,6 @@ def test_check_submodule_addition(script):
     update_result = script.pip(
         'install', '-e', 'git+' + module_path + '#egg=version_pkg',
         '--upgrade',
-        expect_error=True,
     )
 
     assert (

tests/functional/test_vcs_git.py

@@ -19,12 +19,12 @@ def get_head_sha(script, dest):
 
 
 def checkout_ref(script, repo_dir, ref):
-    script.run('git', 'checkout', ref, cwd=repo_dir, expect_stderr=True)
+    script.run('git', 'checkout', ref, cwd=repo_dir)
 
 
 def checkout_new_branch(script, repo_dir, branch):
     script.run(
-        'git', 'checkout', '-b', branch, cwd=repo_dir, expect_stderr=True,
+        'git', 'checkout', '-b', branch, cwd=repo_dir,
     )
 
 
@@ -87,7 +87,7 @@ def test_get_remote_url(script, tmpdir):
     do_commit(script, source_dir)
 
     repo_dir = str(tmpdir / 'repo')
-    script.run('git', 'clone', source_url, repo_dir, expect_stderr=True)
+    script.run('git', 'clone', source_url, repo_dir)
 
     remote_url = Git.get_remote_url(repo_dir)
     assert remote_url == source_url

tests/lib/__init__.py

@@ -1,6 +1,7 @@
 from __future__ import absolute_import
 
 from contextlib import contextmanager
+from textwrap import dedent
 import os
 import sys
 import re
@@ -263,6 +264,17 @@ def assert_installed(self, pkg_name, editable=True, with_files=[],
                 )
 
 
+def make_check_stderr_message(stderr, line, reason):
+    """
+    Create an exception message to use inside check_stderr().
+    """
+    return dedent("""\
+    {reason}:
+     Caused by line: {line!r}
+     Complete stderr: {stderr}
+    """).format(stderr=stderr, line=line, reason=reason)
+
+
 def check_stderr(
     stderr, allow_stderr_warning=None, allow_stderr_error=None,
 ):
@@ -293,22 +305,34 @@ def check_stderr(
 
     lines = stderr.splitlines()
     for line in lines:
+        # First check for logging errors which are sent directly to stderr
+        # and so bypass any configured log formatter.  The
+        # "--- Logging error ---" string is used in Python 3.4+, and
+        # "Logged from file " is used in Python 2.
+        if (line.startswith('--- Logging error ---') or
+                line.startswith('Logged from file ')):
+            reason = 'stderr has a logging error, which is never allowed'
+            msg = make_check_stderr_message(stderr, line=line, reason=reason)
+            raise RuntimeError(msg)
+
         if line.startswith('ERROR: '):
-            raise RuntimeError(
+            reason = (
                 'stderr has an unexpected error '
-                '(pass allow_stderr_error=True to permit this): {}'
-                .format(line)
+                '(pass allow_stderr_error=True to permit this)'
             )
+            msg = make_check_stderr_message(stderr, line=line, reason=reason)
+            raise RuntimeError(msg)
         if allow_stderr_warning:
             continue
 
         if (line.startswith('WARNING: ') or
                 line.startswith(DEPRECATION_MSG_PREFIX)):
-            raise RuntimeError(
+            reason = (
                 'stderr has an unexpected warning '
-                '(pass allow_stderr_warning=True to permit this): {}'
-                .format(line)
+                '(pass allow_stderr_warning=True to permit this)'
             )
+            msg = make_check_stderr_message(stderr, line=line, reason=reason)
+            raise RuntimeError(msg)
 
 
 class PipTestEnvironment(TestFileEnvironment):

tests/lib/test_lib.py

@@ -20,7 +20,9 @@ def assert_error_startswith(exc_type, expected_start):
     with pytest.raises(exc_type) as err:
         yield
 
-    assert str(err.value).startswith(expected_start)
+    assert str(err.value).startswith(expected_start), (
+        'full message: {}'.format(err.value)
+    )
 
 
 def test_tmp_dir_exists_in_env(script):
@@ -78,6 +80,18 @@ def test_as_import(script):
 
 class TestPipTestEnvironment:
 
+    def run_with_log_command(self, script, sub_string):
+        """
+        Call run() on a command that logs a "%"-style format string using
+        the given substring as the string's replacement field.
+        """
+        command = (
+            "import logging; logging.basicConfig(level='INFO'); "
+            "logging.getLogger().info('sub: {}', 'foo')"
+        ).format(sub_string)
+        args = [sys.executable, '-c', command]
+        script.run(*args)
+
     def run_stderr_with_prefix(self, script, prefix, **kwargs):
         """
         Call run() that prints stderr with the given prefix.
@@ -139,6 +153,18 @@ def test_run__unexpected_stderr(self, script, prefix, expected_start):
         with assert_error_startswith(RuntimeError, expected_start):
             self.run_stderr_with_prefix(script, prefix)
 
+    def test_run__logging_error(self, script):
+        """
+        Test calling run() with an unexpected logging error.
+        """
+        # Pass a good substitution string.
+        self.run_with_log_command(script, sub_string='%r')
+
+        expected_start = 'stderr has a logging error, which is never allowed'
+        with assert_error_startswith(RuntimeError, expected_start):
+            # Pass a bad substitution string.
+            self.run_with_log_command(script, sub_string='{!r}')
+
     def test_run__allow_stderr_error_false_error_with_expect_error(
         self, script,
     ):