logging.py broken when running in threading with indent_log context mgr

[rawouter]

• Pip version: 8.1.2 (code is the same in latest development branch)
• Python version: 3.5.2
• Operating System: Mac OS

Description:

Pip logging in threading is broken when installing requirements with ident_log().
The _log_state object in the thread does not have the parent indentation attribute in:
https://github.com/pypa/pip/blob/master/pip/utils/logging.py#L34 (and L38)

See repro below. For the backgroung, this is a traceback I get when installing plugins in errbotio/errbot from within a thread:

Triggered from https://github.com/errbotio/errbot/blob/master/errbot/plugin_manager.py#L58

Traceback (most recent call last):
  File "/app/venv/lib/python3.5/site-packages/pip/commands/install.py", line 310, in run
    wb.build(autobuilding=True)
  File "/app/venv/lib/python3.5/site-packages/pip/wheel.py", line 750, in build
    self.requirement_set.prepare_files(self.finder)
  File "/app/venv/lib/python3.5/site-packages/pip/req/req_set.py", line 370, in prepare_files
    ignore_dependencies=self.ignore_dependencies))
  File "/app/venv/lib/python3.5/site-packages/pip/req/req_set.py", line 476, in _prepare_file
    with indent_log():
  File "/usr/local/lib/python3.5/contextlib.py", line 59, in __enter__
    return next(self.gen)
  File "/app/venv/lib/python3.5/site-packages/pip/utils/logging.py", line 34, in indent_log
    _log_state.indentation += num
AttributeError: '_thread._local' object has no attribute 'indentation'

What I've run:

>>> import threading
>>> _log_state = threading.local()
>>> _log_state.indentation = 0
>>>
>>> print(_log_state.indentation)
0
>>>
>>> def test_child():
...     print(_log_state.indentation)
...
>>>
>>> threading.Thread(target=test_child, args=()).start()
>>> Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/local/Cellar/python3/3.5.2/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 914, in _bootstrap_inner
    self.run()
  File "/usr/local/Cellar/python3/3.5.2/Frameworks/Python.framework/Versions/3.5/lib/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "<stdin>", line 2, in test_child
AttributeError: '_thread._local' object has no attribute 'indentation'

[kdschlosser]

I to have the same error when installing from inside a thread

[pfmoore]

I'm not quite sure how the test_child code snippet relates to pip, but regardless, pip does not have a supported programming API - the only supported way of calling pip from within another program is via subprocess.Popen or similar. Specifically, there are no guarantees that pip would be thread safe if you use its internal APIs from multiple threads.

I'd recommend changing your plugin manager to call pip via subprocess.Popen.

[kdschlosser]

I have a workaround. It sets the attribute indentation in pip.utils.logging._log_state

setattr(pip.func_globals['utils'].logging._log_state, 'indentation', 0)

I know it's not ideal. but stopped the indentation problem. now i have an issue with it not getting the ssl. if you could let me know if you encounter the same that would be helpful.

[rawouter]

@pfmoore I don't own the project facing this issue, yet I didn't expect pip did not support programming API given the enormous examples using of pip.main() you can find out there. It's a very convenient way to invoke pip from within a program, but I understand the concern for not being thread safe, good to know!

This error comes from the utils/logging.py module which seemed to have a context manager (indent_log) written to support threading:
https://github.com/pypa/pip/blob/master/pip/utils/logging.py#L24
The test_child code snipped is just a demo that the code inside logging.py can't work as intended if indent_log supports threading.

If indent_log does not support threading, then using the object returned by threading.local() to store the indentation level seems useless and confusing (and error prone). I found this older bug before opening this one, which fixes exactly the same problem, but only at one place...
#2553
The same fix at L34 and L38 would work.

[pfmoore]

@rawouter I'd suggest you report to the upstream project that their usage of pip is unsupported.

Other than that, all I can suggest is that if you were to raise a PR to fix this issue, one of the pip devs may be willing to merge it (I won't, because I don't want to get sucked into the rabbit hole of threading issues). But running pip on a thread remains a bad idea. What if 2 threads run pip.main simultaneously? There's a very good chance that would break badly, as nothing in pip is designed to be thread safe.

[rawouter]

Thanks @pfmoore ! Reported upstream.

I don't think it's wise to raise a PR in this case indeed, at least this issue will prevent some usage of pip in threading and the trace should link to this issue.

Is it worth to document this further, or to review the logging.py code to remove the usage threading there?

[mitar]

I made #4654 to address this.

[pfmoore]

Summary (for clarity) pip does not support use in-process via its internal API, and in particular the pip code makes no guarantees that it can be used safely in the presence of threads.