Cleaned up the installer output behavior.

This change also makes sure the logger handlers are not alterated after an
installation. That also fixes the remaining environment alteration issue in
test_packaging.

6 files changed, 86 insertions, 67 deletions

diff --git a/Lib/packaging/install.py b/Lib/packaging/install.py
index 92657ea3d8..cd2bbb6b6b 100644
--- a/Lib/packaging/install.py
+++ b/Lib/packaging/install.py
@@ -118,15 +118,15 @@ def install_local_project(path):
     """
     path = os.path.abspath(path)
     if os.path.isdir(path):
-        logger.info('installing from source directory: %s', path)
+        logger.info('Installing from source directory: %s', path)
         _run_install_from_dir(path)
     elif _is_archive_file(path):
-        logger.info('installing from archive: %s', path)
+        logger.info('Installing from archive: %s', path)
         _unpacked_dir = tempfile.mkdtemp()
         shutil.unpack_archive(path, _unpacked_dir)
         _run_install_from_archive(_unpacked_dir)
     else:
-        logger.warning('no projects to install')
+        logger.warning('No projects to install.')
 
 
 def _run_install_from_archive(source_dir):
@@ -174,16 +174,16 @@ def install_dists(dists, path, paths=sys.path):
 
     installed_dists = []
     for dist in dists:
-        logger.info('installing %s %s', dist.name, dist.version)
+        logger.info('Installing %r %s...', dist.name, dist.version)
         try:
             _install_dist(dist, path)
             installed_dists.append(dist)
         except Exception as e:
-            logger.info('failed: %s', e)
+            logger.info('Failed: %s', e)
 
             # reverting
             for installed_dist in installed_dists:
-                logger.info('reverting %s', installed_dist)
+                logger.info('Reverting %s', installed_dist)
                 _remove_dist(installed_dist, paths)
             raise e
     return installed_dists
@@ -292,7 +292,7 @@ def get_infos(requirements, index=None, installed=None, prefer_final=True):
     #    or remove
 
     if not installed:
-        logger.info('reading installed distributions')
+        logger.debug('Reading installed distributions')
         installed = list(get_distributions(use_egg_info=True))
 
     infos = {'install': [], 'remove': [], 'conflict': []}
@@ -306,7 +306,7 @@ def get_infos(requirements, index=None, installed=None, prefer_final=True):
         if predicate.name.lower() != installed_project.name.lower():
             continue
         found = True
-        logger.info('found %s %s', installed_project.name,
+        logger.info('Found %s %s', installed_project.name,
                     installed_project.metadata['version'])
 
         # if we already have something installed, check it matches the
@@ -316,7 +316,7 @@ def get_infos(requirements, index=None, installed=None, prefer_final=True):
         break
 
     if not found:
-        logger.info('project not installed')
+        logger.debug('Project not installed')
 
     if not index:
         index = wrapper.ClientWrapper()
@@ -331,7 +331,7 @@ def get_infos(requirements, index=None, installed=None, prefer_final=True):
         raise InstallationException('Release not found: "%s"' % requirements)
 
     if release is None:
-        logger.info('could not find a matching project')
+        logger.info('Could not find a matching project')
         return infos
 
     metadata = release.fetch_metadata()
@@ -348,7 +348,7 @@ def get_infos(requirements, index=None, installed=None, prefer_final=True):
     # Get what the missing deps are
     dists = depgraph.missing[release]
     if dists:
-        logger.info("missing dependencies found, retrieving metadata")
+        logger.info("Missing dependencies found, retrieving metadata")
         # we have missing deps
         for dist in dists:
             _update_infos(infos, get_infos(dist, index, installed))
@@ -401,7 +401,7 @@ def remove(project_name, paths=sys.path, auto_confirm=True):
     finally:
         shutil.rmtree(tmp)
 
-    logger.info('removing %r: ', project_name)
+    logger.info('Removing %r: ', project_name)
 
     for file_ in rmfiles:
         logger.info('  %s', file_)
@@ -444,20 +444,20 @@ def remove(project_name, paths=sys.path, auto_confirm=True):
         if os.path.exists(dist.path):
             shutil.rmtree(dist.path)
 
-        logger.info('success: removed %d files and %d dirs',
+        logger.info('Success: removed %d files and %d dirs',
                     file_count, dir_count)
 
 
 def install(project):
-    logger.info('getting information about %r', project)
+    logger.info('Getting information about %r...', project)
     try:
         info = get_infos(project)
     except InstallationException:
-        logger.info('cound not find %r', project)
+        logger.info('Cound not find %r', project)
         return
 
     if info['install'] == []:
-        logger.info('nothing to install')
+        logger.info('Nothing to install')
         return
 
     install_path = get_config_var('base')
diff --git a/Lib/packaging/pypi/simple.py b/Lib/packaging/pypi/simple.py
index ee7a113754..983d4773de 100644
--- a/Lib/packaging/pypi/simple.py
+++ b/Lib/packaging/pypi/simple.py
@@ -118,9 +118,10 @@ class Crawler(BaseClient):
     def __init__(self, index_url=DEFAULT_SIMPLE_INDEX_URL, prefer_final=False,
                  prefer_source=True, hosts=DEFAULT_HOSTS,
                  follow_externals=False, mirrors_url=None, mirrors=None,
-                 timeout=SOCKET_TIMEOUT, mirrors_max_tries=0):
+                 timeout=SOCKET_TIMEOUT, mirrors_max_tries=0, verbose=False):
         super(Crawler, self).__init__(prefer_final, prefer_source)
         self.follow_externals = follow_externals
+        self.verbose = verbose
 
         # mirroring attributes.
         parsed = urllib.parse.urlparse(index_url)
@@ -184,7 +185,7 @@ class Crawler(BaseClient):
         if predicate.name.lower() in self._projects and not force_update:
             return self._projects.get(predicate.name.lower())
         prefer_final = self._get_prefer_final(prefer_final)
-        logger.info('reading info on PyPI about %s', predicate.name)
+        logger.debug('Reading info on PyPI about %s', predicate.name)
         self._process_index_page(predicate.name)
 
         if predicate.name.lower() not in self._projects:
@@ -321,8 +322,9 @@ class Crawler(BaseClient):
                                 infos = get_infos_from_url(link, project_name,
                                             is_external=not self.index_url in url)
                             except CantParseArchiveName as e:
-                                logger.warning(
-                                    "version has not been parsed: %s", e)
+                                if self.verbose:
+                                    logger.warning(
+                                        "version has not been parsed: %s", e)
                             else:
                                 self._register_release(release_info=infos)
                         else:
diff --git a/Lib/packaging/run.py b/Lib/packaging/run.py
index 1d4fadb880..03b80c6a05 100644
--- a/Lib/packaging/run.py
+++ b/Lib/packaging/run.py
@@ -5,6 +5,7 @@ import re
 import sys
 import getopt
 import logging
+from copy import copy
 
 from packaging import logger
 from packaging.dist import Distribution
@@ -227,12 +228,13 @@ def _install(dispatcher, args, **kw):
             logger.warning('no project to install')
             return
 
+    target = args[1]
     # installing from a source dir or archive file?
-    if os.path.isdir(args[1]) or _is_archive_file(args[1]):
-        install_local_project(args[1])
+    if os.path.isdir(target) or _is_archive_file(target):
+        install_local_project(target)
     else:
         # download from PyPI
-        install(args[1])
+        install(target)
 
 
 @action_help(metadata_usage)
@@ -399,6 +401,17 @@ class Dispatcher:
             msg = 'Unrecognized action "%s"' % self.action
             raise PackagingArgError(msg)
 
+        self._set_logger()
+
+        # for display options we return immediately
+        option_order = self.parser.get_option_order()
+
+        self.args = args
+
+        if self.help or self.action is None:
+            self._show_help(self.parser, display_options_=False)
+
+    def _set_logger(self):
         # setting up the logging level from the command-line options
         # -q gets warning, error and critical
         if self.verbose == 0:
@@ -416,13 +429,11 @@ class Dispatcher:
         else:  # -vv and more for debug
             level = logging.DEBUG
 
-        # for display options we return immediately
-        option_order = self.parser.get_option_order()
-
-        self.args = args
-
-        if self.help or self.action is None:
-            self._show_help(self.parser, display_options_=False)
+        # setting up the stream handler
+        handler = logging.StreamHandler(sys.stderr)
+        handler.setLevel(level)
+        logger.addHandler(handler)
+        logger.setLevel(level)
 
     def _parse_command_opts(self, parser, args):
         # Pull the current command from the head of the command line
@@ -635,11 +646,17 @@ class Dispatcher:
 
 
 def main(args=None):
-    dispatcher = Dispatcher(args)
-    if dispatcher.action is None:
-        return
+    old_level = logger.level
+    old_handlers = copy(logger.handlers)
+    try:
+        dispatcher = Dispatcher(args)
+        if dispatcher.action is None:
+            return
+        return dispatcher()
+    finally:
+        logger.setLevel(old_level)
+        logger.handlers[:] = old_handlers
 
-    return dispatcher()
 
 if __name__ == '__main__':
     sys.exit(main())
diff --git a/Lib/packaging/tests/test_command_test.py b/Lib/packaging/tests/test_command_test.py
index 4fd8452683..f780723970 100644
--- a/Lib/packaging/tests/test_command_test.py
+++ b/Lib/packaging/tests/test_command_test.py
@@ -150,8 +150,7 @@ class TestTest(TempdirManager,
         cmd.tests_require = [phony_project]
         cmd.ensure_finalized()
         logs = self.get_logs(logging.WARNING)
-        self.assertEqual(1, len(logs))
-        self.assertIn(phony_project, logs[0])
+        self.assertIn(phony_project, logs[-1])
 
     def prepare_a_module(self):
         tmp_dir = self.mkdtemp()
diff --git a/Lib/packaging/tests/test_util.py b/Lib/packaging/tests/test_util.py
index 61b4ec76f3..5a94a7386e 100644
--- a/Lib/packaging/tests/test_util.py
+++ b/Lib/packaging/tests/test_util.py
@@ -818,51 +818,51 @@ class PackagingLibChecks(support.TempdirManager,
 
     def test_is_setuptools_logs_setup_py_text_found(self):
         is_setuptools(self._setuptools_setup_py_pkg())
-        expected = ['setup.py file found', 'found setuptools text in setup.py']
-        self.assertEqual(expected, self.get_logs(logging.INFO))
+        expected = ['setup.py file found.',
+                    'No egg-info directory found.',
+                    'Found setuptools text in setup.py.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_setuptools_logs_setup_py_text_not_found(self):
         directory = self._random_setup_py_pkg()
         is_setuptools(directory)
-        info_expected = ['setup.py file found']
-        warn_expected = ['no egg-info directory found',
-                         'no setuptools text found in setup.py']
-        self.assertEqual(info_expected, self.get_logs(logging.INFO))
-        self.assertEqual(warn_expected, self.get_logs(logging.WARN))
+        expected = ['setup.py file found.', 'No egg-info directory found.',
+                    'No setuptools text found in setup.py.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_setuptools_logs_egg_info_dir_found(self):
         is_setuptools(self._setuptools_egg_info_pkg())
-        expected = ['setup.py file found', 'found egg-info directory']
-        self.assertEqual(expected, self.get_logs(logging.INFO))
+        expected = ['setup.py file found.', 'Found egg-info directory.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_distutils_logs_setup_py_text_found(self):
         is_distutils(self._distutils_setup_py_pkg())
-        expected = ['setup.py file found', 'found distutils text in setup.py']
-        self.assertEqual(expected, self.get_logs(logging.INFO))
+        expected = ['setup.py file found.',
+                    'No PKG-INFO file found.',
+                    'Found distutils text in setup.py.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_distutils_logs_setup_py_text_not_found(self):
         directory = self._random_setup_py_pkg()
         is_distutils(directory)
-        info_expected = ['setup.py file found']
-        warn_expected = ['no PKG-INFO file found',
-                         'no distutils text found in setup.py']
-        self.assertEqual(info_expected, self.get_logs(logging.INFO))
-        self.assertEqual(warn_expected, self.get_logs(logging.WARN))
+        expected = ['setup.py file found.', 'No PKG-INFO file found.',
+                    'No distutils text found in setup.py.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_distutils_logs_pkg_info_file_found(self):
         is_distutils(self._distutils_pkg_info())
-        expected = ['setup.py file found', 'PKG-INFO file found']
-        self.assertEqual(expected, self.get_logs(logging.INFO))
+        expected = ['setup.py file found.', 'PKG-INFO file found.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_packaging_logs_setup_cfg_found(self):
         is_packaging(self._valid_setup_cfg_pkg())
-        expected = ['setup.cfg file found']
-        self.assertEqual(expected, self.get_logs(logging.INFO))
+        expected = ['setup.cfg file found.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def test_is_packaging_logs_setup_cfg_not_found(self):
         is_packaging(self._empty_dir)
-        expected = ['no setup.cfg file found']
-        self.assertEqual(expected, self.get_logs(logging.WARN))
+        expected = ['No setup.cfg file found.']
+        self.assertEqual(expected, self.get_logs(logging.DEBUG))
 
     def _write_setuptools_setup_py(self, directory):
         self.write_file((directory, 'setup.py'),
diff --git a/Lib/packaging/util.py b/Lib/packaging/util.py
index 15da9e66a8..e8393207ec 100644
--- a/Lib/packaging/util.py
+++ b/Lib/packaging/util.py
@@ -1224,9 +1224,9 @@ def _has_egg_info(srcdir):
         for item in os.listdir(srcdir):
             full_path = os.path.join(srcdir, item)
             if item.endswith('.egg-info') and os.path.isdir(full_path):
-                logger.info("found egg-info directory")
+                logger.debug("Found egg-info directory.")
                 return True
-    logger.warning("no egg-info directory found")
+    logger.debug("No egg-info directory found.")
     return False
 
 
@@ -1243,9 +1243,9 @@ def _has_text(setup_py, installer):
     with open(setup_py, 'r', encoding='utf-8') as setup:
         for line in setup:
             if re.search(installer_pattern, line):
-                logger.info("found %s text in setup.py", installer)
+                logger.debug("Found %s text in setup.py.", installer)
                 return True
-    logger.warning("no %s text found in setup.py", installer)
+    logger.debug("No %s text found in setup.py.", installer)
     return False
 
 
@@ -1261,15 +1261,16 @@ def _has_pkg_info(srcdir):
     pkg_info = os.path.join(srcdir, 'PKG-INFO')
     has_pkg_info = os.path.isfile(pkg_info)
     if has_pkg_info:
-        logger.info("PKG-INFO file found")
-    logger.warning("no PKG-INFO file found")
+        logger.debug("PKG-INFO file found.")
+    else:
+        logger.debug("No PKG-INFO file found.")
     return has_pkg_info
 
 
 def _has_setup_py(srcdir):
     setup_py = os.path.join(srcdir, 'setup.py')
     if os.path.isfile(setup_py):
-        logger.info('setup.py file found')
+        logger.debug('setup.py file found.')
         return True
     return False
 
@@ -1277,9 +1278,9 @@ def _has_setup_py(srcdir):
 def _has_setup_cfg(srcdir):
     setup_cfg = os.path.join(srcdir, 'setup.cfg')
     if os.path.isfile(setup_cfg):
-        logger.info('setup.cfg file found')
+        logger.debug('setup.cfg file found.')
         return True
-    logger.warning("no setup.cfg file found")
+    logger.debug("No setup.cfg file found.")
     return False