【问题标题】:Python program hangs forever when called from subprocess从子进程调用 Python 程序永远挂起
【发布时间】:2014-08-22 17:36:30
【问题描述】:

pip 测试套件使用子进程调用来运行集成测试。最近放置了一个 PR,它删除了一些旧的兼容性代码。具体来说,它用显式使用 b"" 文字替换了 b() 函数。然而,这似乎破坏了某个特定子进程调用将永远挂起的地方。更糟糕的是,它只会在 Python 3.3(可能只有 Python 3.3.5)上永远挂起,而且在 Travis 之外无法轻易复制。

相关的拉取请求:

其他拉取请求也会出现类似的问题,但是它们在不同版本的 Python 和不同的测试用例上会失败。这些拉取请求是:

另一位用户今天在 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'\r\n'(entry + endline).encode("utf-8") 的更改都会触发它,但是这些东西都不在pip install -vvv INITools 的执行路径中,这是它无法执行的命令。

在尝试追查问题时,我注意到如果我用(lambda: "something")().encode("utf8") 替换至少一个对"something".encode("utf8") 的调用,它会起作用。

尝试调试时的另一个问题是,我尝试过的各种事情(添加打印语句、无操作 atexit 函数、将 trollious 用于异步子进程)只会将问题从特定测试用例转移到针对不同 Python 版本上的不同测试用例的特定 Python 版本。

我知道如果您直接从subprocess.Popen().stdout/stderr/stdin 读/写,subprocess 模块可能会死锁。但是,此代码使用的是应该可以解决这些问题的 communicate() 方法。正是在 wait() 调用内部,communicate() 执行该进程,该进程将永远挂起,等待 pip 进程退出。

其他信息:

  • 它非常糟糕,我已经设法让它消失或根据各种不应该对其产生任何影响的事情进行转移。
  • 我一直跟踪 pip 内部的执行,一直到代码路径的末尾,直到调用 sys.exit()
  • sys.exit() 替换为 os._exit() 可以解决所有挂起的问题,但我不想这样做,因为我们会跳过 Python 解释器所做的清理工作。
  • 没有其他线程在运行(通过threading.enumerate 验证)。
  • 我已经进行了一些更改组合,即使没有将subprocess.PIPE 用于 stdout/stderr/stdin,它也会挂起,但是如果不使用其他组合,它不会挂起(或者它会转移到不同的测试用例/python 版本)。
  • 它似乎与时间无关,任何特定的提交要么在受影响的测试用例/Python 上 100% 的时间失败,要么在 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 有关? pip._vendor.cachecontrol.filewrapper 中的 Filewrapper 用作 urllib3 响应对象(它是 io.IOBase 的子类)的包装器,以便我们可以使用 read() 方法将每个读取调用的结果存储在缓冲区中并返回它,然后在文件被完全使用后,使用该缓冲区的内容运行回调,以便我们可以将项目存储在缓存中。这会以某种方式与 GC 交互吗?

更新 #2

如果我将 def __del__(self): pass 方法添加到 Filewrapper 类,那么在我尝试过的情况下一切正常。我进行了测试以确保这不是因为我碰巧定义了一个方法(有时会“修复”它),将其更改为def __del2__(self): pass,然后它又开始失败了。我不确定为什么这确实有效,并且无操作 __del__ 方法似乎不是最佳的。

更新 #3

在一直挂着的pip命令执行过程中两次向stderr添加import gc; gc.set_debug(gc.DEBUG_UNCOLLECTABLE)打印的东西,分别是:

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>]

这是有用的信息吗?我以前从未使用过那个标志,所以我不知道这是否不寻常。

【问题讨论】:

  • 哇,当你说这很奇怪时,你不是在开玩笑......在 sys.exit() 调用之前显式刷新输出流有什么不同吗?
  • faulthandler.dump_traceback_later() 也可能有用。它不在 3.2 的 stdlib 中,但 PyPI 版本应该可以工作:pypi.python.org/pypi/faulthandler
  • 我快速浏览了“子进程挂起”错误列表,但没有发现任何明显的罪魁祸首:bugs.python.org/…
  • 这种看似随机无害变化的行为“改变”了时间问题的行为,可能与执行 GC 收集的时间有关。如果更改 GC 检查间隔会发生什么?从慢 1 到高值甚至禁用。你能指出我在 pip 中的 subprocess.POpen 调用吗?
  • 当您添加 __del__ 方法时,错误行为消失的事实向我表明,在关闭期间它的破坏会导致问题出现一个循环,因此使其无法收集可以消除问题。有了__del__gc.set_debug(gc.DEBUG_UNCOLLECTABLE) 可能会提供一些关于stderr 的有用信息。 (另外,gc.set_threshold() 控制执行循环清理的频率)

标签: python subprocess


【解决方案1】:

在 Python 2 中,如果一组对象以链(引用循环)的形式链接在一起,并且至少有一个对象具有 __del__ 方法,则垃圾收集器不会删除这些对象。如果您有引用循环,添加__del__() 方法可能只是隐藏错误(解决方法错误)。

根据您的更新 #3,您似乎遇到了这样的问题。

【讨论】:

  • 找到并解决此问题的最佳方法是什么?我以前从来没有真正处理过这个,所以对我来说这是一个新的:)
  • 鉴于您在评论中提到的 PR,听起来您发现了有问题的循环并且能够显式打破它以避免依赖循环 GC(因此可能会在错误的时间删除东西关掉)。我不知道有什么比像您一样涉水通过 GC 调试统计信息更好的选择。
  • 问题不在于缺乏收集,而是它挂起的事实。我假设正在发生的事情是它在解释器关闭时遇到问题。
猜你喜欢
  • 2013-08-18
  • 2020-05-06
  • 1970-01-01
  • 2017-02-28
  • 2015-01-09
  • 2018-01-10
  • 2016-11-02
  • 2012-09-07
  • 2015-07-07
相关资源
最近更新 更多