Repository: pypa/pip
Pull request: Prefix user_log (--log) entries with timestamp
Why? Eases post-facto analysis of time spent in different phases of pip operation.

Historical note:
https://github.com/pypa/pip/commit/767d11e49cb916e2d4637421d524efcb8d02ae8d#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 https://github.com/pypa/pip/issues/6141


Problem statement:
Time-stamp lines emitted to user_log.
**What's the problem this feature will solve?**
Enable post-facto analysis of pip operation running time.

**Describe the solution you'd like**
Prefix each line in the user_log (a.k.a. --log) with its timestamp.

Example use-case: pip user notes installation of a package takes a long time to complete; by inspecting the log they can see which sub-phase(s) of `pip install` took the lion's share of the time.

**Alternative Solutions**
Pip can be wrapped with a script that logs start/end time, and/or prefixes every line of output from pip with a timestamp. Biggest drawback is incompatibility with e.g. `python -m pip`-based invocations.

**Additional context**
I'll be sending a PR with an implementation proposal shortly (creating this issue first for to make a news/ entry).

Hints from issue discussion:
@fischman You can disregard my previous message.
I don't think this should be in pip's output by default. I'm okay with providing this functionality behind a flag.
Agreed. This should not be in the default output - whether it needs a dedicated flag or can be enabled if verbose output is requested, I'm not too worried about personally.
@pradyunsg / @pfmoore: in case it was unclear, this proposal only affects the user_log file, not stdout / console output (which is unchanged). Note that the user_log is already unconditionally at DEBUG level.
@pradyunsg @pfmoore: In the first comment of his PR, @fischman provided an example of what the two outputs (stdout and the log file) would look like with his PR:
https://gist.github.com/fischman/f570886219de5c64a3b695300195c70a

>  in case it was unclear, this proposal only affects the user_log file, not stdout / console output

Ah, sorry. I had missed that. It wasn't unclear, I just missed it while reading too fast. OK, I have no problem with timestamping the log file lines. Sounds like a reasonable (albeit minor) improvement.
> in case it was unclear, this proposal only affects the user_log file, not stdout / console output

Oh, cool. That makes sense to me.

Commit message: Addressed 2nd round of @cjerdonek review comments, take 2 (missed a couple the first time around).

Patch to review:
diff --git a/news/6141.feature b/news/6141.feature
new file mode 100644
index 00000000000..991bf0f4252
--- /dev/null
+++ b/news/6141.feature
@@ -0,0 +1 @@
+Prefix pip's --log file lines with their timestamp.
diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py
index d9b95414482..781ca813ce8 100644
--- a/src/pip/_internal/utils/logging.py
+++ b/src/pip/_internal/utils/logging.py
@@ -44,15 +44,29 @@ 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 = super(IndentingFormatter, 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 +200,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 +227,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": {
diff --git a/tests/unit/test_base_command.py b/tests/unit/test_base_command.py
index 1cd7277c4ce..c64143629bf 100644
--- a/tests/unit/test_base_command.py
+++ b/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):
         """
diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py
new file mode 100644
index 00000000000..037039a0689
--- /dev/null
+++ b/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_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
+
+    def test_format(self, tmpdir):
+        record = logging.makeLogRecord(dict(
+            created=1547704837.4,
+            msg='hello\nworld',
+        ))
+        f = IndentingFormatter(fmt="%(message)s", add_timestamp=False)
+        assert f.format(record) == 'hello\nworld'


Code review comments:
diff_hunk: @@ -44,15 +44,29 @@ 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 = super(IndentingFormatter, self).formatTime(
path: src/pip/_internal/utils/logging.py
text: @user1:
Actually, I'm noticing now this should be `self` rather than `super()` since we are not inside `formatTime()`.

diff_hunk: @@ -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_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
+
+    def test_format(self, tmpdir):
+        record = logging.makeLogRecord(dict(
+            created=1547704837.4,
+            msg='hello\nworld',
+        ))
+        f = IndentingFormatter(fmt="%(message)s", add_timestamp=False)
path: tests/unit/test_logging.py
text: @user1:
It would be better not to pass `add_timestamp` here so the default value can be tested. That is also the code path used by the logging config. (The test can also be moved to be before `test_format_with_timestamp()` for a better ordering.)