Repository: pypa/pip

Issue:
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

Discussion:

Patch:
diff --git a/news/6527.bugfix b/news/6527.bugfix
new file mode 100644
index 000000000..92d29d9ff
--- /dev/null
+++ b/news/6527.bugfix
@@ -0,0 +1,2 @@
+Add the line number and file location to the error message when reading an
+invalid requirements file in certain situations.
diff --git a/news/6587.feature b/news/6587.feature
new file mode 100644
index 000000000..d47c206d2
--- /dev/null
+++ b/news/6587.feature
@@ -0,0 +1,1 @@
+Update timestamps in pip's ``--log`` file to include milliseconds.
diff --git a/src/pip/_internal/req/constructors.py b/src/pip/_internal/req/constructors.py
index 99df626b7..d0b0c7153 100644
--- a/src/pip/_internal/req/constructors.py
+++ b/src/pip/_internal/req/constructors.py
@@ -205,11 +205,15 @@ def install_req_from_line(
     isolated=False,  # type: bool
     options=None,  # type: Optional[Dict[str, Any]]
     wheel_cache=None,  # type: Optional[WheelCache]
-    constraint=False  # type: bool
+    constraint=False,  # type: bool
+    line_source=None,  # type: Optional[str]
 ):
     # type: (...) -> InstallRequirement
     """Creates an InstallRequirement from a name, which might be a
     requirement, directory containing 'setup.py', filename, or URL.
+
+    :param line_source: An optional string describing where the line is from,
+        for logging purposes in case of an error.
     """
     if is_url(name):
         marker_sep = '; '
@@ -289,10 +293,17 @@ def install_req_from_line(
                   not any(op in req_as_string for op in operators)):
                 add_msg = "= is not a valid operator. Did you mean == ?"
             else:
-                add_msg = ""
-            raise InstallationError(
-                "Invalid requirement: '%s'\n%s" % (req_as_string, add_msg)
+                add_msg = ''
+            if line_source is None:
+                source = ''
+            else:
+                source = ' (from {})'.format(line_source)
+            msg = (
+                'Invalid requirement: {!r}{}'.format(req_as_string, source)
             )
+            if add_msg:
+                msg += '\nHint: {}'.format(add_msg)
+            raise InstallationError(msg)
     else:
         req = None
 
diff --git a/src/pip/_internal/req/req_file.py b/src/pip/_internal/req/req_file.py
index ee62171da..bfad9d161 100644
--- a/src/pip/_internal/req/req_file.py
+++ b/src/pip/_internal/req/req_file.py
@@ -138,7 +138,7 @@ def process_line(
     session=None,  # type: Optional[PipSession]
     wheel_cache=None,  # type: Optional[WheelCache]
     use_pep517=None,  # type: Optional[bool]
-    constraint=False  # type: bool
+    constraint=False,  # type: bool
 ):
     # type: (...) -> Iterator[InstallRequirement]
     """Process a single requirements line; This can result in creating/yielding
@@ -187,10 +187,16 @@ def process_line(
         for dest in SUPPORTED_OPTIONS_REQ_DEST:
             if dest in opts.__dict__ and opts.__dict__[dest]:
                 req_options[dest] = opts.__dict__[dest]
+        line_source = 'line {} of {}'.format(line_number, filename)
         yield install_req_from_line(
-            args_str, line_comes_from, constraint=constraint,
+            args_str,
+            comes_from=line_comes_from,
             use_pep517=use_pep517,
-            isolated=isolated, options=req_options, wheel_cache=wheel_cache
+            isolated=isolated,
+            options=req_options,
+            wheel_cache=wheel_cache,
+            constraint=constraint,
+            line_source=line_source,
         )
 
     # yield an editable requirement
diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py
index e0578875d..71849a4fb 100644
--- a/src/pip/_internal/req/req_install.py
+++ b/src/pip/_internal/req/req_install.py
@@ -485,41 +485,42 @@ class InstallRequirement(object):
         use_pep517 attribute can be used to determine whether we should
         follow the PEP 517 or legacy (setup.py) code path.
         """
-        pep517_data = load_pyproject_toml(
+        pyproject_toml_data = load_pyproject_toml(
             self.use_pep517,
             self.pyproject_toml,
             self.setup_py,
             str(self)
         )
 
-        if pep517_data is None:
-            self.use_pep517 = False
-        else:
-            self.use_pep517 = True
-            requires, backend, check = pep517_data
-            self.requirements_to_check = check
-            self.pyproject_requires = requires
-            self.pep517_backend = Pep517HookCaller(self.setup_py_dir, backend)
+        self.use_pep517 = (pyproject_toml_data is not None)
 
-            # Use a custom function to call subprocesses
-            self.spin_message = ""
+        if not self.use_pep517:
+            return
 
-            def runner(
-                cmd,  # type: List[str]
-                cwd=None,  # type: Optional[str]
-                extra_environ=None  # type: Optional[Mapping[str, Any]]
-            ):
-                # type: (...) -> None
-                with open_spinner(self.spin_message) as spinner:
-                    call_subprocess(
-                        cmd,
-                        cwd=cwd,
-                        extra_environ=extra_environ,
-                        spinner=spinner
-                    )
-                self.spin_message = ""
+        requires, backend, check = pyproject_toml_data
+        self.requirements_to_check = check
+        self.pyproject_requires = requires
+        self.pep517_backend = Pep517HookCaller(self.setup_py_dir, backend)
+
+        # Use a custom function to call subprocesses
+        self.spin_message = ""
+
+        def runner(
+            cmd,  # type: List[str]
+            cwd=None,  # type: Optional[str]
+            extra_environ=None  # type: Optional[Mapping[str, Any]]
+        ):
+            # type: (...) -> None
+            with open_spinner(self.spin_message) as spinner:
+                call_subprocess(
+                    cmd,
+                    cwd=cwd,
+                    extra_environ=extra_environ,
+                    spinner=spinner
+                )
+            self.spin_message = ""
 
-            self.pep517_backend._subprocess_runner = runner
+        self.pep517_backend._subprocess_runner = runner
 
     def prepare_metadata(self):
         # type: () -> None
diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py
index a28e88cac..14aee6d3e 100644
--- a/src/pip/_internal/utils/logging.py
+++ b/src/pip/_internal/utils/logging.py
@@ -92,6 +92,7 @@ def get_indentation():
 
 
 class IndentingFormatter(logging.Formatter):
+
     def __init__(self, *args, **kwargs):
         """
         A logging.Formatter that obeys the indent_log() context manager.
@@ -120,8 +121,8 @@ class IndentingFormatter(logging.Formatter):
 
     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 +130,9 @@ class IndentingFormatter(logging.Formatter):
 
         prefix = ''
         if self.add_timestamp:
-            prefix = self.formatTime(record, "%Y-%m-%dT%H:%M:%S ")
+            # TODO: Use Formatter.default_time_format after dropping PY2.
+            t = self.formatTime(record, "%Y-%m-%dT%H:%M:%S")
+            prefix = '%s,%03d ' % (t, record.msecs)
         prefix += " " * get_indentation()
         formatted = "".join([
             prefix + line


Test patch:
diff --git a/tests/unit/test_base_command.py b/tests/unit/test_base_command.py
index f90aaadf2..344d24e08 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 @@ class Test_base_command_logging(object):
         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 @@ class Test_base_command_logging(object):
         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 @@ class Test_base_command_logging(object):
         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 28b31af0e..ddff2b38d 100644
--- a/tests/unit/test_logging.py
+++ b/tests/unit/test_logging.py
@@ -51,7 +51,10 @@ class TestIndentingFormatter(object):
     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 @@ class TestIndentingFormatter(object):
         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)
diff --git a/tests/unit/test_req.py b/tests/unit/test_req.py
index 3f8c38ce5..a7f830475 100644
--- a/tests/unit/test_req.py
+++ b/tests/unit/test_req.py
@@ -530,7 +530,7 @@ class TestInstallRequirement(object):
         with pytest.raises(InstallationError) as e:
             install_req_from_line(test_name)
         err_msg = e.value.args[0]
-        assert ("Invalid requirement: '%s'\n" % test_name) == err_msg
+        assert "Invalid requirement: '{}'".format(test_name) == err_msg
 
     def test_requirement_file(self):
         req_file_path = os.path.join(self.tempdir, 'test.txt')
diff --git a/tests/unit/test_req_file.py b/tests/unit/test_req_file.py
index 972d84684..0bebb46de 100644
--- a/tests/unit/test_req_file.py
+++ b/tests/unit/test_req_file.py
@@ -191,6 +191,26 @@ class TestProcessLine(object):
         with pytest.raises(InstallationError):
             list(process_line("req1 req2", "file", 1))
 
+    def test_error_message(self):
+        """
+        Test the error message if a parsing error occurs (all of path,
+        line number, and hint).
+        """
+        iterator = process_line(
+            'my-package=1.0',
+            filename='path/requirements.txt',
+            line_number=3
+        )
+        with pytest.raises(InstallationError) as exc:
+            list(iterator)
+
+        expected = (
+            "Invalid requirement: 'my-package=1.0' "
+            '(from line 3 of path/requirements.txt)\n'
+            'Hint: = is not a valid operator. Did you mean == ?'
+        )
+        assert str(exc.value) == expected
+
     def test_yield_line_requirement(self):
         line = 'SomeProject'
         filename = 'filename'