Prefix user_log (--log) entries with timestamp

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