8

一次调试段错误(segmentation fault)的经验

 4 years ago
source link: http://www.dongwm.com/post/debug-segmentation-fault/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

段错误 (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 里的内容):

  1. 启动 Keychain Access 应用程序
  2. 从菜单选择 Certificate Assistant -> Create a Certificate
  3. 新加一个证书，名字就叫 gdbcert (之后还要用到)，身份类型 self-signed root，证书类型 Code Signing，「Let me override defaults」不用勾，然后 create
  4. 创建一个 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>
  1. 更新代码签名: 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

nYniQ3e.gif

还没有结束

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

YFN3QnQ.gif

延伸阅读


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK