Add milliseconds to --log entry timestamps. (#6621)

Resolves #6587.

Author: chrahunt

news/6587.feature

@@ -0,0 +1 @@
+Update timestamps in pip's ``--log`` file to include milliseconds.

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,16 +121,18 @@ def get_message_start(self, formatted, levelno):
 
     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)
         formatted = message_start + formatted
 
         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

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 @@ def test_log_command_success(self, tmpdir):
         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 @@ def test_log_command_error(self, tmpdir):
         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 @@ def test_log_file_command_error(self, tmpdir):
         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):
         """

tests/unit/test_logging.py

@@ -51,7 +51,10 @@ def teardown(self):
     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 @@ def test_format(self, level_name, expected):
         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)