Программа Python зависает навсегда при вызове из подпроцесса

#python #subprocess

#python #подпроцесс

Вопрос:

Набор тестов pip использует вызовы подпроцесса для запуска интеграционных тестов. Недавно был размещен PR, который удалил некоторый старый код совместимости. В частности, он заменил b() функцию явным использованием b"" литерала. Однако это, по-видимому, привело к тому, что конкретный вызов подпроцесса будет зависать вечно. Что еще хуже, она зависает навсегда только на Python 3.3 (возможно, только на Python 3.3.5), и ее нелегко воспроизвести за пределами Travis.

Соответствующие запросы на извлечение:

Аналогичная проблема возникает с другими запросами на извлечение, однако они терпят неудачу в разных версиях Python и в разных тестовых примерах. Эти запросы на извлечение являются:

https://github.com/pypa/pip/pull/1882
https://github.com/pypa/pip/pull/1912 (Снова Python 3.3)

Другой пользователь сообщил мне об аналогичной проблеме сегодня в IRC, они говорят, что могут воспроизвести ее локально на Ubuntu 14.04 с помощью Python 3.3 от deadsnakes (но не на OSX), а не только на Travis, как я в основном мог до сих пор. Они прислали мне шаги для воспроизведения, которые:

 $ git clone git@github.com:xavfernandez/pip.git
$ cd pip
$ git checkout debug_stuck
$ pip install pytest==2.5.2 scripttest==1.3 virtualenv==1.11.6 mock==1.0.1 pretend==1.0.8 setuptools==4.0
$ # The below should pass just fine
$ py.test -k test_env_vars_override_config_file -v -s
$ # Now edit pip/req/req_set.py and remove method remove_me_to_block or change its content to print('KO') or pass
$ # The below should hang forever
$ py.test -k test_env_vars_override_config_file -v -s

В приведенном выше примере remove_me_to_block метод нигде не вызывается, простого его существования достаточно, чтобы сделать тест не блокируемым, а его отсутствия (или изменения его содержимого) достаточно, чтобы сделать тестовый блок навсегда.

Большая часть отладки была связана с изменениями в этом PR (https://github.com/pypa/pip/pull/1901 ). После нажатия одной фиксации за раз тесты проходили до тех пор, пока не была применена эта конкретная фиксация — https://github.com/dstufft/pip/commit/d296df620916b4cd2379d9fab988cbc088e28fe0. В частности, либо изменение для использования, b'rn' либо (entry endline).encode("utf-8") вызовет его, однако ни одна из этих вещей не находится в пути выполнения, для pip install -vvv INITools которого команда не может выполнить.

Пытаясь отследить проблему, я заметил, что если я заменю хотя бы один вызов на "something".encode("utf8") на (lambda: "something")().encode("utf8") , это сработает.

Еще одна проблема при попытке отладить это заключалась в том, что различные вещи, которые я пробовал (добавление операторов печати, функций no-op atexit , использование trollious для асинхронного подпроцесса), просто перенесут проблему с конкретного тестового случая в конкретной версии Python на разные тестовые случаи в разных версиях Python.

Я осознаю тот факт, что subprocess модуль может зайти в тупик, если вы читаете / записываете из subprocess.Popen().stdout/stderr/stdin напрямую. Однако этот код использует communicate() метод, который должен обойти эти проблемы. Именно внутри wait() вызова, который communicate() выполняет, процесс зависает навсегда, ожидая завершения процесса pip.

Other information:

It is very heisenbug-ey, I’ve managed to make it go away or shift based on various things that should not have any affect on it.
I’ve traced the execution inside of pip itself all the way through to the end of the code paths until sys.exit() is called.
Replacing sys.exit() with os._exit() fixes all the hanging issues, however I’d rather not do that as we’re then skipping the clean up that the Python interpreter does.
There are no additional threads running (verified with threading.enumerate ).
I’ve had some combination of changes which have had it hang even without subprocess.PIPE being used for stdout/stderr/stdin, however other combinations will have it not hang if those are not used (or it’ll shift to a different test case/python version).
It does not appear to be timing related, any particular commit will either fail 100% of the time on the affect test cases/Pythons or fail 0% of the time.
Often times the code that was changed isn’t even being executed by that particular code path in the pip subprocess, however the mere existence of the change seems to break it.
I’ve tried disabling bytecode generation using PYTHONDONTWRITEBYTECODE=1 and that had an effect in one combination, but in others it’s had no effect.
The command that the subprocess calls does not hang in every invocation (similar commands are issued through the test suite) however it does always hang in the exact same place for a particular commit.
So far i’ve been completely unable to reproduce this outside of being called via subproccess in the test suite, however I don’t know for a fact if it is or isn’t related to that.

I’m completely at a loss for what could be causing this.

UPDATE #1

Using faulthandler.dump_traceback_later() I got this result:

 Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/requests/packages/urllib3/response.py", line 287 in closed
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/requests/packages/urllib3/response.py", line 287 in closed
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
Timeout (0:00:05)!
Current thread 0x00007f417bd92740:
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/requests/packages/urllib3/response.py", line 285 in closed
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__
  [ Duplicate Lines Snipped ]
  File "/tmp/pytest-10/test_env_vars_override_config_file0/pip_src/pip/_vendor/cachecontrol/filewrapper.py", line 24 in __getattr__

This suggests to me that maybe the problem is something to do with the garbage collection and urllib3? The Filewrapper in pip._vendor.cachecontrol.filewrapper is used as a wrapper around a urllib3 response object (which subclasses io.IOBase ) so that we can tee the read() method to store the results of each read call in a buffer as well as returning it, and then once the file has been completely consumed run a callback with the contents of that buffer so that we can store the item in the cache. Could this be interacting with the GC in some way?

Update #2

If I add a def __del__(self): pass method to the Filewrapper class, then everything works correctly in the cases I’ve tried. I tested to ensure that this wasn’t because I just happened to define a method (which «fixes» it sometimes) by changing that to def __del2__(self): pass and it started failing again. I’m not sure why this works exactly and a no-op __del__ method seems like it’s less than optimal.

Update #3

Adding a import gc; gc.set_debug(gc.DEBUG_UNCOLLECTABLE) printed stuff to stderr twice during the execution of the pip command that has been hanging, they are:

 gc: uncollectable <CallbackFileWrapper 0x7f66385c1cd0>
gc: uncollectable <dict 0x7f663821d5a8>
gc: uncollectable <functools.partial 0x7f663831de10>
gc: uncollectable <_io.BytesIO 0x7f663804dd50>
gc: uncollectable <method 0x7f6638219170>
gc: uncollectable <tuple 0x7f663852bd40>
gc: uncollectable <HTTPResponse 0x7f663831c7d0>
gc: uncollectable <PreparedRequest 0x7f66385c1a90>
gc: uncollectable <dict 0x7f663852cb48>
gc: uncollectable <dict 0x7f6637fdcab8>
gc: uncollectable <HTTPHeaderDict 0x7f663831cb90>
gc: uncollectable <CaseInsensitiveDict 0x7f66385c1ad0>
gc: uncollectable <dict 0x7f6638218ab8>
gc: uncollectable <RequestsCookieJar 0x7f663805d7d0>
gc: uncollectable <dict 0x7f66382140e0>
gc: uncollectable <dict 0x7f6638218680>
gc: uncollectable <list 0x7f6638218e18>
gc: uncollectable <dict 0x7f6637f14878>
gc: uncollectable <dict 0x7f663852c5a8>
gc: uncollectable <dict 0x7f663852cb00>
gc: uncollectable <method 0x7f6638219d88>
gc: uncollectable <DefaultCookiePolicy 0x7f663805d590>
gc: uncollectable <list 0x7f6637f14518>
gc: uncollectable <list 0x7f6637f285a8>
gc: uncollectable <list 0x7f6637f144d0>
gc: uncollectable <list 0x7f6637f14ab8>
gc: uncollectable <list 0x7f6637f28098>
gc: uncollectable <list 0x7f6637f14c20>
gc: uncollectable <list 0x7f6637f145a8>
gc: uncollectable <list 0x7f6637f14440>
gc: uncollectable <list 0x7f663852c560>
gc: uncollectable <list 0x7f6637f26170>
gc: uncollectable <list 0x7f663821e4d0>
gc: uncollectable <list 0x7f6637f2d050>
gc: uncollectable <list 0x7f6637f14fc8>
gc: uncollectable <list 0x7f6637f142d8>
gc: uncollectable <list 0x7f663821d050>
gc: uncollectable <list 0x7f6637f14128>
gc: uncollectable <tuple 0x7f6637fa8d40>
gc: uncollectable <tuple 0x7f66382189e0>
gc: uncollectable <tuple 0x7f66382183f8>
gc: uncollectable <tuple 0x7f663866cc68>
gc: uncollectable <tuple 0x7f6637f1e710>
gc: uncollectable <tuple 0x7f6637fc77a0>
gc: uncollectable <tuple 0x7f6637f289e0>
gc: uncollectable <tuple 0x7f6637f19f80>
gc: uncollectable <tuple 0x7f6638534d40>
gc: uncollectable <tuple 0x7f6637f259e0>
gc: uncollectable <tuple 0x7f6637f1c7a0>
gc: uncollectable <tuple 0x7f6637fc8c20>
gc: uncollectable <tuple 0x7f6638603878>
gc: uncollectable <tuple 0x7f6637f23440>
gc: uncollectable <tuple 0x7f663852c248>
gc: uncollectable <tuple 0x7f6637f2a0e0>
gc: uncollectable <tuple 0x7f66386a6ea8>
gc: uncollectable <tuple 0x7f663852f9e0>
gc: uncollectable <tuple 0x7f6637f28560>

и затем

 gc: uncollectable <CallbackFileWrapper 0x7f66385c1350>
gc: uncollectable <dict 0x7f6638c33320>
gc: uncollectable <HTTPResponse 0x7f66385c1590>
gc: uncollectable <functools.partial 0x7f6637f03ec0>
gc: uncollectable <_io.BytesIO 0x7f663804d600>
gc: uncollectable <dict 0x7f6637f1f680>
gc: uncollectable <method 0x7f663902d3b0>
gc: uncollectable <tuple 0x7f663852be18>
gc: uncollectable <HTTPMessage 0x7f66385c1c10>
gc: uncollectable <HTTPResponse 0x7f66385c1450>
gc: uncollectable <PreparedRequest 0x7f66385cac50>
gc: uncollectable <dict 0x7f6637f2f248>
gc: uncollectable <dict 0x7f6637f28b90>
gc: uncollectable <dict 0x7f6637f1e638>
gc: uncollectable <list 0x7f6637f26cb0>
gc: uncollectable <list 0x7f6637f2f638>
gc: uncollectable <HTTPHeaderDict 0x7f66385c1f90>
gc: uncollectable <CaseInsensitiveDict 0x7f66385b2890>
gc: uncollectable <dict 0x7f6638bd9200>
gc: uncollectable <RequestsCookieJar 0x7f663805da50>
gc: uncollectable <dict 0x7f6637f28a28>
gc: uncollectable <dict 0x7f663853aa28>
gc: uncollectable <list 0x7f663853a6c8>
gc: uncollectable <dict 0x7f6638ede5f0>
gc: uncollectable <dict 0x7f6637f285f0>
gc: uncollectable <dict 0x7f663853a4d0>
gc: uncollectable <method 0x7f663911f710>
gc: uncollectable <DefaultCookiePolicy 0x7f663805d210>
gc: uncollectable <list 0x7f6637f28ab8>
gc: uncollectable <list 0x7f6638215050>
gc: uncollectable <list 0x7f663853a200>
gc: uncollectable <list 0x7f6638215a28>
gc: uncollectable <list 0x7f663853a950>
gc: uncollectable <list 0x7f663853a998>
gc: uncollectable <list 0x7f6637f21638>
gc: uncollectable <list 0x7f6637f0cd40>
gc: uncollectable <list 0x7f663853ac68>
gc: uncollectable <list 0x7f6637f22c68>
gc: uncollectable <list 0x7f663853a170>
gc: uncollectable <list 0x7f6637fa6a28>
gc: uncollectable <list 0x7f66382153b0>
gc: uncollectable <list 0x7f66386a5e60>
gc: uncollectable <list 0x7f663852f2d8>
gc: uncollectable <list 0x7f66386a3320>
    [<pip._vendor.cachecontrol.filewrapper.CallbackFileWrapper object at 0x7f66385c1cd0>, <pip._vendor.cachecontrol.filewrapper.CallbackFileWrapper object at 0x7f66385c1350>]

Это полезная информация? Я никогда раньше не использовал этот флаг, поэтому понятия не имею, необычно это или нет.

1. Вау, ты не шутил, когда сказал, что это странно … имеет ли значение явная очистка выходных потоков перед вызовом sys.exit()?

2. faulthandler.dump_traceback_later() также может быть полезен. Этого нет в stdlib в версии 3.2, но версия PyPI должна работать: pypi.python.org/pypi/faulthandler

3. Я быстро просмотрел список ошибок «зависания подпроцесса», но не увидел ни одной, которая выглядела бы как очевидные виновники: bugs.python.org /…

4. Этот тип поведения с кажущимися случайными безобидными изменениями, «изменяющими» поведение, пахнет проблемой синхронизации, возможно, связанной с тем, когда выполняются коллекции GC. Что произойдет, если вы измените интервал проверки GC? От медленного 1 до высокого значения и даже отключена. Можете ли вы указать мне на подпроцесс. Всплывающий вызов в pip?

5. Тот факт, что неправильное поведение исчезает, когда вы добавляете __del__ метод, наводит меня на мысль, что существует цикл, в котором его разрушение во время завершения работы вызывает проблемы, поэтому невозможность его сбора устраняет проблему. __del__ На месте gc.set_debug(gc.DEBUG_UNCOLLECTABLE) может предоставить некоторую полезную информацию о stderr. (Кроме того, gc.set_threshold() определяет, как часто выполняются циклические очистки)

Ответ №1:

В Python 2, если набор объектов связан вместе в цепочку (ссылочный цикл) и, по крайней мере, у одного объекта есть __del__ метод, сборщик мусора не удалит эти объекты. Если у вас есть ссылочный цикл, добавление __del__() метода может просто скрыть ошибки (обходные ошибки).

Согласно вашему обновлению # 3, похоже, у вас такая проблема.

1. Каков наилучший способ найти и исправить это? Мне никогда раньше не приходилось сталкиваться с этим, поэтому для меня это ново 🙂

2. Учитывая PR, который вы упомянули в комментарии, похоже, что вы нашли нарушающий цикл и смогли явно прервать его, чтобы не полагаться на циклический GC (и, следовательно, потенциально удалять вещи в неподходящее время во время завершения работы). Я не знаю лучшего варианта, чем просматривать статистику отладки GC, как вы это делали.

3. Проблема не в отсутствии коллекции, а в том, что она зависает. Я предполагаю, что происходит то, что она сталкивается с проблемами при завершении работы интерпретатора.