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

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

Соответствующие запросы на оттяжку:

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

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 [email protected]: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'\r\n' или (entry + endline).encode("utf-8"), однако ни одна из этих вещей не находится в пути выполнения для pip install -vvv INITools, который является командой, которую он не может выполнить.

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

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

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

Дополнительная информация:

Это очень heisenbug-ey, мне удалось заставить его уйти или сдвинуться, основываясь на разных вещах, которые не должны влиять на него.
Я проследил выполнение внутри самого пипса до конца путей кода до тех пор, пока не будет вызываться sys.exit().
Замена sys.exit() на os._exit() устраняет все проблемы с зависанием, однако я бы предпочел не делать этого, поскольку мы пропустим очистку, которую выполняет интерпретатор Python.
Нет дополнительных потоков (проверено с помощью threading.enumerate).
У меня была некоторая комбинация изменений, в которых она зависала даже без subprocess.PIPE, используемой для stdout/stderr/stdin, однако в других комбинациях она не будет зависать, если они не используются (или она перейдет в другой вариант теста/версия python).
Кажется, что это не связано с хронометром, любая конкретная фиксация либо завершит 100% времени на тестовых примерах влияния /Pythons, либо завершится ошибкой 0% времени.
Часто код, который был изменен, даже не выполняется этим конкретным кодом в подпроцессе pip, однако простое существование изменения, похоже, нарушает его.
Я попытался отключить генерацию байт-кода, используя PYTHONDONTWRITEBYTECODE=1, и это имело эффект в одной комбинации, но в других это не имело никакого эффекта.
Команда, вызываемая вызовом подпроцесса, не зависает в каждом вызове (аналогичные команды выдаются через набор тестов), однако она всегда зависает в том же месте для конкретной фиксации.
До сих пор я полностью не смог воспроизвести это за пределами вызова через subproccess в тестовом наборе, однако я не знаю, факт, если он или не связан с этим.

Я полностью в недоумении за то, что может быть причиной этого.

ОБНОВЛЕНИЕ # 1

Используя faulthandler.dump_traceback_later(), я получил этот результат:

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__

Это говорит мне, что, возможно, проблема связана с сборкой мусора и urllib3? Filewrapper в pip._vendor.cachecontrol.filewrapper используется как обертка вокруг объекта ответа urllib3 (какие подклассы io.IOBase), так что мы можем использовать метод read() для хранения результатов каждого запроса на чтение в буфере, а также для возврата он, а затем, как только файл был полностью использован, выполните обратный вызов с содержимым этого буфера, чтобы мы могли сохранить элемент в кеше. Может ли это каким-то образом взаимодействовать с GC?

Обновление # 2

Если я добавлю метод def __del__(self): pass в класс Filewrapper, тогда все работает правильно в тех случаях, которые я пробовал. Я проверил, чтобы это произошло не потому, что мне просто удалось определить метод (который иногда "исправляет" ), изменив его на def __del2__(self): pass, и он снова начал сбой. Я не уверен, почему это работает точно, и метод no-op __del__ кажется менее оптимальным.

Обновление # 3

Добавление import gc; gc.set_debug(gc.DEBUG_UNCOLLECTABLE) печатных материалов в stderr два раза во время выполнения команды pip, которая была висит, это:

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