一次调试段错误(segmentation fault)的经验
/ / / 阅读数:17381
段错误 (segmentation fault) 的发生是由于 C 模块试图访问无法访问的内存。如果没有尝鲜最新的 CPython 或者类库或者编写 C/C++ 扩展，段错误对 Python 开发者来说可以说可遇不可求，因为 CPython 和主流第三方类库的测试完善且社区活跃所以很难看到，即便看到了往往也已经被修复了。
昨天恰好遇到一个，所以把整个调试解决过程整理成本文。
问题
我准备在博客应用 lyanna 的 v3.0 版本时支持 Python 3.8 最新的 海象运算符 ，所以拉取了最新的 CPython 源码并编译，在 lyanna 项目中使用它创建虚拟环境并安装依赖。问题就出在安装依赖过程中:
❯ virtualenv venv --python=python3.8 ❯ source venv/bin/activate ❯ pip install -r requirements.txt ... Installing collected packages: aiomcache Running setup.py develop for aiomcache ERROR: Command errored out with exit status -11: command: /Users/dongweiming/lyanna/venv/bin/python3.8 -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/Users/dongweiming/lyanna/venv/src/aiomcache/setup.py'"'"'; __file__='"'"'/Users/dongweiming/lyanna/venv/src/aiomcache/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' develop --no-deps cwd: /Users/dongweiming/lyanna/venv/src/aiomcache/ Complete output (10 lines): running develop running egg_info writing aiomcache.egg-info/PKG-INFO writing dependency_links to aiomcache.egg-info/dependency_links.txt writing top-level names to aiomcache.egg-info/top_level.txt reading manifest file 'aiomcache.egg-info/SOURCES.txt' reading manifest template 'MANIFEST.in' warning: no previously-included files matching '*.pyc' found anywhere in distribution warning: no previously-included files matching '*.swp' found anywhere in distribution writing manifest file 'aiomcache.egg-info/SOURCES.txt' ... |
这里并没有抛出段错误，输出还是很让人困惑的，我查了下退出码 11 (延伸阅读链接 1) 表示段错误，当然还可以直接执行复现:
❯ python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop ... [1] 93545 segmentation fault python3.8 /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop |
和 Python 代码报错有详细的堆栈不一样，段错误的输出不带任何有帮助的信息，不能确定是哪行代码引起的。
faulthandler 模块
看到错误立刻想起来之前看过的 faulthandler 模块，它是 Python 3.3 加入的，我尝试通过它获得堆栈。 首先把下面代码写入 setup.py 头部:
import faulthandler; faulthandler.enable() # 下面是原来的代码 import codecs ... |
然后运行它：
❯ python -Xfaulthandler /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop # 或者: PYTHONFAULTHANDLER=1 /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop ... Fatal Python error: Segmentation fault Current thread 0x000000010fe73dc0 (most recent call first): File "<frozen importlib._bootstrap>", line 219 in _call_with_frames_removed File "<frozen importlib._bootstrap_external>", line 1109 in exec_module File "<frozen importlib._bootstrap>", line 671 in _load_unlocked File "<frozen importlib._bootstrap>", line 975 in _find_and_load_unlocked File "<frozen importlib._bootstrap>", line 991 in _find_and_load File "/Users/dongweiming/lyanna/venv/lib/python3.8/site-packages/Cython/Compiler/Main.py", line 28 in <module> File "<frozen importlib._bootstrap>", line 219 in _call_with_frames_removed File "<frozen importlib._bootstrap_external>", line 783 in exec_module File "<frozen importlib._bootstrap>", line 671 in _load_unlocked File "<frozen importlib._bootstrap>", line 975 in _find_and_load_unlocked ... |
这次的输出可谓详细了很多，注意堆栈顺序和 Python 代码的相反：引起错误的在顶部。
看了下importlib._bootstrap的代码没看出来有问题，而且堆栈提到的这些是 Python 代码的应该不是它。不过这次的堆栈之后要考，大家看看能不能联想到什么？其实这里已经隐隐的显示了问题。
怀疑 aiomcache 代码兼容性问题
接着想到的第一个搜索点就是 aiomcache，但是翻了下 aiomcache 代码，它和其依赖中没有 C 扩展，那应该不是，另外试了下install没有问题:
❯ python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py install ... # 正常 Installed /Users/dongweiming/lyanna/venv/lib/python3.8/site-packages/aiomcache-0.6.0-py3.8.egg Processing dependencies for aiomcache==0.6.0 Finished processing dependencies for aiomcache==0.6.0 |
那可以确定不是 aiomemcache，这个时候我想到:
- 是 setuptools (在 setup.py 中会用到) 及其依赖中的 C 扩展 (在 Python3.8 下) 问题
- 最新的 CPython 代码问题
怀疑最新的 CPython 代码问题
等大家看完全文会发现这里偏了，因为按照几率来说肯定是第三方的库更不靠谱一点... 不过也是合理的，想尝鲜就是非常可能遇到各种还没有人踩到的坑。此时我心中一怔，顺便给 CPython 改 C 代码的机会来的，激动！！
由于这种心情的撺掇，调试方向的天平倾向了 CPython 而不是看 setuptools 依赖链。
接着我加了 DEBUG 标记重新编译了 CPython:
❯ ./configure CFLAGS='-DPy_DEBUG' --with-pydebug && make && make install |
这次最终没有抛段错误，执行正常，很奇怪。接着我不带标记重新编译，上面的错误又重现了，不过我在调试过程发现直接用 CPython 源码目录下编译好的 python 执行正常:
❯ ~/cpython/python.exe /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop |
也就是说用什么都没做的裸 Python 正常，但是在虚拟环境中的 Python 本来也正常，但是安装了一堆依赖后就不正常
直观上，我已经觉得和 CPython 3.8 的源码无关了 (＃￣～￣＃)，但谁引起的段错误还不清楚。
GDB 大法
对于调试 Python 代码，我基本上都会用 print，连 pdb 也用的很少。如果是 C 接口有问题，就需要使用 gdb 了。另外 gdb 也可以用于调试正在运行的 Python 进程。
在 macOS 下使用 Homebrew 安装 gdb:
❯ brew install gdb |
不过此时 GDB 只有基本的 Python 支持，如果你自己编译 GDB 记得加上--with-python选项。接着我们要把 CPython 项目中的 libpython.py 里面提供的命令加进来:
❯ gdb python3 GNU gdb (GDB) 8.3 ... (gdb) python # Python解释器 >import sys # 和写Python代码一样 >sys.path.insert(0, '/Users/dongweiming/cpython/Tools/gdb') # 把包含libpython.py文件的目录加到sys.path里 >import libpython # 导入 >end # 结束Python (gdb) py # 按Tab就可以看到支持多个py-开头的命令了 py-bt py-down py-locals py-up python-interactive py-bt-full py-list py-print python |
导入 libpython 的缺点是每次进入 gdb 都得执行一次，另外一个方法是写入到 GDB 初始化文件.gdbinit中:
source ~/cpython/Tools/gdb/libpython.py |
libpython 的作用是让PyObject*的输出更容易理解，另外新加了上面看到的命令具体用法可以看延伸阅读链接 2。
另外 CPython 官方也维护了一个Misc/gdbinit文件 (见延伸阅读链接 3)，其中提供了 pystack、pyframe、lineno 等命令，它们是针对 gdb 7 之前的版本，我安装的是当前最新的 GDB 8.3，就不需要了
这里要注意一个细节，加了配置后抛段错误前会卡住，需要在.gdbinit里面加这么一句:
set startup-with-shell off
|
Ok, 配置已经完成了，现在运行这个有问题的命令:
❯ gdb python3 (gdb) run /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop Starting program: /Users/dongweiming/lyanna/venv/bin/python3 /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop Unable to find Mach task port for process-id 8888: (os/kern) failure (0x5). (please check gdb is codesigned - see taskgated(8)) |
这是由于权限问题，需要给 gdb 签一个证书。步骤如下 (也可以参考延伸阅读链接 5 里的内容):
- 启动 Keychain Access 应用程序
- 从菜单选择 Certificate Assistant -> Create a Certificate
- 新加一个证书，名字就叫 gdbcert (之后还要用到)，身份类型 self-signed root，证书类型 Code Signing，「Let me override defaults」不用勾，然后 create
- 创建一个 XML 文件 (gdb.xml)，内容如下:
<?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd"> <plist version="1.0"> <dict> <key>com.apple.security.cs.debugger</key> <true/> </dict> </plist> |
- 更新代码签名:
codesign --entitlements gdb.xml -fs gdbcert /usr/local/bin/gdb
现在就可以正常使用了:
❯ cd ~/cpython (gdb) run /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop Starting program: /Users/dongweiming/lyanna/venv/bin/python3 /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop [New Thread 0x1a03 of process 35316] [New Thread 0x2603 of process 35316] warning: unhandled dyld version (16) ... Thread 2 received signal SIGSEGV, Segmentation fault. 0x0000000100026c04 in PyCode_NewWithPosOnlyArgs (argcount=1, posonlyargcount=0, kwonlyargcount=0, nlocals=0, stacksize=1, flags=0, code=<unknown at remote 0x3>, consts=b'', names=(), varnames=(), freevars=('self',), cellvars=(), filename=(), name='Cython/Compiler/Scanning.py', firstlineno=28646256, lnotab=<unknown at remote 0x42>) at Objects/codeobject.c:121 121 code == NULL || !PyBytes_Check(code) || # 可以看到是这里引起的段错误 (gdb) bt # 回溯堆栈。frame0是栈顶，id越大顺序越靠前，也就是说PyCode_New里面调用了PyCode_NewWithPosOnlyArgs最终引发段错误 #0 0x0000000100026c04 in PyCode_NewWithPosOnlyArgs (argcount=1, posonlyargcount=0, kwonlyargcount=0, nlocals=0, stacksize=1, flags=0, code=<unknown at remote 0x3>, consts=b'', names=(), varnames=(), freevars=('self',), cellvars=(), filename=(), name='Cython/Compiler/Scanning.py', firstlineno=28646256, lnotab=<unknown at remote 0x42>) at Objects/codeobject.c:121 #1 0x00000001000273f7 in PyCode_New (argcount=1, kwonlyargcount=3, nlocals=25499040, stacksize=1, flags=0, code=0x0, consts=b'', names=(), varnames=(), freevars=('self',), cellvars=(), filename=(), name='Cython/Compiler/Scanning.py', firstlineno=28646256, lnotab=<unknown at remote 0x42>) at Objects/codeobject.c:253 #2 0x0000000103b84fe2 in ?? () #3 0x00000001018515a0 in ?? () #4 0x00000001004b6040 in ?? () #5 0x00000001004b6040 in ?? () #6 0x0000000103b4c070 in ?? () ... (gdb) frame 0 # 切换到栈顶 ... (gdb) list # 查看栈顶的代码，注意121行 116 117 /* Check argument types */ 118 if (argcount < posonlyargcount || posonlyargcount < 0 || 119 kwonlyargcount < 0 || nlocals < 0 || 120 stacksize < 0 || flags < 0 || 121 code == NULL || !PyBytes_Check(code) || 相关的是code这个参数 122 consts == NULL || !PyTuple_Check(consts) || 123 names == NULL || !PyTuple_Check(names) || 124 varnames == NULL || !PyTuple_Check(varnames) || 125 freevars == NULL || !PyTuple_Check(freevars) || (gdb) frame 0 # 切回栈顶，这个输出内容很多，由于libpython的作用，参数的值更明确了 #0 0x0000000100026c04 in PyCode_NewWithPosOnlyArgs (argcount=1, posonlyargcount=0, kwonlyargcount=0, nlocals=0, stacksize=1, flags=0, code=<unknown at remote 0x3>, consts=b'', names=(), varnames=(), freevars=('self',), cellvars=(), filename=(), name='Cython/Compiler/Scanning.py', firstlineno=28646256, lnotab=<unknown at remote 0x42>) at Objects/codeobject.c:121 121 code == NULL || !PyBytes_Check(code) || (gdb) p code $1 = <unknown at remote 0x3> # 可以看到大部分参数是Python对象，但是要注意其中code的参数看起来是一个很怪的内存地址，看一下下个栈: (gdb) up #1 0x00000001000273f7 in PyCode_New (argcount=1, kwonlyargcount=3, nlocals=25499040, stacksize=1, flags=0, code=0x0, consts=b'', names=(), varnames=(), freevars=('self',), cellvars=(), filename=(), name='Cython/Compiler/Scanning.py', firstlineno=28646256, lnotab=<unknown at remote 0x42>) at Objects/codeobject.c:253 253 return PyCode_NewWithPosOnlyArgs(argcount, 0, kwonlyargcount, nlocals, # 注意code的值0x0，应该是这个内存地址有问题。 |
注意 code 的值 0x0，应该是这个内存地址有问题，因为它不像 stacksize、flags、consts 等参数那样可读。不过到这里卡住了，我循着 frame 又向前看了一遍，没看出来 CPython 的问题
sys.settrace
既然 CPython 这方面没有收获，换个思路，用sys.settrace试试把整个执行代码的过程都打印出来。在 setup.py 里面加入下面代码:
import sys def trace(frame, event, arg): print("%s, %s:%d" % (event, frame.f_code.co_filename, frame.f_lineno)) return trace sys.settrace(trace) # 下面是原来的代码 import codecs # ... |
然后执行:
❯ python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop # 执行时间略长，等1分钟 ... # 输出非常长，省略 line, /Users/dongweiming/lyanna/venv/lib/python3.8/site-packages/Cython/Compiler/Main.py:28 ... line, <frozen importlib._bootstrap>:671 call, <frozen importlib._bootstrap_external>:1107 line, <frozen importlib._bootstrap_external>:1109 call, <frozen importlib._bootstrap>:211 line, <frozen importlib._bootstrap>:219 [1] 7125 segmentation fault python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop |
大家还记得一开始用 faulthandler 模块输出的堆栈么？这个要具体的多，不过我由捕捉到了 Cython 这部分，这是出现错误前最后一个出现的和 C 有关的模块。
我突然来了灵感: 「是不是什么 Python 3.8 的修改对 Cython 的逻辑有影响？」Python3.8 已经上了一段时间，相信有别人已经用了一段时间了，不过去 Cython 项目下没找到对应 issue，因为这个不能明确的对应到是 Cython 引起的。我就顺手升级下 Cython 试试:
❯ pip freeze |grep -i cython Cython==0.29.13 ❯ pip install -U cython ... Successfully installed cython-0.29.14 |
从0.29.13升到了0.29.14，去掉sys.settrace部分代码再试一下:
❯ python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop ... Finished processing dependencies for aiomcache==0.6.0 |
Emm, 正常了 O (∩_∩) O！之后我翻了下这次 cython 更新的改变，但由于改动太多还是没有找到具体的问题，另外一个让我疑惑的是，用另外一个电脑没有过问题。不过问题算是解决了，先这样。
别急，还有后续
现在依赖都装好了，启动应用:
❯ python app.py [1] 10396 segmentation fault python app.py |
心情 down 到了谷底。用 gdb 看还是类似的错误，不过换用 faulthandler 后看到了新的问题:
❯ python app.py Fatal Python error: Segmentation fault Current thread 0x000000010b4e3dc0 (most recent call first): ... File "/Users/dongweiming/lyanna/venv/lib/python3.8/site-packages/yaml/cyaml.py", line 7 in <module> ... [1] 12363 segmentation fault python app.py |
也就是 yaml 有问题了。按之前的套路，先升级看看:
❯ pip freeze |grep -i yaml PyYAML==5.1.2 ❯ pip install -U PyYAML ... Successfully installed PyYAML-5.2 |
再启动:
❯ python app.py [2019-12-11 13:19:03 +0800] [14690] [DEBUG] Sanic Build Fast. Run Fast. [2019-12-11 13:19:03 +0800] [14690] [INFO] Goin' Fast @ http://0.0.0.0:8000 |
还没有结束
2 个段错误都以升级包而解决，不过这也太巧了吧？此时我怀疑是 pip cache 引起的，很早前我就在编译安装 Python3.8，所以我在想是不是由于 pip 缓存的缘故，使用了之前编译的包，而距离上次编译之后 Python3.8 又做了不兼容的修改？所以我做了如下尝试:
❯ pip install cython==0.29.13 # 安装回之前有问题的包 Processing /Users/dongweiming/Library/Caches/pip/wheels/5b/1e/17/15dd6d435ec0644967eb8e1493af09ae28cd94184c6f416d02/Cython-0.29.13-cp38-cp38-macosx_10_14_x86_64.whl # 注意这句，用了缓存 ❯ python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop # 还是会抛出段错误 ... [1] 33909 segmentation fault python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop ❯ rm /Users/dongweiming/Library/Caches/pip/wheels/5b/1e/17/15dd6d435ec0644967eb8e1493af09ae28cd94184c6f416d02/Cython-0.29.13-cp38-cp38-macosx_10_14_x86_64.whl # 删除本地编译好的包 ❯ pip uninstall cython # 卸载Cython-0.29.13 ❯ pip install cython==0.29.13 # 重新安装 ❯ python /Users/dongweiming/lyanna/venv/src/aiomcache/setup.py develop ... Finished processing dependencies for aiomcache==0.6.0 |
这次一切正常，猜对了，这也解释了为什么用另外一个电脑不能复现。不过等等，我突然意识到了问题:
❯ sw_vers -productVersion
10.15.1
|
什么意思呢？我最近升级了系统到 Catalina 10.15.1，但是安装包时会使用 10.14 时编译的包
搜了下本地有错误的 whl 包:
❯ find /Users/dongweiming/Library/Caches/pip/wheels -name "*cp38-cp38-macosx_10_14_x86_64.whl"
/Users/dongweiming/Library/Caches/pip/wheels/3b/13/4a/e6b972b23b1d7fca074f2ef681b3c819123b842cf1b4de8627/ciso8601-2.1.2-cp38-cp38-macosx_10_14_x86_64.whl
/Users/dongweiming/Library/Caches/pip/wheels/f2/aa/04/0edf07a1b8a5f5f1aed7580fffb69ce8972edc16a505916a77/MarkupSafe-1.1.1-cp38-cp38-macosx_10_14_x86_64.whl
/Users/dongweiming/Library/Caches/pip/wheels/28/77/e4/0311145b9c2e2f01470e744855131f9e34d6919687550f87d1/ujson-1.35-cp38-cp38-macosx_10_14_x86_64.whl
|
虽然这次没因为他们抛出段错误，不过正好可以当做调试 pip 的 badcase 罒 ω 罒
虽然没给 CPython 贡献代码，给 pip 贡献一下也好，具体 PR 是:https://github.com/pypa/pip/pull/7466
更新
给 pip 提了 PR 后，维护者说编译的包应该是向前兼容的，所以这不是 pip 的问题。emm，等我有时间帮助复现一下~
哈哈哈。BugOS。我选择 Windows10 + WSL。颜值又高，生态又好。