From 8d78ff0fcedefe985ff9b6a777083430d7f4f607 Mon Sep 17 00:00:00 2001 From: Chris Jerdonek Date: Sat, 26 Jan 2019 14:20:14 -0800 Subject: [PATCH] Prefix warning and error log messages. --- news/6298.feature | 1 + src/pip/_internal/cli/base_command.py | 2 +- src/pip/_internal/utils/deprecation.py | 5 ++- src/pip/_internal/utils/logging.py | 22 ++++++++- tests/functional/test_freeze.py | 4 +- tests/functional/test_install.py | 4 +- tests/functional/test_install_check.py | 6 +-- tests/functional/test_install_extras.py | 4 +- tests/unit/test_logging.py | 59 ++++++++++++++++++++----- 9 files changed, 83 insertions(+), 24 deletions(-) create mode 100644 news/6298.feature diff --git a/news/6298.feature b/news/6298.feature new file mode 100644 index 00000000000..23c70b53ac1 --- /dev/null +++ b/news/6298.feature @@ -0,0 +1 @@ +Prefix warning and error messages in log output with `WARNING` and `ERROR`. diff --git a/src/pip/_internal/cli/base_command.py b/src/pip/_internal/cli/base_command.py index b152ad1a026..f6108c96eb5 100644 --- a/src/pip/_internal/cli/base_command.py +++ b/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 diff --git a/src/pip/_internal/utils/deprecation.py b/src/pip/_internal/utils/deprecation.py index cd754a15eb1..8c896f8cee5 100644 --- a/src/pip/_internal/utils/deprecation.py +++ b/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: diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 579d696219a..9ff6fcb141a 100644 --- a/src/pip/_internal/utils/logging.py +++ b/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,7 +93,7 @@ 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. @@ -100,12 +101,31 @@ def __init__(self, *args, **kwargs): 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 ") diff --git a/tests/functional/test_freeze.py b/tests/functional/test_freeze.py index 776b494f983..735d71f4ebc 100644 --- a/tests/functional/test_freeze.py +++ b/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 diff --git a/tests/functional/test_install.py b/tests/functional/test_install.py index 5e72aab5e71..ed0d37b5b91 100644 --- a/tests/functional/test_install.py +++ b/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 diff --git a/tests/functional/test_install_check.py b/tests/functional/test_install_check.py index 01032e08b25..46c7dabe5df 100644 --- a/tests/functional/test_install_check.py +++ b/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) diff --git a/tests/functional/test_install_extras.py b/tests/functional/test_install_extras.py index 3f6bdac6e83..9ef2eef4300 100644 --- a/tests/functional/test_install_extras.py +++ b/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 diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 6d72bf62320..28b31af0ea0 100644 --- a/tests/unit/test_logging.py +++ b/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