From 26cdedd618c080ba207c55bf81d61119e1c36232 Mon Sep 17 00:00:00 2001 From: Christopher Hunt Date: Mon, 17 Jun 2019 17:50:41 -0400 Subject: [PATCH] Add milliseconds to --log entry timestamps. (#6621) Resolves #6587. --- news/6587.feature | 1 + src/pip/_internal/utils/logging.py | 9 ++++++--- tests/unit/test_base_command.py | 8 ++++---- tests/unit/test_logging.py | 12 +++++++++--- 4 files changed, 20 insertions(+), 10 deletions(-) create mode 100644 news/6587.feature diff --git a/news/6587.feature b/news/6587.feature new file mode 100644 index 000000000..d47c206d2 --- /dev/null +++ b/news/6587.feature @@ -0,0 +1 @@ +Update timestamps in pip's ``--log`` file to include milliseconds. diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index a28e88cac..14aee6d3e 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -92,6 +92,7 @@ def get_indentation(): class IndentingFormatter(logging.Formatter): + def __init__(self, *args, **kwargs): """ A logging.Formatter that obeys the indent_log() context manager. @@ -120,8 +121,8 @@ class IndentingFormatter(logging.Formatter): def format(self, record): """ - Calls the standard formatter, but will indent all of the log messages - by our current indentation level. + Calls the standard formatter, but will indent all of the log message + lines by our current indentation level. """ formatted = super(IndentingFormatter, self).format(record) message_start = self.get_message_start(formatted, record.levelno) @@ -129,7 +130,9 @@ class IndentingFormatter(logging.Formatter): prefix = '' if self.add_timestamp: - prefix = self.formatTime(record, "%Y-%m-%dT%H:%M:%S ") + # TODO: Use Formatter.default_time_format after dropping PY2. + t = self.formatTime(record, "%Y-%m-%dT%H:%M:%S") + prefix = '%s,%03d ' % (t, record.msecs) prefix += " " * get_indentation() formatted = "".join([ prefix + line diff --git a/tests/unit/test_base_command.py b/tests/unit/test_base_command.py index f90aaadf2..344d24e08 100644 --- a/tests/unit/test_base_command.py +++ b/tests/unit/test_base_command.py @@ -81,7 +81,7 @@ class Test_base_command_logging(object): def setup(self): self.old_time = time.time - time.time = lambda: 1547704837.4 + time.time = lambda: 1547704837.040001 self.old_tz = os.environ.get('TZ') os.environ['TZ'] = 'UTC' # time.tzset() is not implemented on some platforms (notably, Windows). @@ -105,7 +105,7 @@ class Test_base_command_logging(object): log_path = tmpdir.join('log') cmd.main(['fake', '--log', log_path]) with open(log_path) as f: - assert f.read().rstrip() == '2019-01-17T06:00:37 fake' + assert f.read().rstrip() == '2019-01-17T06:00:37,040 fake' def test_log_command_error(self, tmpdir): """ @@ -115,7 +115,7 @@ class Test_base_command_logging(object): log_path = tmpdir.join('log') cmd.main(['fake', '--log', log_path]) with open(log_path) as f: - assert f.read().startswith('2019-01-17T06:00:37 fake') + assert f.read().startswith('2019-01-17T06:00:37,040 fake') def test_log_file_command_error(self, tmpdir): """ @@ -125,7 +125,7 @@ class Test_base_command_logging(object): log_file_path = tmpdir.join('log_file') cmd.main(['fake', '--log-file', log_file_path]) with open(log_file_path) as f: - assert f.read().startswith('2019-01-17T06:00:37 fake') + assert f.read().startswith('2019-01-17T06:00:37,040 fake') def test_unicode_messages(self, tmpdir): """ diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index 28b31af0e..ddff2b38d 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -51,7 +51,10 @@ class TestIndentingFormatter(object): def make_record(self, msg, level_name): level_number = getattr(logging, level_name) attrs = dict( - msg=msg, created=1547704837.4, levelname=level_name, + msg=msg, + created=1547704837.040001, + msecs=40, + levelname=level_name, levelno=level_number, ) record = logging.makeLogRecord(attrs) @@ -75,9 +78,12 @@ class TestIndentingFormatter(object): assert f.format(record) == expected @pytest.mark.parametrize('level_name, expected', [ - ('INFO', '2019-01-17T06:00:37 hello\n2019-01-17T06:00:37 world'), + ('INFO', + '2019-01-17T06:00:37,040 hello\n' + '2019-01-17T06:00:37,040 world'), ('WARNING', - '2019-01-17T06:00:37 WARNING: hello\n2019-01-17T06:00:37 world'), + '2019-01-17T06:00:37,040 WARNING: hello\n' + '2019-01-17T06:00:37,040 world'), ]) def test_format_with_timestamp(self, level_name, expected): record = self.make_record('hello\nworld', level_name=level_name)