Prefix warning and error log messages.

This commit is contained in:
Chris Jerdonek 2019-01-26 14:20:14 -08:00
parent 821247dc36
commit 8d78ff0fce
9 changed files with 84 additions and 25 deletions

1
news/6298.feature Normal file
View File

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

View File

@ -191,7 +191,7 @@ class Command(object):
return ERROR
except CommandError as exc:
logger.critical('ERROR: %s', exc)
logger.critical('%s', exc)
logger.debug('Exception information:', exc_info=True)
return ERROR

View File

@ -15,6 +15,9 @@ if MYPY_CHECK_RUNNING:
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:

View File

@ -10,6 +10,7 @@ import sys
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 @@ class IndentingFormatter(logging.Formatter):
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 ")

View File

@ -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

View File

@ -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

View File

@ -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)

View File

@ -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

View File

@ -48,21 +48,56 @@ class TestIndentingFormatter(object):
if 'tzset' in dir(time):
time.tzset()
def test_format(self, tmpdir):
record = logging.makeLogRecord(dict(
created=1547704837.4,
msg='hello\nworld',
))
f = IndentingFormatter(fmt="%(message)s")
assert f.format(record) == '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)
def test_format_with_timestamp(self, tmpdir):
record = logging.makeLogRecord(dict(
created=1547704837.4,
msg='hello\nworld',
))
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) == expected
@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