2023.03.20 号，OpenAI 的 ChatGPT 服务曾经中断了一段时间，随后 OpenAI 发了一篇公告 March 20 ChatGPT outage: Here’s what happened 把这里的来龙去脉讲了一下。OpenAI 在公告里说明了本次故障的影响范围、补救策略、部分技术细节以及改进措施，还是很值得学习的。

本次事故处理的具体时间节点在 ChatGPT Web Interface Incident 也有公开，如下图：

ChatGPT 故障整体修复时间节点

这个故障是由 Redis 的 Python 客户端 Bug 引发的，在 Github 上有关于这个 bug 的讨论。这个 bug 的修复过程并不顺利，有不少讨论和修复尝试，比如 Issue 2624，PR 2641，Issue 2665，PR 2695。看过这些后，似乎还是不能理解这里的修复，只好深入读读代码，看看这里的 bug 原因以及修复过程到底是怎么回事，顺便整理成这篇文章。

故障公开

在开始分析 Python 的 bug 之前，想先聊一下 OpenAI 的故障看板。OpenAI 提供有一个故障状态查询页面，可以在上面看到目前各个服务的健康状态。这点在国外做的比较好，很多服务都有 status 看板，比如 Github，Google Cloud。

OpenAI status 看板，故障公示

当遇到 ChatGPT 不能用的时候，可以第一时间来这里看看当前服务状态。如果服务没问题，那一般就是自己的网络或者账户出了问题。一旦服务出问题，这里就能看到故障的进度。反观国内的很多服务，遇到问题是能遮掩就遮掩，就怕使用的人知道出故障。

本文的这个故障比较严重，OpenAI CEO Sam Altman 也专门发了一个简短 说明：

we had a significant issue in ChatGPT due to a bug in an open source library, for which a fix has now been released and we have just finished validating.

a small percentage of users were able to see the titles of other users’ conversation history.

we feel awful about this.

故障详情

OpenAI 官方随后写了一篇文章：March 20 ChatGPT outage: Here’s what happened 详细介绍了本次故障。最开始是发现某些用户可以查看其他用户聊天对话中的标题，另外如果两个用户在同一时间活跃，那么新会话的第一条消息也可能会被其他人看到。后面又发现在特定的 9 个小时内，大概有 1.2% 左右的活跃 ChatGPT Plus 用户的支付信息被其他人看到。这里的支付信息包括：名字、电子邮件地址、付款地址、信用卡类型和信用卡号的最后四位数字以及信用卡到期日期。

当然这里支付信息被泄露的人数其实极少，因为触发条件比较苛刻，只有下面两种情况：

  1. 在 2023.03.30 早上 1 点到 10 点打开了 OpenAI 发送的订阅确认邮件，邮件里可能有其他人的信用卡类型和卡号的后四位(好在没有完整卡号)。
  2. 在 2023.03.30 早上 1 点到 10 点在 ChatGPT 聊天页面点击“我的账户”，并且进入了“管理我的订阅”。这时候可能会看到其他 Plus 用户的名字和姓氏、电子邮件地址、付款地址、信用卡类型和信用卡号的最后四位数字（仅）以及信用卡到期日期。

整个事故的处理时间节点在 ChatGPT Web Interface Incident 有公开。

故障原因

OpenAI 给出了这个故障发生的一些技术细节：

  1. 使用 Redis 缓存了用户的信息，避免每次都查询数据库。
  2. Redis 是集群模式部署，负载分在许多个 Redis 实例上。
  3. 服务用 Python 开发，用到了异步I/O库 Asyncio，使用 redis-py 库来访问 Redis。
  4. 服务用 redis-py 库维护了一个到 Redis 集群的连接池，会复用连接来处理请求。
  5. 使用 Asyncio 异步处理 redis-py 的请求时，请求和响应可以看做两个队列，每个请求和响应在两个队列中是一一对应的。
  6. 如果请求已经入队到 Redis server，但在响应出队之前被取消，那么这个连接中请求和响应的对应关系会错乱。后面的请求可能会读到前面毫不相关的请求响应。
  7. 大多数情况下，因为读到的数据和请求预期不一致，会返回错误。
  8. 某些巧合情况下，读到的错误数据刚和和请求预期的数据类型一致，虽然不是同一个用户的信息，但是也会被正常显示。
  9. 在 2023.03.20 凌晨 1 点，进行服务变更后，redis 取消请求的调用量激增，导致出现了返回错误数据的情况(概率很低)；

这里的关键在第 5 和第 6 点，后面我们会深入看看 redis-py 中这个 bug 的复现以及修复过程。

故障处理

OpenAI 对这个故障的处理措施也值得学习。首先是强调保护用户的隐私和数据安全，承认这次确实没做到，然后诚挚道歉，并发邮件通知了所有受影响的用户(不知道有没有啥实质的补偿)。

技术层面上，在找到了具体的原因后，也加固了这里的防护。具体来说就是：

  1. 测试修复是否生效；
  2. 增加了数据的校验，保证请求和拿到的 Redis 缓存中的用户是同一个；
  3. 分析日志，保证消息不会被没权限的人看到；
  4. 通过多个数据源准确识别受影响的用户，然后进行通知；
  5. 增加了一些日志，确保问题被彻底解决，如果再出现这个问题，也能立马发现；
  6. 提高了 Redis 集群的鲁棒性，减少在极端负载情况下出现连接错误。

接下来我们将聚焦 redis-py 的这个 bug，来看看如何复现并修复。

Bug 复现

drago-balto 3.17 号在 redis-py 提交 Issue 2624 报告了 redis-py client 的这个 bug，简单说就是 Redis client 发出了一个异步请求，在收到并解析响应前，如果取消了这个异步请求，那么当前这个连接后续的命令就会出错。

If async Redis request is canceled at the right time, after the command was sent but before the response was received and parsed, the connection is left in an unsafe state for future commands.

要复现这里问题的话，先得有一个 redis server，可以在本地安装一个用默认配置启动就好。注意如果本地 redis 没有配置密码和 ssl 的话, redis 连接部分要改成注释的代码。然后用 conda 创建一个 python 的虚拟环境，安装 redis-py 的 4.5.1 版本 pip install redis==4.5.1。之后就可以用下面的脚本来复现 bug：

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
import asyncio
from redis.asyncio import Redis
import sys


async def main():
    # local redis server without passwd and ssl support
    # myhost = sys.argv[1]
    # async with Redis(host=myhost, ssl=False, single_connection_client=True) as r:
    myhost, mypassword = sys.argv[1:]
    async with Redis(host=myhost, password=mypassword, ssl=True, single_connection_client=True) as r:

        await r.set('foo', 'foo')
        await r.set('bar', 'bar')

        t = asyncio.create_task(r.get('foo'))
        await asyncio.sleep(0.001)
        # may change to some other value
        # await asyncio.sleep(0.000001)
        t.cancel()
        try:
            await t
            print('try again, we did not cancel the task in time')
        except asyncio.CancelledError:
            print('managed to cancel the task, connection is left open with unread response')

        print('bar:', await r.get('bar'))
        print('ping:', await r.ping())
        print('foo:', await r.get('foo'))


if __name__ == '__main__':
    asyncio.run(main())

上面脚本用同一个 client 连接，先后执行了多个命令。其中异步执行 r.get('foo') 期间，调用 cancel 取消了这个查询，接着又执行了其他命令，通过观察后续命令的结果，就能知道这里有没有问题。注意这里在 await t 的时候，会尝试捕获异常 asyncio.CancelledError，如果捕获到这个异常，说明成功在 r.get('foo') 结束前取消了异步任务。如果没有异常，说明读 redis 任务已经完成，cancel 并没有成功取消异步任务。这里有个关键点就是 asyncio.sleep(0.001)，这里等待一段时间，就是为了让这个异步读请求被服务器接收并执行，但是在收到服务器的响应前被成功取消。

如果在Redis server 在云环境，延迟 > 5ms，那么这里 sleep(0.001) 就能复现问题。我的 Redis client 和 server 都在一台机，网络耗时可以忽略。通过不断实验，发现这里 asyncio.sleep(0.000001) 能稳定复现，下面是在我本地，sleep 不同时间的执行结果：

Bug 的复现过程

可以看到在 sleep(0.000001) 情况下，这里后续的 Redis 命令结果全部不对，每个命令都是上一个命令的结果。回到 OpenAI 的故障描述，就能解释为啥一个人看到了其他人的数据。因为这中间有取消的 redis 异步请求任务，导致结果错乱，读串了。

源码剖析

之前没有怎么了解过 redis-py 的实现，为了快速定位这里的 bug 原因，最好的办法就是加日志。为了能够立即看到代码改动的效果，先把 redis-py 仓库 clone 到本地，然后用 git checkout v4.5.1 命令切换到 4.5.1 分支。接着用 conda 创建了一个新的虚拟环境，在这个新环境安装本地的库，这里用 pip install -e . ，带上 -e 后，本地的代码变更后就会立马生效。

官方的 redis-py 库写的还是比较清晰的，从 client.py 入手，能很快找到一些线索。比如 execute_command 函数，应该就是执行某个具体的命令，可以在 finally 的代码块里面加上日志 print("execute_command finally", *args) 来确认这一点。

命令解析流程

接下来比较关键的部分应该在 _send_command_parse_response 中了，可以看到首先发送命令，然后就是解析回包。

1
2
3
4
5
6
7
async def _send_command_parse_response(self, conn, command_name, *args, **options):
    """
    Send a command and parse the response
    """
    await conn.send_command(*args)
    return await se
    lf.parse_response(conn, command_name, **options)

这里发送命令部分没啥问题，和我们的 bug 无关，可以跳过，主要来看解析回包部分了。直接看代码的话，干扰的因素太多了，各种分支比较难看的全。可以结合代码，同时不断的添加调试日志，整理一个请求的处理步骤。最后通过在 _read_response 里面打印函数堆栈，具体代码如下：

1
2
import traceback
print("_read_response", "".join(traceback.format_stack()))

通过堆栈，可以看到一个异步 redis get 请求的处理链路如下：

  1. blog_script/redis_bug.py (line 29) - main
  2. redis-py/redis/asyncio/client.py (line 514) - execute_command
  3. redis-py/redis/asyncio/retry.py (line 59) - call_with_retry
  4. redis-py/redis/asyncio/client.py (line 488) - _send_command_parse_response
  5. redis-py/redis/asyncio/client.py (line 535) - parse_response
  6. redis-py/redis/asyncio/connection.py (line 840) - read_response
  7. redis-py/redis/asyncio/connection.py (line 256) - _parser.read_response
  8. redis-py/redis/asyncio/connection.py (line 267) - _read_response

注意上面 connection.py 部分的行数可能和实际代码对不上，因为加了一些调试代码，影响了行数计算。取消异步任务，可以看到抛出了 asyncio.CancelledError 异常，那么具体是在哪里抛出这个异常呢？

异常抛出位置

还是通过不断的加日志，定位到了 connection.py，直观觉得应该在 data = await self._stream.readline() 中，这里的 _stream 是一个 asyncio.StreamReader 对象，它在读出一行内容的时候抛出了异常。如何确认这一点呢？尝试在这里添加 try 来捕获异常即可，不过开始的时候在这里捕获 Exception 异常，结果发现捕获不到。后来问了 ChatGPT，才知道在 Python 3.8 及更高版本中，asyncio.CancelledError 不再从 Exception 基类派生，而是直接从 BaseException 派生。于是改为下面的代码，验证了猜想。

1
2
3
4
5
6
7
8
9
# redis/asyncio/connection.py
async def _readline(self) -> bytes:
    # ...
    try:
        data = await self._stream.readline()
    # 验证确实在这里抛出了异常
    except asyncio.CancelledError:
        print("Task was cancelled")
    # ...

数据错乱原因

一个请求的执行流程已经很清晰了，但是还没有解决我们的疑问，为什么取消一个任务后，后续请求会读串。这里继续添加日志，在每个请求的开始部分打印请求命令( execute_command 里面添加日志)，然后打印解析出来的回包(_read_response 里面添加日志)，执行后结果如下：

请求和回复的对应错乱了

这里涉及到 Redis 回复的协议解析，Redis 使用的RESP（Redis Serialization Protocol）协议是一种简单、高效并且便于人直接阅读的基于文本的协议。它支持多种数据类型，包括字符串、数组和整数。客户端发送的命令请求和服务器的响应都遵循这个协议。具体格式的技术细节可以参考官方文档 RESP protocol spec。

通过上面的截图可以看出来，这里 bug 的根本原因在于，如果异步请求成功被 server 处理，那么在 redline 读取出回复前就抛出了异常。后续的请求在调用 readline 的时候，会读到这个被取消请求的回复。

Bug 修复

对 Python 的异步库 asyncio 和 reids-py 的实现细节不是很清楚，所以这里就直接看官方的修复代码了。不过官方修复过程也不是很顺利，中间有的修复代码和测试代码都是有问题的，下面来看看。

错误的修复方案

第一次修复尝试是在 PR 2641 中，有人提交了修复方案，关键部分在于：

修复的代码比对

这里的核心思路在于，既然取消异步操作会导致漏读 server 的回复，那就保证一旦进入到读操作，就不允许取消异步任务(这里其实是一个协程)，直到读出这部分回复。这里用到了 asyncio.shield 函数，它用来保护一个异步操作不被取消。如果在 asyncio.shield 函数中的操作正在进行时，其他地方尝试取消这个操作，那么这个取消操作会被忽略，直到 asyncio.shield 函数中的操作完成再抛出异常。关于 asyncio.shield 的详细解释，可以参考官方文档 Shielding From Cancellation。

这个修复方案被合并到了 v4.5.3 版本，然而在该版本下，能继续复现这个 bug。看了下代码，原因是这里的修复只对 execute 函数的取消加了保护，对于前面复现脚本执行路径中的 execute_command 并没有加保护。此外，这种保护方案本身也有问题，修改后就没法取消一个阻塞的异步请求，严重时甚至导致读请求卡住。

这个方案的提交者其实也提供了测试用例，不过用例写到有问题，导致没有测出这里的 bug。

错误的测试用例

这里 sleep 的时间是 1s，这时候这个读请求早执行完了的，所以取消操作其实没生效。这里复现的一个关键点就在于，要卡一个很精确的时间点，保证请求被处理，但是回复内容还没被解析。这里引出一个重要问题，就是测试要如何卡这个时间点，让 bug 能在有问题的版本稳定复现。

稳定复现与改进

随后，有开发者起了一个新的 Issue 2665，来讨论这里如何稳定复现。做法很简单，起了一个 proxy server，来中转 client 和 server 的通信。中转的时候，不论是请求还是响应，都延迟 0.1s。这相当于伪造了一个通信延迟 0.1s 的网络环境，然后就能稳定控制 cancel 异步操作的时机了。

其中中转 proxy 的部分代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
class DelayProxy:

    def __init__(self, addr, redis_addr, delay: float):
        self.addr = addr
        self.redis_addr = redis_addr
        self.delay = delay

    async def start(self):
        server = await asyncio.start_server(self.handle, *self.addr)
        asyncio.create_task(server.serve_forever())

    async def handle(self, reader, writer):
        # establish connection to redis
        redis_reader, redis_writer = await asyncio.open_connection(*self.redis_addr)
        pipe1 = asyncio.create_task(pipe(reader, redis_writer, self.delay, 'to redis:'))
        pipe2 = asyncio.create_task(pipe(redis_reader, writer, self.delay, 'from redis:'))
        await asyncio.gather(pipe1, pipe2)

完整的复现代码见 redis_cancel.py。

针对这里的复现，chayim 接着提交了 PR 2666 中，对应 commit 5acbde3 被放在 v4.5.4，在所有的命令操作场景中都用 asyncio.shield 禁止取消操作，关键部分的改动如下：

asyncio.shield 加保护

相当于对前面修复的一个补丁，这样确实修复了读串数据的 bug，新的测试脚本也无法复现。我们对下面的修复代码稍作改动，就能更好理解这里的修复原理了。把代码中的 asyncio.shield 部分抽离出来，打印结果，并尝试捕获异常。改动部分如下：

1
2
3
4
5
6
7
8
9
10
11
async def execute_command(self, *args, **options):
    # ...
    result = None
    try: 
        result = await asyncio.shield(
            self._try_send_command_parse_response(conn, *args, **options)
        )
        print(f"[log] {args} {result}")
        return result
    except asyncio.CancelledError:
        print(f"[EXCEPTION] {args}")

重新执行测试脚本，就能看到对于取消异步读部分的请求，输出如下：

[EXCEPTION] (‘GET’, ‘foo’)
try again, we did not cancel the task in time

可以看到加了 asyncio.shield 后，异步任务并没有在原来的 data = await self._stream.readline()(见前面对这里的说明) 位置抛出异常，而是正常执行完了异步的 get 操作，拿到结果 ‘foo’ 后在 await asyncio.shield 这里才最终抛出 asyncio.CancelledError 异常。本次 PR 还提交了能稳定复现的测试用例，在 tests/test_asyncio/test_cwe_404.py 中，基本思想还是用代理模拟延迟时间。

背景与最终修复

上面的修复看似解决了问题，不过 kristjanvalur 对这个修复方案很不满意，在 PR 2666 中也直接跟贴评论了。其实前面也提过，这种延迟异常抛出的做法，导致没法真正取消一个异步请求，在某些场景下甚至导致死锁。kristjanvalur 在这个 PR 中也给出了一个示例代码，来证明完全有可能导致死锁问题。

好事做到底，kristjanvalur 接着提了一个新的 PR 2695。这个 PR 的内容比较多，包括回滚 v4.5.3 和 4.5.4 中 shield 相关的代码，然后修复导致 ChatGPT 读错数据的的 Issue 2624，并提供了一个单元测试。

再多说一点这里的背景，kristjanvalur 2022年就为 asyncio/client.py 贡献了很多代码，包括 PR 2104: Catch Exception and not BaseException in the Connection，也就是只有遇到 Exception 情况才会关闭连接。正是这个改动，导致了某些场景下包含错误数据的连接，会被放回去连接池，具体讨论可以看 Issue 2499: BaseException at I/O corrupts Connection，这次的 bug 也是这个改动带来的。

具体修复方案的核心代码如下，在 read_response 中增加了对 BaseException 的异常处理，默认是直接断开连接。

异常直接断开连接

最终的验证过程

根据 Release 页面的版本日志，可以看到 4.5.5 版本合并了 PR 2695，如下图：

Redis python 的修复记录

切换到 v4.5.5 分支，然后再次用上面的复现脚本尝试验证，得到结果如下：

已经修复好的输出

至此，这个 bug 彻底修复了。再来加日志对上面的理解过程做一些验证，比如：

  1. 取消任务的时候，这里会断开连接；
  2. 下一次拿连接的时候，会用到一个新的连接；

这里在准备断开连接和新建连接的地方加上日志，通过 id(self._reader) 来验证确实建了新的 asyncio.StreamReader 对象。 如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
--- a/redis/asyncio/connection.py
+++ b/redis/asyncio/connection.py
@@ -638,6 +638,8 @@ class Connection:
             task = callback(self)
             if task and inspect.isawaitable(task):
                 await task
+
+        print(f'[log] New Connection {id(self._reader)} {id(self._writer)}')

     async def _connect(self):
         """Create a TCP socket connection"""
@@ -866,6 +868,7 @@ class Connection:
             # relies on this behaviour when doing Command/Response pairs.
             # See #1128.
             if disconnect_on_error:
+                print(f'[log] disconnecting {id(self._reader)} {id(self._writer)}')
                 await self.disconnect(nowait=True)
             raise

得到的输出如下，可以看到在取消任务时，立马断开了连接，这时候 id=4388303056 的 stream read 被销毁。接下来的 redis 操作新创建了 connection，并且分配了新的 id=4388321104 的 stream read。

[log] New Connection 4388303056 4385849616
[log] disconnecting 4388303056 4385849616
managed to cancel the task, connection is left open with unread response
[log] New Connection 4388321104 4385849616
bar: b’bar’
ping: True
foo: b’foo’

整体的修复思路清晰了，就是对于异常的请求 client，直接关闭 connection，这样会清理读写流。下一次再有新的请求，用一个新的流，就不会有读乱的问题了。

简单总结

OpenAI 公开了一个故障状态页面，实时展示各项服务的运行情况。当 ChatGPT 不可用时，用户可以第一时间在状态页面上确认，而不是盲目猜测问题出在自己这边。这种高透明度的做法值得学习，首先它体现了对用户的尊重和负责，不轻易封锁消息。其次也有利于公司积极主动应对问题，而不是回避或隐瞒。

OpenAI 公布的技术细节相当翔实，这也体现了其高度透明的态度。报告中还特别说明了问题仅存在于非常短的窗口，并列出了各种补救和防范措施，包括新增校验逻辑、日志记录、提升容错性等。这些细节无不显示 OpenAI 对用户隐私和产品质量的高度重视。然后通过详细分析本次 ChatGPT 服务中断的技术原因，我们也可以获得以下启示:

首先，这充分说明了开源社区力量的伟大。从最初的问题报告，到错误修复方案的提交，再到提供稳定复现手段，以及最终合理修复方案的实现，整个过程都有开源社区参与者的贡献。正是因为这样的协作，一个严重的 bug 才能在短时间内系统性地被分析并修复。

其次，这也体现了定位难以稳定复现的 bug 需要技巧。使用代理服务器来模拟网络延迟，创造出错误触发的时机窗口,为确认和定位 bug 提供了重要支持。这种手段对处理各类偶发的异常问题具有借鉴意义。

另外，这也展示了异步编程的难点。理解一个异步任务流的执行需要对代码细节有非常强的把握。打印日志和添加断点是必要手段，同时需要对语言和库的行为有充分理解，才能分析出问题的根源所在。

最后，这个案例也彰显了优秀开源项目的价值。不仅要提供可靠的功能实现，还需要有完善的文档、注释和测试代码。这是开源项目能够长期发展的基石。读者可以通过这种源码级的调试分析，掌握定位难点问题的技巧，提高自己的编程能力。也希望本文对需要深入理解开源项目实现的读者有所启发和帮助。

最后总结部分是 claude2 写的，感觉还可以？虽然有点说教的感觉。