Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Include milliseconds in pip log timestamps #6587

Closed
chrahunt opened this issue Jun 10, 2019 · 9 comments

Comments

@chrahunt
Copy link
Contributor

commented Jun 10, 2019

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
  2. 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

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

@triage-new-issues triage-new-issues bot added the triage label Jun 10, 2019

@chrahunt chrahunt changed the title Include milliseconds in IndentingFormatter timestamp Include milliseconds in pip log timestamps Jun 10, 2019

@pradyunsg

This comment has been minimized.

Copy link
Member

commented Jun 10, 2019

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).

prefix = self.formatTime(record, "%Y-%m-%dT%H:%M:%S ")


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.

@cjerdonek

This comment has been minimized.

Copy link
Member

commented Jun 10, 2019

(#6142 is the correct link.)

@chrahunt

This comment has been minimized.

Copy link
Contributor Author

commented Jun 11, 2019

@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 can be a reference.

@pradyunsg

This comment has been minimized.

Copy link
Member

commented Jun 11, 2019

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. :/

@pradyunsg

This comment has been minimized.

Copy link
Member

commented Jun 11, 2019

(#6142 is the correct link.)

Fixed. Thanks @cjerdonek! :)

@chrahunt

This comment has been minimized.

Copy link
Contributor Author

commented Jun 11, 2019

That is datetime.strftime, the implementation of formatTime uses 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.

@cjerdonek

This comment has been minimized.

Copy link
Member

commented Jun 11, 2019

If this is going to make things messy, do we really need for this feature to be available in 2.7?

@pfmoore

This comment has been minimized.

Copy link
Member

commented Jun 11, 2019

+1 on implementing it "where available" (and if that means "not in 2.7" then so be it).

@pradyunsg

This comment has been minimized.

Copy link
Member

commented Jun 11, 2019

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.

chrahunt added a commit to chrahunt/pip that referenced this issue Jun 16, 2019

chrahunt added a commit to chrahunt/pip that referenced this issue Jun 16, 2019

chrahunt added a commit to chrahunt/pip that referenced this issue Jun 16, 2019

cjerdonek added a commit that referenced this issue Jun 17, 2019

@lock lock bot added the S: auto-locked label Jul 17, 2019

@lock lock bot locked as resolved and limited conversation to collaborators Jul 17, 2019

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
4 participants
You can’t perform that action at this time.