Prefix user_log (--log) entries with timestamp (#6142)

Why? Eases post-facto analysis of time spent in different phases of pip operation.

Historical note:
767d11e#diff-b670e3b192038c9ffe810c1a12c0c51fL219
made it so that pip invocations emit zero timestamp information to the log
file. Prior to that each pip invocation's start time was written out (search
that commit's diff for [strftime]).

Result: https://gist.github.com/fischman/f570886219de5c64a3b695300195c70a

Resolves #6141

news/6141.feature

@@ -0,0 +1 @@
+Prefix pip's ``--log`` file lines with their timestamp.

src/pip/_internal/utils/logging.py

@@ -44,15 +44,28 @@ def get_indentation():
 
 
 class IndentingFormatter(logging.Formatter):
+    def __init__(self, *args, **kwargs):
+        """
+        A logging.Formatter obeying containing indent_log contexts.
+
+        :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 format(self, record):
         """
         Calls the standard formatter, but will indent all of the log messages
         by our current indentation level.
         """
-        formatted = logging.Formatter.format(self, record)
+        formatted = super(IndentingFormatter, self).format(record)
+        prefix = ''
+        if self.add_timestamp:
+            prefix = self.formatTime(record, "%Y-%m-%dT%H:%M:%S ")
+        prefix += " " * get_indentation()
         formatted = "".join([
-            (" " * get_indentation()) + line
+            prefix + line
             for line in formatted.splitlines(True)
         ])
         return formatted
@@ -186,6 +199,11 @@ def setup_logging(verbosity, no_color, user_log_file):
                 "()": IndentingFormatter,
                 "format": "%(message)s",
             },
+            "indent_with_timestamp": {
+                "()": IndentingFormatter,
+                "format": "%(message)s",
+                "add_timestamp": True,
+            },
         },
         "handlers": {
             "console": {
@@ -208,7 +226,7 @@ def setup_logging(verbosity, no_color, user_log_file):
                 "class": handler_classes["file"],
                 "filename": additional_log_file,
                 "delay": True,
-                "formatter": "indent",
+                "formatter": "indent_with_timestamp",
             },
         },
         "root": {

tests/unit/test_base_command.py

@@ -1,4 +1,6 @@
 import logging
+import os
+import time
 
 from pip._internal.cli.base_command import Command
 
@@ -38,6 +40,26 @@ class Test_base_command_logging(object):
     options
     """
 
+    def setup(self):
+        self.old_time = time.time
+        time.time = lambda: 1547704837.4
+        # Robustify the tests below to the ambient timezone by setting it
+        # explicitly here.
+        self.old_tz = getattr(os.environ, 'TZ', None)
+        os.environ['TZ'] = 'UTC'
+        # time.tzset() is not implemented on some platforms (notably, Windows).
+        if hasattr(time, 'tzset'):
+            time.tzset()
+
+    def teardown(self):
+        if self.old_tz:
+            os.environ['TZ'] = self.old_tz
+        else:
+            del os.environ['TZ']
+        if 'tzset' in dir(time):
+            time.tzset()
+        time.time = self.old_time
+
     def test_log_command_success(self, tmpdir):
         """
         Test the --log option logs when command succeeds
@@ -46,7 +68,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 'fake' == f.read().strip()[:4]
+            assert f.read().rstrip() == '2019-01-17T06:00:37 fake'
 
     def test_log_command_error(self, tmpdir):
         """
@@ -56,7 +78,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 'fake' == f.read().strip()[:4]
+            assert f.read().startswith('2019-01-17T06:00:37 fake')
 
     def test_log_file_command_error(self, tmpdir):
         """
@@ -66,7 +88,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 'fake' == f.read().strip()[:4]
+            assert f.read().startswith('2019-01-17T06:00:37 fake')
 
     def test_unicode_messages(self, tmpdir):
         """

tests/unit/test_logging.py

@@ -0,0 +1,45 @@
+import logging
+import os
+import time
+
+from pip._internal.utils.logging import IndentingFormatter
+
+
+class TestIndentingFormatter(object):
+    """
+    Test `pip._internal.utils.logging.IndentingFormatter`.
+    """
+
+    def setup(self):
+        # Robustify the tests below to the ambient timezone by setting it
+        # explicitly here.
+        self.old_tz = getattr(os.environ, 'TZ', None)
+        os.environ['TZ'] = 'UTC'
+        # time.tzset() is not implemented on some platforms (notably, Windows).
+        if hasattr(time, 'tzset'):
+            time.tzset()
+
+    def teardown(self):
+        if self.old_tz:
+            os.environ['TZ'] = self.old_tz
+        else:
+            del os.environ['TZ']
+        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 test_format_with_timestamp(self, tmpdir):
+        record = logging.makeLogRecord(dict(
+            created=1547704837.4,
+            msg='hello\nworld',
+        ))
+        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