Merge pull request #6299 from cjerdonek/prefix-warn-messages

Prefix warning and error log messages

news/6298.feature

@@ -0,0 +1 @@
+Prefix warning and error messages in log output with `WARNING` and `ERROR`.

src/pip/_internal/cli/base_command.py

@@ -191,7 +191,7 @@ def main(self, args):
 
             return ERROR
         except CommandError as exc:
-            logger.critical('ERROR: %s', exc)
+            logger.critical('%s', exc)
             logger.debug('Exception information:', exc_info=True)
 
             return ERROR

src/pip/_internal/utils/deprecation.py

@@ -15,6 +15,9 @@
     from typing import Any, Optional
 
 
+DEPRECATION_MSG_PREFIX = "DEPRECATION: "
+
+
 class PipDeprecationWarning(Warning):
     pass
 
@@ -77,7 +80,7 @@ def deprecated(reason, replacement, gone_in, issue=None):
     # Construct a nice message.
     # This is purposely eagerly formatted as we want it to appear as if someone
     # typed this entire message out.
-    message = "DEPRECATION: " + reason
+    message = DEPRECATION_MSG_PREFIX + reason
     if replacement is not None:
         message += " A possible replacement is {}.".format(replacement)
     if issue is not None:

src/pip/_internal/utils/logging.py

@@ -10,6 +10,7 @@
 from pip._vendor.six import PY2
 
 from pip._internal.utils.compat import WINDOWS
+from pip._internal.utils.deprecation import DEPRECATION_MSG_PREFIX
 from pip._internal.utils.misc import ensure_dir
 
 try:
@@ -92,20 +93,39 @@ def get_indentation():
 class IndentingFormatter(logging.Formatter):
     def __init__(self, *args, **kwargs):
         """
-        A logging.Formatter obeying containing indent_log contexts.
+        A logging.Formatter that obeys the indent_log() context manager.
 
         :param add_timestamp: A bool indicating output lines should be prefixed
             with their record's timestamp.
         """
         self.add_timestamp = kwargs.pop("add_timestamp", False)
         super(IndentingFormatter, self).__init__(*args, **kwargs)
 
+    def get_message_start(self, formatted, levelno):
+        """
+        Return the start of the formatted log message (not counting the
+        prefix to add to each line).
+        """
+        if levelno < logging.WARNING:
+            return ''
+        if formatted.startswith(DEPRECATION_MSG_PREFIX):
+            # Then the message already has a prefix.  We don't want it to
+            # look like "WARNING: DEPRECATION: ...."
+            return ''
+        if levelno < logging.ERROR:
+            return 'WARNING: '
+
+        return 'ERROR: '
+
     def format(self, record):
         """
         Calls the standard formatter, but will indent all of the log messages
         by our current indentation level.
         """
         formatted = super(IndentingFormatter, self).format(record)
+        message_start = self.get_message_start(formatted, record.levelno)
+        formatted = message_start + formatted
+
         prefix = ''
         if self.add_timestamp:
             prefix = self.formatTime(record, "%Y-%m-%dT%H:%M:%S ")

tests/functional/test_freeze.py

@@ -476,8 +476,8 @@ def test_freeze_with_requirement_option_file_url_egg_not_installed(
         'freeze', '--requirement', 'requirements.txt', expect_stderr=True,
     )
     expected_err = (
-        'Requirement file [requirements.txt] contains {}, but package '
-        "'Does.Not-Exist' is not installed\n"
+        'WARNING: Requirement file [requirements.txt] contains {}, '
+        "but package 'Does.Not-Exist' is not installed\n"
     ).format(url)
     if deprecated_python:
         assert expected_err in result.stderr

tests/functional/test_install.py

@@ -503,7 +503,7 @@ def test_editable_install__local_dir_no_setup_py(
     if deprecated_python:
         assert 'File "setup.py" not found. ' in msg
     else:
-        assert msg.startswith('File "setup.py" not found. ')
+        assert msg.startswith('ERROR: File "setup.py" not found. ')
     assert 'pyproject.toml' not in msg
 
 
@@ -524,7 +524,7 @@ def test_editable_install__local_dir_no_setup_py_with_pyproject(
     if deprecated_python:
         assert 'File "setup.py" not found. ' in msg
     else:
-        assert msg.startswith('File "setup.py" not found. ')
+        assert msg.startswith('ERROR: File "setup.py" not found. ')
     assert 'A "pyproject.toml" file was found' in msg
 
 

tests/functional/test_install_check.py

@@ -34,7 +34,7 @@ def test_check_install_canonicalization(script, deprecated_python):
         'install', '--no-index', normal_path, '--quiet', expect_error=True
     )
     expected_lines = [
-        "pkga 1.0 requires SPECIAL.missing, which is not installed.",
+        "ERROR: pkga 1.0 requires SPECIAL.missing, which is not installed.",
     ]
     # Deprecated python versions produce an extra warning on stderr
     assert matches_expected_lines(
@@ -90,9 +90,9 @@ def test_check_install_does_not_warn_for_out_of_graph_issues(
         'install', '--no-index', pkg_conflict_path, expect_error=True,
     )
     assert matches_expected_lines(result.stderr, [
-        "broken 1.0 requires missing, which is not installed.",
+        "ERROR: broken 1.0 requires missing, which is not installed.",
         (
-            "broken 1.0 has requirement conflict<1.0, but "
+            "ERROR: broken 1.0 has requirement conflict<1.0, but "
             "you'll have conflict 1.0 which is incompatible."
         ),
     ], exact=not deprecated_python)

tests/functional/test_install_extras.py

@@ -101,8 +101,8 @@ def test_nonexistent_options_listed_in_order(script, data):
         'simplewheel[nonexistent, nope]', expect_stderr=True,
     )
     msg = (
-        "  simplewheel 2.0 does not provide the extra 'nonexistent'\n"
-        "  simplewheel 2.0 does not provide the extra 'nope'"
+        "  WARNING: simplewheel 2.0 does not provide the extra 'nonexistent'\n"
+        "  WARNING: simplewheel 2.0 does not provide the extra 'nope'"
     )
     assert msg in result.stderr
 

tests/unit/test_logging.py

@@ -48,21 +48,56 @@ def teardown(self):
         if 'tzset' in dir(time):
             time.tzset()
 
-    def test_format(self, tmpdir):
-        record = logging.makeLogRecord(dict(
-            created=1547704837.4,
-            msg='hello\nworld',
-        ))
+    def make_record(self, msg, level_name):
+        level_number = getattr(logging, level_name)
+        attrs = dict(
+            msg=msg, created=1547704837.4, levelname=level_name,
+            levelno=level_number,
+        )
+        record = logging.makeLogRecord(attrs)
+
+        return record
+
+    @pytest.mark.parametrize('level_name, expected', [
+        ('DEBUG', 'hello\nworld'),
+        ('INFO', 'hello\nworld'),
+        ('WARNING', 'WARNING: hello\nworld'),
+        ('ERROR', 'ERROR: hello\nworld'),
+        ('CRITICAL', 'ERROR: hello\nworld'),
+    ])
+    def test_format(self, level_name, expected):
+        """
+        Args:
+          level_name: a logging level name (e.g. "WARNING").
+        """
+        record = self.make_record('hello\nworld', level_name=level_name)
         f = IndentingFormatter(fmt="%(message)s")
-        assert f.format(record) == 'hello\nworld'
+        assert f.format(record) == expected
 
-    def test_format_with_timestamp(self, tmpdir):
-        record = logging.makeLogRecord(dict(
-            created=1547704837.4,
-            msg='hello\nworld',
-        ))
+    @pytest.mark.parametrize('level_name, expected', [
+        ('INFO', '2019-01-17T06:00:37 hello\n2019-01-17T06:00:37 world'),
+        ('WARNING',
+         '2019-01-17T06:00:37 WARNING: hello\n2019-01-17T06:00:37 world'),
+    ])
+    def test_format_with_timestamp(self, level_name, expected):
+        record = self.make_record('hello\nworld', level_name=level_name)
         f = IndentingFormatter(fmt="%(message)s", add_timestamp=True)
-        expected = '2019-01-17T06:00:37 hello\n2019-01-17T06:00:37 world'
+        assert f.format(record) == expected
+
+    @pytest.mark.parametrize('level_name, expected', [
+        ('WARNING', 'DEPRECATION: hello\nworld'),
+        ('ERROR', 'DEPRECATION: hello\nworld'),
+        ('CRITICAL', 'DEPRECATION: hello\nworld'),
+    ])
+    def test_format_deprecated(self, level_name, expected):
+        """
+        Test that logged deprecation warnings coming from deprecated()
+        don't get another prefix.
+        """
+        record = self.make_record(
+            'DEPRECATION: hello\nworld', level_name=level_name,
+        )
+        f = IndentingFormatter(fmt="%(message)s")
         assert f.format(record) == expected