记一次诡异的 FD 泄露:躲在暗处的猴子补丁

本文记录一次线上服务关于 FD 泄露的 Bug 排查经历。相关代码:hscspring/fd_leak: fd leak caused by monkey patch.[1]

引子:线上服务频频告警,一切迹象都指向了再常见不过的 FD 耗尽问题。然而,这次的排查之旅却像一场侦探游戏,线索若隐若现,真相几度反转。最终,我们揪出的元凶竟是一个“躲在暗处”的猴子补丁(Monkey Patch),而触发它作案的,则是一两行看似人畜无害的导入语句

问题背景

某天,报警系统突然出现下面的错误日志:

1
Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7fd77cfd8b10>: Failed to establish a new connection: [Errno 16] Device or resource busy')

这个我们知道一般是文件描述符(FD)耗尽导致。用下面的命令查看确认后确实如此。

1
2
ulimit -n # 1024
lsof -p pid |wc -l # 1369

重启后会正常,但运行一段时间后又出现了。

好了,问题找到了,但是为什么呢?

服务描述

首先,这是一个 LLM 相关的流式服务,这个服务作为 Server 同时会请求第三方 LLM 的 API,我们可以简单将其理解为对第三方流式数据的转发。

其次,该服务本身并没有多线程相关逻辑和代码,不存在多线程调用 API。

第三,该服务的并发并不高,请求数也不是特别多。但每次输出的 Token 数比较多,一次请求从开始到结束可达到 10-30 秒以上。

总的来说,是一个回复长度比较长的流式 LLM 服务。

问题定位

第一反应是自己发起的请求没正确释放或者没释放,导致 FD 不断累积,请求未释放或未完成确实会导致 FD 耗尽,我们可以用下面代码实验一下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
# find/repro.py
# Server端不处理
import threading
import requests
import sys
import time
import socket
from http.server import HTTPServer, BaseHTTPRequestHandler

PORT = 8022

def start_hang_server():
class HangHandler(BaseHTTPRequestHandler):
def do_GET(self):
self.send_response(200)
self.send_header("Content-Type", "text/plain")
self.end_headers()
# Server 端卡死
time.sleep(30)
server = HTTPServer(("localhost", PORT), HangHandler)
server.serve_forever()

threading.Thread(target=start_hang_server).start()
time.sleep(1)

session = requests.Session()
stop_flag = False
lock = threading.Lock()

def open_conn():
global stop_flag
try:
resp = session.get(
f"http://localhost:{PORT}",
stream=True,
timeout=10,
)
for v in resp.iter_lines():
if v:
print(f"Received: {v.decode('utf-8')}")
except Exception as e:
print(f"Got exception in thread: {e!r}")
# 如果是 Errno 16,就能看到类似 Device or resource busy
with lock:
stop_flag = True

count = 0
threads = []
while True:
if stop_flag:
print("Encountered failure, exiting loop.")
break
t = threading.Thread(target=open_conn)
t.daemon = True
t.start()
threads.append(t)
count += 1
print(f"Opened connections: {count}")
time.sleep(0.1)


for t in threads:
t.join()

设置ulimit -n 10,或者更小,运行后马上就会遇到 Errno 16。Server 端卡住,Client 一直发很快就会到达ulimit上限,导致 Device or resource busy,这样当然是没问题的(显而易见)。

现在的问题是,Server 端大概率是没问题的(毕竟用了很长时间了),不确定自己代码里调用 Server 端时是否遇到「错误」导致连接未成功释放,毕竟我这个也是服务,而不是一个脚本任务。如果是,那确定是这个问题;如果不是,那一定有其他什么占用了 FD,导致无法发起新的连接。再模拟实验一下,让 Client 模拟抛出异常,不正常释放 Server 的 stream 流,看看会不会耗尽 FD。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
# find/main.py
from fastapi import FastAPI
from fastapi.responses import StreamingResponse
import time


app = FastAPI()

def generate_stream():
for i in range(3):
yield f"{i}\n"
time.sleep(1)


@app.get("/")
def stream_text():
return StreamingResponse(generate_stream(), media_type="text/plain")

# find/client.py
import requests
import threading
import time

session = requests.Session()
adapter = requests.adapters.HTTPAdapter(pool_connections=2, pool_maxsize=2)
session.mount("http://", adapter)
session.mount("https://", adapter)

url = "http://localhost:8022"

def make_leak(i):
try:
print(f"[Thread-{i}] start")
resp = session.get(url, stream=True)
for line in resp.iter_lines():
print(f"[Thread-{i}] line: {line}")
if b"2" in line:
# 模拟异常中断,连接不释放
raise Exception("simulate disconnect")
except Exception as e:
print(f"[Thread-{i}] Exception: {e}")

threads = []
for i in range(100):
t = threading.Thread(target=make_leak, args=(i,))
t.start()
time.sleep(0.1)
threads.append(t)

for t in threads:
t.join()

还是设置ulimit -n 10time.sleep()设置到比较小时(比如0.1),自然很快就报错了,那是因为新创建的连接太多了,一下就超过了 FD 的限制,但是如果我们把它调大点,比如调到 0.5 或 1,那么随便怎么执行都不会报错。因为请求 2s 结束(抛出异常),2s 可以发送 2/0.5=4 个请求,达不到限制的 10。实际上即使调到 0.3 也不会报错,极限是 2/10=0.2s,但显然这是理想值,实际可能需要 0.3。这也说,我们发起的流式请求即使没有正常释放,问题依然不大,不会导致 FD 增加。

还可以通过命令:

1
netstat -anp | grep 32215 | awk '{print $6}' | sort | uniq -c

查看状态分布,CLOSE_WAIT 并没有很多,说明并没有异常挂起的连接。

那就是其他地方有问题了!看下有哪些 FD(进程打开的文件):

1
lsof -p 32215 | awk '{print $5}' | sort | uniq -c | sort -nr

输出如下:

1
2
3
4
5
6
7
8
308 REG 
668 a_inode
34 CHR
26 IPv4
10 FIFO
2 DIR
1 unix
1 TYPE

含义如下:

1
2
3
4
5
6
7
8
308 REG        ← 普通文件(日志、Python 模块、库、缓存等)
668 a_inode ← lsof监控的文件,inode是文件的唯一标识符
34 CHR ← 字符设备(stdin、stdout、stderr)
26 IPv4 ← IPv4套接字
10 FIFO ← 先进先出队列
2 DIR ← 目录
1 unix ← Unix domain套接字
1 TYPE ← lsof 内部标识

进程没有大量 TCP socket,也没泄露网络连接!比较多的是 REG 和 a_inode,经确认,REG是正常的,确实有那么多。那么看看 a_inode 都有些啥:

1
lsof -p 32215 | grep a_inode

结果好多eventpoll,它是Linux 系统中的一个系统调用,用于高效地监听多个文件描述符上的 I/O 事件。由于需要运行一段时间才会出现,很自然想监控一下随时间推移 FD 的变化,结果发现 a_node 居然会随时间增加!这应该就是 FD 泄露的直接原因。

但是显然,大部分情况下没有谁代码里能用到epoll这么底层的调用,所以肯定有一些不为人知的模块有问题。接下来就是要找出具体是哪个地方用到了这个。

直接使用 py-spy 看线程堆栈中哪个线程一直持有资源不释放。

1
py-spy dump --pid 32215

执行后,结果如下:

1
2
3
4
5
# 只显示epoll相关
Thread 1605012 (idle): "Thread-4 (start)"
do_poll (eventlet/hubs/epolls.py:31)
wait (eventlet/hubs/poll.py:80)
run (eventlet/hubs/hub.py:362)

果然找到了相关的线程,和 eventlet 这个包有关。不过这个我自己代码里没用到,应该是某个依赖用到了。直接卸载后重启服务,果然正常了!

接下来就是找到是谁用了它。服务命令启动时加入 PYTHONPROFILEIMPORTTIME=1 分析引入链,将结果输出后,grep eventlet

1
grep eventlet import.log -C 10

结果如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
import time:       347 |        347 |       redis.asyncio.utils
import time: 617 | 38094 | redis.asyncio
import time: 511 | 511 | redis.sentinel
import time: 1060 | 39664 | redis
import time: 436 | 436 | sentry_sdk._types
import time: 354 | 790 | sentry_sdk._compat
import time: 692 | 692 | sentry_sdk.consts
import time: 170 | 170 | gevent
import time: 551 | 551 | greenlet._greenlet
import time: 444 | 994 | greenlet
import time: 471 | 471 | eventlet.patcher
......
import time: 529 | 370559 | eventlet
import time: 12 | 370570 | eventlet.patcher
import time: 148 | 148 | gevent
import time: 1942 | 373822 | sentry_sdk.utils
import time: 375 | 374197 | sentry_sdk.session
import time: 420 | 374617 | sentry_sdk.envelope
import time: 353 | 374969 | sentry_sdk.attachments
import time: 353 | 353 | sentry_sdk._lru_cache
import time: 148 | 148 | gevent
import time: 13 | 160 | gevent.monkey
import time: 597 | 1109 | sentry_sdk.profiler
import time: 879 | 879 | sentry_sdk.metrics

找到了,是 sentry_sdk 引入了 eventlet!找到相关代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
# sentry_sdk/utils.py
def _is_contextvars_broken():
# type: () -> bool
"""
Returns whether gevent/eventlet have patched the stdlib in a way where thread locals are now more "correct" than contextvars.
"""
try:
import gevent # type: ignore
from gevent.monkey import is_object_patched # type: ignore

# Get the MAJOR and MINOR version numbers of Gevent
version_tuple = tuple(
[int(part) for part in re.split(r"a|b|rc|\.", gevent.__version__)[:2]]
)
if is_object_patched("threading", "local"):
# Gevent 20.9.0 depends on Greenlet 0.4.17 which natively handles switching
# context vars when greenlets are switched, so, Gevent 20.9.0+ is all fine.
# Ref: https://github.com/gevent/gevent/blob/83c9e2ae5b0834b8f84233760aabe82c3ba065b4/src/gevent/monkey.py#L604-L609
# Gevent 20.5, that doesn't depend on Greenlet 0.4.17 with native support
# for contextvars, is able to patch both thread locals and contextvars, in
# that case, check if contextvars are effectively patched.
if (
# Gevent 20.9.0+
(sys.version_info >= (3, 7) and version_tuple >= (20, 9))
# Gevent 20.5.0+ or Python < 3.7
or (is_object_patched("contextvars", "ContextVar"))
):
return False

return True
except ImportError:
pass

try:
import greenlet # type: ignore
from eventlet.patcher import is_monkey_patched # type: ignore

greenlet_version = parse_version(greenlet.__version__)

if greenlet_version is None:
logger.error(
"Internal error in Sentry SDK: Could not parse Greenlet version from greenlet.__version__."
)
return False

if is_monkey_patched("thread") and greenlet_version < (0, 5):
return True
except ImportError:
pass

return False


def _get_contextvars():
# type: () -> Tuple[bool, type]
"""
Figure out the "right" contextvars installation to use. Returns a
`contextvars.ContextVar`-like class with a limited API.

See https://docs.sentry.io/platforms/python/contextvars/ for more information.
"""
if not _is_contextvars_broken():
# aiocontextvars is a PyPI package that ensures that the contextvars
# backport (also a PyPI package) works with asyncio under Python 3.6
#
# Import it if available.
if sys.version_info < (3, 7):
# `aiocontextvars` is absolutely required for functional
# contextvars on Python 3.6.
try:
from aiocontextvars import ContextVar

return True, ContextVar
except ImportError:
pass
else:
# On Python 3.7 contextvars are functional.
try:
from contextvars import ContextVar

return True, ContextVar
except ImportError:
pass

# Fall back to basic thread-local usage.

from threading import local

return False, _make_threadlocal_contextvars(local)


HAS_REAL_CONTEXTVARS, ContextVar = _get_contextvars()

注意,eventletgevent 都是基于协程(协作式并发)的 Python 并发库,用于在同步代码中实现高并发 I/O 处理

我的环境正好装了 greenleteventlet,由此可以推断,很可能是因为 eventlet(eventlet==0.36.1)的猴子补丁改变了线程和协程的行为,导致 Sentry 内部上下文追踪、线程同步等机制异常,从而引发资源泄漏。

猴子补丁是指:在运行时修改已有的类或模块的行为,而不是通过继承或修改源码来改变它。举个例子:

1
2
3
4
5
6
7
8
9
10
import time

def fake_sleep(seconds):
print(f"pretend sleeping for {seconds} seconds")

# 猴子补丁:替换原来的 time.sleep
time.sleep = fake_sleep

# 原本应该阻塞的代码,现在变成打印
time.sleep(3) # 输出:pretend sleeping for 3 seconds

解决方案

非常简单,直接卸载 eventlet

但是,作为一名工程师,显然不能停留在这里就结束,我们还想搞清楚更深层次的原因:到底是哪里的代码,或者说哪一行代码导致的这个问题?很显然,这需要我们把核心逻辑抽出来进一步研究,没想到这一步居然出问题了!

诡异现象

当我快速把带有sentry_sdk的相关逻辑单独抽出来测试时,奇怪的事情出现了:FD 居然不再增加!这怎么可能呢?回到原项目重新启动跑了一下——没错呀,确实有增加。那么问题一定出在相关逻辑的抽取上!可是看起来确实好像没问题,没办法,只好一点一点剥离代码,删掉一点测试一下,就这一步搞了几个小时,代码都快看烂了。有几次还不小心剥离多了代码,导致上一步没问题,下一步又消失了……没办法,只好再回退回去。

废了半天劲,终于找到导致 FD 泄露的位置了:居然不是 sentry_sdk,而是请求完成后推送日志的逻辑!这尼玛,此时的心情可真是一言难尽。

好吧,此时的我以为是云厂商的 SDK 问题,又把 SDK 的源代码扒拉了一通,边对源代码进行注释后测试,边心里吐槽:“这 SDK 怎么还有 Bug,我记得是用的最新版的啊!”A few moments later……找到了:是 requests 的一个 post 请求!错怪 SDK 了!直接把 SDK 代码挪掉,换成 requests.get("https://baidu.com"),没问题,FD 如预期般在泄露!也就是说,请求完成后开线程后台执行 requests 请求导致了 FD 泄露!

这啥嘛!谁能想到在这里呢!但是,如果你以为到这里就结束了的话,那我只能说你太年轻,其实是我太年轻!不过随着年纪的增长,我喜欢这样的“批评”!

因为我把 requests 请求日志那块给简化成了一个 get 操作,所以那块代码自然也就替换掉了,所以我就顺便在原代码前面加了这么几句:

1
2
3
4
5
6
# ……其他一些包导入,包含项目文件
import requests

def send_log():
resp = requests.get("https://www.baidu.com")
print(f"send log to SLS success.")

这样是有问题的对吧。然后我看这个包的导入在本地项目之后,就想着顺便调整一下,把 requests 放在了前面,结果你猜怎么着,FD 泄露居然消失了!连他么 a_inode 都没创建!搞了半天我只要换个导入顺序就行?WTF!

进一步测试后确认,如果先导入 sentry_sdk 再导入 requests,就会有 FD 泄露,但是如果换一下它俩的导入顺序,一切太平!我是真的无语了。

为了方便大家复现,我尽量模拟我的代码,把简化版的最小可复现代码整了一份,Server 如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
# strange/main.py
from threading import Thread
import queue

from fastapi import FastAPI
from fastapi.responses import StreamingResponse
import sentry_sdk
import requests


def send_log():
resp = requests.get("https://www.baidu.com")
print(f"send log success.")


class Worker:
def __init__(self):
sentry_sdk.init(
dsn="http://example@sentry.io/1",
auto_enabling_integrations=False
)
self.input_queue = queue.Queue()

def worker():
while True:
q, response_queue = self.input_queue.get()
if q is None:
break
for i in range(3):
token = f"token-{i}"
response_queue.put(token)
response_queue.put(None)
Thread(target=worker, daemon=True).start()

def run(self, q: str):
response_queue = queue.Queue()
self.input_queue.put((q, response_queue))

while True:
token = response_queue.get()
if token is None:
break
yield f"data: {token}\n\n"

Thread(
target=send_log,
args=(),
).start()


worker = Worker()

app = FastAPI()


@app.post("/", response_model=None)
def llm_svc(q: str):
return StreamingResponse(
worker.run(q),
media_type="text/event-stream",
)

很简单的代码,Client 更简单,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# strange/client.py
import requests

def call_service(q: str):
url = "http://127.0.0.1:9321/?q=q"
response = requests.post(url, stream=True)
for chunk in response.iter_lines():
if chunk:
yield chunk.decode("utf-8")


if __name__ == "__main__":
for i in range(10):
gen = call_service("hello")
for cont in gen:
print(f"-->receive cont: {cont!r}")

我们打开一个 terminal 启动 Server:

1
uvicorn main:app --port 9321

然后打开另一个 terminal 进行验证:

1
lsof -p $(ps aux|grep uvicorn |grep 9321 | awk '{print $2}') | awk '{print $5}' | sort | uniq -c | sort -nr

此时看到 a_inode 应该是 3。接下来执行 python client.py,发起 10 次请求后,再执行上面的命令,a_inode 应该是 13。

如果我们将 send_log 中的那行 requests 请求注释掉,a_inode 就一直都是 3。

如果我们将 sentry_sdkrequests 的导入换个顺序,a_inode 始终保持为 2。

其实,既然已经知道了问题所在,上面的 Server 代码还可以改的更简单一些,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
# strange/main_simple.py
import threading

from fastapi import FastAPI
from fastapi.responses import StreamingResponse

import sentry_sdk
import requests

sentry_sdk.init(
dsn="http://example@sentry.io/1",
auto_enabling_integrations=False
)
session = requests.Session()


def send_log():
resp = session.get("https://www.baidu.com")
print(f"send log success.")


app = FastAPI()


@app.post("/")
def stream_tokens(q: str):
def generator():
for i in range(3):
yield f"data: token-{i}\n\n"
threading.Thread(target=send_log).start()
return StreamingResponse(generator(), media_type="text/event-stream")

其他步骤同上,最终的结果也是一样的。另外,如果不是新开线程去执行 send_log,而是直接执行,a_inode 会从 3 变为 4,并一直保持为 4。

也就是说,这个 FD 泄露的直接原因是新开了个线程去执行 requests 请求,但根本原因还是 sentry_sdkrequests 导入的问题。

到底为啥

我先把上面的这个现象丢给了 ChatGPT 老师,它给我了一些解释,并建议给我一个不用 FastAPI 的最小 Demo。其实也很简单,就只要两个包的导入和一个后台(新线程)触发请求的逻辑。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
# why/mini.py
import os
import threading
import time
import subprocess

import sentry_sdk
import requests


def send_log():
requests.get("https://www.baidu.com")
print("send_log done")

def show_fds():
pid = os.getpid()
cmd = f"lsof -p {pid} | awk '{{print $5}}' | sort | uniq -c | sort -nr"
out = subprocess.check_output(cmd, shell=True)
print(out.decode())


if __name__ == "__main__":
print("初始 FD:")
show_fds()

# 多线程触发
threads = [threading.Thread(target=send_log) for _ in range(5)]
for t in threads:
t.start()
for t in threads:
t.join()

time.sleep(1)
print("\n触发请求后 FD:")
show_fds()

这样执行后就很容易看出 a_inode 在增加了。ChatGPT 老师给出的解释是:

这个现象其实是 Python 库导入时的 side effect(副作用)+ requests/urllib3/sentry_sdk 对 epollfd 的使用方式组合 造成的,看似“a_inode 泄漏”,其实是因为依赖初始化顺序导致文件描述符(epoll、eventfd 等)被不同地持有。

每次 requests + urllib3 在多线程下第一次用到时,可能会触发 urllib3 的 连接池管理器 创建后台 selector(用 selectors.EpollSelector),这会新建一个 epoll fd。

同时,sentry_sdk 导入时如果它先 monkey-patch 了一些库(比如 threading 或 requests),就会改变 什么时候 初始化这些 selector/fd。

sentry_sdk import 的时候,它会 import/patch requests 相关模块。这导致当你在子线程里首次调用 requests 时,每个线程可能各自触发 urllib3 的连接池初始化,开多个 epollfd。所以随着请求次数增加,fd 数量上升。

那既然如此的话,用 urllib3 替换 requests 应该也是一样的,试了一下果然如此。注意,ChatGPT 老师说的不一定都对哦,要仔细甄别和判断。

再回想我们前面的《问题定位》,当时推断:

很可能是因为 eventlet(eventlet==0.36.1)的猴子补丁改变了线程和协程的行为,导致 Sentry 内部上下文追踪、线程同步等机制异常,从而引发资源泄漏。

我们把 sentry_sdk 直接替换为 eventlet 导入的那一句试试。好吧,不出所料,问题就在这里!也就是说,出问题的是 sentry_sdk 中的 eventlet

1
from eventlet.patcher import is_monkey_patched

sentry_sdk 本身并无问题。换句话说,可以把导入的地方更换一下也是可以复现的:

1
2
3
4
5
6
7
8
9
10
11
12
# 换成导入eventlet也是一样的
import eventlet
# from eventlet.patcher import is_monkey_patched
import urllib3


def send_log():
try:
urllib3.request("GET", "127.0.0.1")
except Exception as e:
pass
print("send_log done")

不用请求百度了,只要发起请求就行。同理,这两个导入换个顺序也是正常的。其实到这里我们感觉 ChatGPT 老师说的应该是八九不离十的。

另外,升级了一下 sentry_sdk 到最新版,发现这个地方还是在的,想想应该也是可以理解的,毕竟这不是它的问题。那 eventlet 升级到最新版呢?从 0.36.1 升级到 0.40.3 后发现依然一样。其实也可以理解,站在 eventlet 的角度它也没错。好吧,你们都没错,错的是我……我在导入时忽视了 side effect。这里需要说明一下,实际的代码不可能这么简单,只能说确实是包含 sentry_sdk 的 Python 文件先导入,然后导入了写日志的文件。

继续把新的情况丢给 ChatGPT 老师,显然,这一次的回复看起来更加接近真相。

  1. eventlet 通过 monkey-patch 把标准库(socket、threading、ssl、select 等)替换成“绿色”实现(green),从而使阻塞操作可被 eventlet 的协作调度处理。
  2. 很多网络库(requests / urllib3 / httplib / ssl / selectors)在第一次导入时会绑定/缓存底层实现(例如:socket.create_connection、SSLContext、selector 模块的实现等)。如果它们在 monkey_patch 之前被导入,就会绑定到“原生阻塞”的实现;如果在 monkey_patch 之后导入,就会绑定到 eventlet 的 green 实现。
  3. 当库的内部使用到某些 I/O 框架(例如 selectors/epoll)或在 N 个线程间创建资源时,不同实现混用会导致资源(如 epoll fd / eventfd / timerfd / socket fd)没有正确被释放。这通常表现为“每次发请求后 epollfd 数量上升但不回收”。
  4. 因此导入顺序改变了哪个实现被绑定,从而影响到是否会产生(或回收)这些底层 FDs。你观察到“把 requests 放在 eventlet 之前就没有泄露”正是这一点的直接体现(但这不是最稳健的修复 —— 正确的是先 monkey_patch,再导入其他库)。

关于 ChatGPT 老师的回复,我们还是秉承一样的理念:提供思路+怀疑精神。

先来看看 eventlet 这个包,经过逐个对下面一系列文件进行排查:

1
2
3
4
5
6
# from eventlet.patcher import is_monkey_patched
# from eventlet import convenience
# from eventlet.green import socket
# from eventlet.support import greendns
# from eventlet import greenio
# from eventlet import patcher

最终确定应该为 socket 的问题,只要把下面这个代码 modules 中的 socket 注掉就不会有问题了。具体来说,这里的 socket 被替换为绿色实现,然后导入 dnssetattr 部分属性时,用到了这个 socket

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
# eventlet/support/greendns.py

from eventlet import patcher
from eventlet.green import _socket_nodns


def import_patched(module_name):
# Import cycle note: it's crucial to use _socket_nodns here because
# regular evenlet.green.socket imports *this* module and if we imported
# it back we'd end with an import cycle (socket -> greendns -> socket).
# We break this import cycle by providing a restricted socket module.

modules = {
'select': select,
'time': time,
'os': os,
# 'socket': _socket_nodns,
'ssl': ssl,
}
return patcher.import_patched(module_name, **modules)


dns = import_patched('dns')

for pkg in dns.__all__:
if pkg == 'rdtypes':
continue
# if pkg in ["asyncresolver", "asyncquery", "e164", "query", "resolver"]:
# continue
setattr(dns, pkg, import_patched('dns.' + pkg))

显然,此时的 socket 已经变成了绿色版本。同样的情况也发生在 urllib3 的导入过程中。

而如果将下面这个 setattr 部分的注释代码取消注释,也不会有问题。很显然,dns 的这几个属性的 patch 需要进一步查看。经检查,"asyncresolver", "asyncquery", "e164", "resolver" 几个都直接或间接调用了 query,而 query(即 dns/query.py,其他类似)中则尝试去调用了 requests,以及 httpx!注意,dns 可不是标准库。进一步检查后发现,副作用就来自这里的 requests!很显然,把这里的 requests 换成 urllib3 也是一样的效果。

好了,现在我们来梳理一下迄今为止的代码和改动。首先是复现代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
# why/mini2.py
import os, sys
import threading
import time
import subprocess

import eventlet
import urllib3
print("we import urllib3:", urllib3.socket)


def send_log():
try:
urllib3.request("GET", "127.0.0.1")
except Exception as e:
pass


def show_fds():
pid = os.getpid()
cmd = f"lsof -p {pid} | awk '{{print $5}}' | sort | uniq -c | sort -nr"
out = subprocess.check_output(cmd, shell=True)
print(out.decode())


if __name__ == "__main__":
print("初始 FD:")
show_fds()

# 多线程触发
threads = [threading.Thread(target=send_log) for _ in range(10)]
for t in threads:
t.start()
for t in threads:
t.join()

time.sleep(1)
print("\n触发请求后 FD:")
show_fds()

然后对下面的包进行调整:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
# eventlet/support/greendns.py

print("greendns import dns: import_patched(dns) start")
dns = import_patched('dns')
print("greendns import dns: import_patched(dns) end")

for pkg in dns.__all__:
if pkg == 'rdtypes':
continue
if pkg == "query":
print("greendns setattr start")
setattr(dns, pkg, import_patched('dns.' + pkg))
print("greendns setattr end")


# dns/__init__.py 最后加一行

import socket
print("dns import socket: ", socket)

# dns/query.py
try:
print("`dns` import urllib3")
import urllib3
# import requests
# from requests_toolbelt.adapters.source import SourceAddressAdapter
# from requests_toolbelt.adapters.host_header_ssl import HostHeaderSSLAdapter


# urllib3/__init__.py 加一行
import socket
print("urlib3 import socket: ", socket)

注意,几个包的版本如下:

1
2
3
eventlet-0.36.1
urllib3-2.4.0
dnspython-2.3.0

前两个是可以升级到最新版的:

1
2
3
eventlet-0.40.3
urllib3-2.5.0
dnspython-2.3.0 # 这个不要升级

但是 dnspython 不行,因为新版已经把 requests 的依赖移除了,自然也就复现不出来了。

执行前面的复现代码后,输出如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
# import eventlet (eventlet/support/greendns.py)带来的
greendns import dns: import_patched(dns) start
dns import socket: <module 'eventlet.green._socket_nodns' from '/path/to/python3.11/site-packages/eventlet/green/_socket_nodns.py'>
greendns import dns: import_patched(dns) end

# (eventlet/support/greendns.py)import_patched('dns.' + pkg) 带来的,准确来说是 import dns.query
dns import socket: <module 'eventlet.green._socket_nodns' from '/path/to/python3.11/site-packages/eventlet/green/_socket_nodns.py'>

# dns.query.py 开头我们改掉的那段代码
`dns` import urllib3
urlib3 import socket: <module 'eventlet.green._socket_nodns' from '/path/to/python3.11/site-packages/eventlet/green/_socket_nodns.py'>

# setattr带来的
greendns setattr start
`dns` import urllib3

# 复现代码里的
we import urllib3: <module 'eventlet.green._socket_nodns' from '/path/to/python3.11/site-packages/eventlet/green/_socket_nodns.py'>

初始 FD:
lsof: WARNING: can't stat() tracefs file system /sys/kernel/debug/tracing
Output information may be incomplete.
56 REG
7 CHR
2 DIR
1 TYPE
1 FIFO
1 a_inode


触发请求后 FD:
lsof: WARNING: can't stat() tracefs file system /sys/kernel/debug/tracing
Output information may be incomplete.
56 REG
11 a_inode
7 CHR
2 DIR
1 TYPE
1 FIFO

可以看到,socket 已经全部变为绿色版本,如果把 dns/query.py 中的 urllib3 依赖去掉,一切就正常了。说明冲突来自这里的 urllib3 和复现代码里后面导入的 urllib3

如果把复现代码中的 urllib3 导入和 eventlet 换个顺序,输出变为:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
urlib3 import socket:  <module 'socket' from '/path/to/python3.11/socket.py'>
we import urllib3: <module 'socket' from '/path/to/python3.11/socket.py'>

greendns import dns: import_patched(dns) start
dns import socket: <module 'eventlet.green._socket_nodns' from '/path/to/python3.11/site-packages/eventlet/green/_socket_nodns.py'>
greendns import dns: import_patched(dns) end

dns import socket: <module 'eventlet.green._socket_nodns' from '/path/bo/python3.11/site-
packages/eventlet/green/_socket_nodns.py'>

`dns` import urllib3
greendns setattr start
`dns` import urllib3

初始 FD:
lsof: WARNING: can't stat() tracefs file system /sys/kernel/debug/tracing
Output information may be incomplete.
56 REG
7 CHR
2 DIR
1 TYPE
1 FIFO


触发请求后 FD:
lsof: WARNING: can't stat() tracefs file system /sys/kernel/debug/tracing
Output information may be incomplete.
56 REG
7 CHR
2 DIR
1 TYPE
1 FIFO

可以看到,此时 urllib3 使用的是原生的 socket,此时新开线程(上下文)执行后 FD 自然会被顺利关闭。

所以,归根结底,直接原因是 eventletmonkey_patch 时处理了 socketdns,而 dns 又依赖 urllib3(实际是 requests,一样的),导致其底层使用了 patch 之后的 socket

这也是 eventlet 官方文档中强调的,一定要在一开始调用 eventlet.monkey_patch()。描述如下:

It is important to call monkey_patch()[2] as early in the lifetime of the application as possible. Try to do it as one of the first lines in the main module. The reason for this is that sometimes there is a class that inherits from a class that needs to be greened – e.g. a class that inherits from socket.socket – and inheritance is done at import time, so therefore the monkeypatching should happen before the derived class is defined. It’s safe to call monkey_patch multiple times.

至于导入顺序这种方式其实并不是好的实践,也不建议。还是建议在最一开始执行 monkey_patch()

1
2
import eventlet
eventlet.monkey_patch()

当然,在这次的案例中,其实我们只需要 patch 掉 thread 就行:

1
eventlet.monkey_patch(thread=True)

因为目前只有新开的 thread 线程不是绿色实现。不过一般还是建议保持空参数,把所有的都 patch 掉。

另外,可以在代码中看到目前支持的模块如下:

1
2
3
4
5
6
7
8
9
10
11
12
# eventlet/patcher.py
accepted_args = {
"os",
"select",
"socket",
"thread",
"time",
"psycopg",
"MySQLdb",
"builtins",
"subprocess",
}

暂时这样

其实,我们的分析并没有结束,还应该进一步去看更底层的代码去观察泄漏位置,不过显然篇幅已经太长了,而且我们基本上清楚了来龙去脉,就留到下次吧。不过,我们也可以用下面的代码先观察一下类似现象:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
# why/mini_selectors.py
import os
import subprocess
import threading
import selectors # select的高层抽象模块
import time


def show_fds():
pid = os.getpid()
cmd = f"lsof -p {pid} | awk '{{print $5}}' | sort | uniq -c | sort -nr"
out = subprocess.check_output(cmd, shell=True)
print(out.decode())

def create_epoll():
sel = selectors.DefaultSelector()
# 这里不关闭
# sel.close()

if __name__ == "__main__":
print("初始 FD:")
show_fds()

threads = [threading.Thread(target=create_epoll) for _ in range(10)]
for t in threads:
t.start()
for t in threads:
t.join()

time.sleep(0.5)
print("\n触发请求后 FD:")
show_fds()

总而言之,这次的“Bug”很显然并不是一个“真正”的 Bug,而是我自己对底层某些包不太了解导致(相信 eventlet 的作者肯定是清楚的)。这也再次给自己敲响警钟——千万不要觉得自己已经熟悉了某个编程语言,顶多只能算知道一点!想想觉得有点搞笑,从 5-6 年前说自己”熟悉 Python“,到最近几年的”比较熟悉“,再到现在的”知道一点“……哎,啥时候才能真正”精通“呢……其实,如果按此标准,那 Java 是稍微知道一点,Rust、JavaScript 是略微知道一点,Elixir、Go 是略微知道一丁点, C/C++ 那就基本不懂了。编程不易呀!

回到这个例子,到目前为止我们可以画出大致逻辑链路:

1
sentry_sdk ->① eventlet -> _socket_nodns -> support/greendns.py -> ② dns -> ③ dns.query -> ④ requests/urllib3

具体的调用链路可以 hook __import__,示例代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
# who_import_me.py
import builtins
import traceback

original_import = builtins.__import__

def traced_import(name, globals=None, locals=None, fromlist=(), level=0):
stack = "".join(traceback.format_stack(limit=5))
print(f"Importing {name}, called from:\n{stack}")
return original_import(name, globals, locals, fromlist, level)

builtins.__import__ = traced_import

import sentry_sdk

回到我们的逻辑链路,有以下几个关键点:

  • ① 这里的前提是安装了 eventlet,否则直接 import error 跳过去了也没问题。
  • ② 这里如果把 _socket_nodns 注释掉也没问题。
  • ③ 这里如果不设置 dns.query 以及调用了 query 的其他几个模块也没问题。
  • ④ 这里不导入 requests 那也没问题。

就是因为我们在执行代码里也导入了 requests/urllib3 并发起了调用,并且最关键的是,我们把这个调用丢到了原生线程(而非本来的绿色实现上下文),导致执行完后无法正常释放资源(上下文改变)。

另外,这里虽然是由于 dns.query 导入 requests/urllib3 导致的问题,但其实是由于 urllib3 底层用了 socket -> select 模块,而这模块由于前面导入 eventlet 被 patch 了。

解决方法也很多:

  • 卸载 eventlet,前面说过。
  • 升级 dnspython,因为升级后的版本消除了 requests 的依赖,自然没问题。
  • 代码最开始执行 eventlet.monkey_patch。当然,如果像 sentry_sdk 这样内部导入的,你可能都不知道。

总之,切记一点:只要用到猴子补丁的地方,就尽量都用猴子补丁的上下文。

另外,不要无脑相信大模型,哪怕它看起来是对的,甚至确实是对的。最好还是自己亲自动手探索验证一下,否则很容易“看起来好像明白了,但其实很多细节一抹黑”。不禁又想起了耗子老哥的那句“细节处全是魔鬼”,缅怀耗子老哥。

简单小结

一个小小的 Bug 居然整出来这么多玩意儿,而且,刚刚才说过,其实现在还没有完全分析完(还可以继续下到 selectepoll 操作系统交互这一层看看具体泄露情况)。不过本文实在已经很长了,实际上大家看到的已经是整理后的结果,完整的 Debug 过程更繁琐。另外,由于平时比较忙,很难有大片空闲时间,导致这个过程持续了一两周时间,确实有点点影响了其他事情……

总结一下,这是一次由 sentry_sdk 导致的 FD 泄露故障,我们从 eventlet 猴子补丁导致的副作用开始,找到 dns 继而找到 requests,并确认此时底层的 select 已经被绿化,而新开的线程却不是绿色版本(原生线程),从而导致上下文不一致,资源回收失败,表现就是 eventpoll 不断增加。

后续——

在 GitHub 上发了个 Issue 记录了一下,得到了回复,eventlet 即将从最新的 SDK 中移除,eventlet 本身也即将退役。如官方文档公告(https://eventlet.readthedocs.io/en/latest/)所写:

新的 Eventlet 使用现已被强烈不推荐!请阅读以下内容。

Eventlet 创建于将近 18 年前,当时 CPython 标准库中还没有异步功能。随着时间推移,Eventlet 和 CPython 都在不断演进,但近几年 Eventlet 的维护活动逐渐减少,导致它与 CPython 实现之间的差距越来越大。

这种差距已经过大,可能会在你的应用程序中引发意想不到的副作用和 bug。

Eventlet 现在遵循新的维护策略:

  • 只会进行稳定性和 bug 修复方面的维护。
  • 不会再接受新的功能请求,除非这些功能与迁移到 asyncio 有关。
  • 不建议在新项目中使用 Eventlet
  • 我们的目标是逐步计划 Eventlet 的退役,并为你提供迁移路径,以便摆脱对 Eventlet 的依赖。

如果你正在寻找一个用于管理异步网络编程的库,并且尚未使用 Eventlet,我们强烈推荐你使用 asyncio ——它是 CPython 标准库官方支持的异步库。

如果你已经在使用 Eventlet,我们希望能在某些使用场景下帮助你迁移到 asyncio;请参考 Migrating off of Eventlet。未来仅会接受与迁移方案相关的新特性。

如果你对维护目标或迁移有任何疑问,请随时开启一个新 issue,我们会乐意回答你的问题。

References

[1] hscspring/fd_leak: fd leak caused by monkey patch.: https://github.com/hscspring/fd_leak
[2] monkey_patch(): https://eventlet.readthedocs.io/en/latest/reference/api/eventlet.html#eventlet.patcher.monkey_patch