Repository: pypa/pip
Pull request: Add milliseconds to --log entry timestamps.
Resolves #6587.

<!---
Thank you for your soon to be pull request. Before you submit this, please
double check to make sure that you've added a news file fragment. In pip we
generate our NEWS.rst from multiple news fragment files, and all pull requests
require either a news file fragment or a marker to indicate they don't require
one.

To read more about adding a news file fragment for your PR, please check out
our documentation at: https://pip.pypa.io/en/latest/development/contributing/#news-entries
-->


Problem statement:
Include milliseconds in pip log timestamps
**What's the problem this feature will solve?**

Currently (pip 19.1.1) when running `pip install --log example.log ...`, the log messages traced into `example.log` have timestamps that includes up to the second. For example:

```
2019-06-09T22:29:08 Created temporary directory: /tmp/user/1000/pip-install-a6hvpvbz
2019-06-09T22:29:08 Requirement already satisfied: requests in ./.venv/lib/python3.7/site-packages (2.22.0)
2019-06-09T22:29:08 Requirement already satisfied: certifi>=2017.4.17 in ./.venv/lib/python3.7/site-packages (from requests) (2019.3.9)
```

As a result:

1. log records cannot be easily correlated with logs from tools like strace, ltrace, and sysdig since these tools may output several thousand events in a given second
1. delays less than 2 seconds long are harder to identify from the logs alone - this is relevant when running `pip` many times as part of integration tests for e.g. build backends or dev tools

**Describe the solution you'd like**

It would be great if pip could include milliseconds in the log timestamps.

**Alternative Solutions**

Create a `./sitecustomize.py` containing

```python
import time
from pip._internal.utils.logging import IndentingFormatter

def formatTime(self, record, _format=None):
    return time.strftime(
        f'%Y-%m-%dT%H:%M:%S,{record.msecs:03.0f} ', self.converter(record.created)
    )

IndentingFormatter.formatTime = formatTime
```

then execute `pip` like `PYTHONPATH=$PWD pip install --log example.log ...`, which results in

```
2019-06-10T02:36:11,474 Created temporary directory: /tmp/user/1000/pip-install-oc0qwb1k
2019-06-10T02:36:11,476 Requirement already satisfied: requests in ./.venv/lib/python3.7/site-packages (2.22.0)
2019-06-10T02:36:11,486 Requirement already satisfied: chardet<3.1.0,>=3.0.2 in ./.venv/lib/python3.7/site-packages (from requests) (3.0.4)
```

This isn't really a good approach since it uses pip implementation details.

The actual implementation could be to define `default_time_format = '%Y-%m-%dT%H:%M:%S'` and `default_msec_format = '%s,%03d '` on `IndentingFormatter`.

**Additional context**

N/A

Hints from issue discussion:
Makes sense. This should be easy to fix, by added `.%f` to the end of the format string we use and updating the corresponding tests to include milliseconds in the output (see #6142 for which tests are relevant).

https://github.com/pypa/pip/blob/9c8b2ea759e5c7410eb46e91ec90b6bc9368bb93/src/pip/_internal/utils/logging.py#L132

---

This issue is a good starting point for anyone who wants to start working on pip -- it's simple and the process of fixing this should be a good introduction to pip's development workflow.

(#6142 is the correct link.)
@pradyunsg, `time.strftime` (as used in `Formatter.formatTime`) does not understand `%f` unfortunately. My previous suggestion to override `default_time_format` and `default_msec_format` is not good either since those were introduced in 3.3. Since we still support 2.7, an implementation of `formatTime` is probably a good way to go. The current implementation of [`logging.Formatter.formatTime`](https://github.com/python/cpython/blob/8a8b59c9794674b50b2242698c29038034f4864c/Lib/logging/__init__.py#L606) can be a reference.
> `time.strftime` (as used in `Formatter.formatTime`) does not understand `%f` unfortunately.

https://docs.python.org/2/library/datetime.html#strftime-and-strptime-behavior

It is documented. :/
> (#6142 is the correct link.)

Fixed. Thanks @cjerdonek! :)




That is `datetime.strftime`, the implementation of `formatTime` uses [`time.strftime`](https://docs.python.org/3/library/time.html#time.strftime) which is a different function. For what it's worth I did personally substitute `%f` into the format string as suggested and the output contained `%f` without any replacement.
If this is going to make things messy, do we really need for this feature to be available in 2.7?
+1 on implementing it "where available" (and if that means "not in 2.7" then so be it).
> formatTime uses time.strftime

Whoops! My bad. Thanks for flagging that.

---

(on mobile)

I don't know if this is a py2/py3 is an issue here, since formatTime uses time in both versions.

That said, it shouldn't be difficult to add a formatTime method to our formatter, that does use datetime.

There's also `%(msecs)03d` that can be added after the time when formatting, instead of overriding formatTime.

Basically, if we want to, this is definitely do-able. Almost any approach we take likely work IMO so let's defer discussion until we see a PR for this functionality.

Commit message: Add milliseconds to --log entry timestamps.

Resolves #6587.

Patch to review:
diff --git a/news/6587.feature b/news/6587.feature
new file mode 100644
index 00000000000..d47c206d269
--- /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 a28e88cac35..e5d75d3bc84 100644
--- a/src/pip/_internal/utils/logging.py
+++ b/src/pip/_internal/utils/logging.py
@@ -6,6 +6,7 @@
 import logging.handlers
 import os
 import sys
+import time
 from logging import Filter
 
 from pip._vendor.six import PY2
@@ -92,6 +93,9 @@ def get_indentation():
 
 
 class IndentingFormatter(logging.Formatter):
+
+    default_time_format = '%Y-%m-%dT%H:%M:%S'
+
     def __init__(self, *args, **kwargs):
         """
         A logging.Formatter that obeys the indent_log() context manager.
@@ -118,10 +122,24 @@ def get_message_start(self, formatted, levelno):
 
         return 'ERROR: '
 
+    if PY2:
+        # Compatibility with default_time_format and default_msec_format from
+        # Python >= 3.3.
+        default_msec_format = '%s,%03d'
+
+        def formatTime(self, record, datefmt=None):
+            ct = self.converter(record.created)
+            if datefmt:
+                s = time.strftime(datefmt, ct)
+            else:
+                t = time.strftime(self.default_time_format, ct)
+                s = self.default_msec_format % (t, record.msecs)
+            return s
+
     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 +147,7 @@ def format(self, record):
 
         prefix = ''
         if self.add_timestamp:
-            prefix = self.formatTime(record, "%Y-%m-%dT%H:%M:%S ")
+            prefix = self.formatTime(record) + " "
         prefix += " " * get_indentation()
         formatted = "".join([
             prefix + line
diff --git a/tests/unit/test_base_command.py b/tests/unit/test_base_command.py
index f90aaadf22c..344d24e08f0 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 @@ 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):
         """
diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py
index 28b31af0ea0..ddff2b38d00 100644
--- a/tests/unit/test_logging.py
+++ b/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)


Code review comments:
diff_hunk: @@ -118,18 +122,32 @@ def get_message_start(self, formatted, levelno):
 
         return 'ERROR: '
 
+    if PY2:
+        # Compatibility with default_time_format and default_msec_format from
+        # Python >= 3.3.
+        default_msec_format = '%s,%03d'
+
+        def formatTime(self, record, datefmt=None):
+            ct = self.converter(record.created)
+            if datefmt:
+                s = time.strftime(datefmt, ct)
+            else:
+                t = time.strftime(self.default_time_format, ct)
+                s = self.default_msec_format % (t, record.msecs)
+            return s
path: src/pip/_internal/utils/logging.py
text: @user2:
Hmm, this was the concern I expressed here and that @user1 seemed to agree with: https://github.com/pypa/pip/issues/6587#issuecomment-500651566

For comparison, how simple could the PR look if only Python versions that have the feature out of the box got the enhancement?

@user2:
Also, would it solve things just to use the logging module's default `datefmt`? It looks like that code path uses milliseconds even in Python 2 when I checked.

@author:
Using `default_time_format` only for Python 3 would require at least 1 check in `format` and several in the tests. I updated the PR with a simpler approach that still works for both 2 and 3 and removes this block.

@user2:
Read my second comment, too. I don’t see a reply to that.

@author:
Sorry, I hadn't refreshed the page when I had posted.

Regarding `datefmt`, I see it passed to `formatTime` by the `Formatter.format` method only if we use `%(asctime)` in the general formatter format string ([1](https://github.com/python/cpython/blob/66d47da86aff15be34adbec02596bb3188684c0d/Lib/logging/__init__.py#L666)) and if it is passed to `formatTime` and is truthy then it bypasses the millisecond formatting ([2](https://github.com/python/cpython/blob/66d47da86aff15be34adbec02596bb3188684c0d/Lib/logging/__init__.py#L603)). So I don't think it will work for us here.

@user2:
I'm not sure if you understood my suggestion. I was suggesting changing `self.formatTime(record, "%Y-%m-%dT%H:%M:%S")` to `self.formatTime(record)` in order to use the logging module's default format.

@author:
Ah, you're right I misunderstood. I prefer the current format since it is standard and if parsing would be easier to `split(1)` for each line of the log records. When we drop 2 support this can be cleaned up as in the initial revision (with `default_time_format`) while preserving the same format, but I suspect there will be a lot more refactoring in a lot more places when that happens.