WebSocket 数据传输中的大数据帧发送问题

Posted on

详细记录了一个WebSocket发送大数据包被截断的问题排查过程

问题背景

需求背景

我们有个业务场景，需要通过 WebSocket 发送图片，根据同事反馈，目前发送一个image数据大概140kb，会出现发送的数据被截断的情况，连接也会被断开

初步猜测：数据帧过大导致发送失败

看了一下代码，我们没有对发送数据包的大小做限制。但是从实际的测试表现来看，发送数据大小超过 140kb 的包，就很容易出现这个问题，初步猜测跟包大小有关。还需要进一步通过 Log 或者抓包确定。

问题复现与初步分析

这个问题很容易复现，这个对我们 troubleshooting 是很好的事情。我们用 mitmproxy 开启了一个代理服务器，然后在测试机器上配置这个代理服务器复现这个问题，这样做的目的是我们可以在 mitmproxy 上看到完整的 WebSocket 包，便于定位问题。mitmproxy 的 UI 交互有终端和 Web 两种形式，我更习惯使用 Web 方式，只需要在执行 mitmweb 命令，就可以启动服务。

交互界面如下：

初步分析验证后，我们确定就是数据帧过大导致的发送失败，具体错误信息从 Log 中可以获取到。基于 Log 的错误信息，我们可以进一步分析 Root Cause。

分析 Root Cause

以下是我们在 Log 中发现的错误信息

Socket not ready for send/recv

[10164:18664:12-20/17:43:51.370:DEBUG:SBCUrlRequest_WebSocket.cc(480)] [CSBCUrlRequest::WebSocket_CheckSendRecvData] End to post data, size:106830 Sent:0 Return:81 Curl Error String:Socket not ready for send/recv

这里的 Return:81 表示错误码是 81

1
2
3
CURLE_AGAIN (81)

Socket is not ready for send/recv wait till it's ready and try again. This return code is only returned from curl_easy_recv and curl_easy_send (Added in 7.18.2)

这个部分的错误信息表示套接字（Socket）没有准备好进行发送或接收操作。具体的错误代码是 CURLE_AGAIN (81)，这表示需要等待，直到套接字准备好，然后再次尝试。这通常是由于非阻塞套接字的操作，需要等待套接字变得可用才能进行进一步的发送或接收。

SSL routines::bad length

我们在日志中还观察到以下错误，这些错误出现在发生 CURLE_AGAIN 之后。

[10164:18664:12-20/17:43:51.520:INFO:SBCUrlRequest.cc(415)] [my_curl_debug_callback] This: 100664864 TEXT :SSL_write() error: error:0A00010F:SSL routines::bad length

我们当前是没有处理 CURLE_AGAIN ，出现 CURLE_AGAIN 时也会直接给业务层 OnDataSent callback。所以业务层可能在 socket 没有就绪的状态下持续不断地发送数据。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
size_t n_sent = 0;
CURLcode ret = curl_easy_send(m_hCurl, GetBaseOf(total_to_send),total_to_send.size(),&n_sent);

for(std::vector<CAString*>::iterator it = bytes_sent.begin(); it != bytes_sent.end(); ++it)
{
		m_webSocketState.doCallback([it,ret](IWebSocketConnectionCallback * callback){
            callback->OnDataSent(*it,ret);
		});
}	

ZLOG(DBG,"[CSBCUrlRequest::WebSocket_CheckSendRecvData] End to post data, size:"<<total_to_send.size()
		<<" Sent:"<<n_sent
		<<" Return:"<<ret
		<<" Curl Error String:"<<curl_easy_strerror(ret));

为何会出现 SSL routines::bad length 错误呢 ？

如果在套接字不可用的情况下进行 SSL_write，可能会引发 SSL_write() 错误，如 “bad length”。

SSL/TLS是一个状态机,涉及了复杂的握手/协商、加密/解密等过程。这些状态需要持续地保持同步。具体来说,SSL连接建立时,客户端和服务器端会协商生成“会话密钥”、初始化变量等。这构成了一个持续的SSL “会话”。如果在“会话”过程中,由于套接字不可用中断了通信,那么客户端和服务器端的SSL状态就失去了同步。之后在套接字不可用时强行调用SSL_write写入数据,那么参与后续加密和传输的数据长度,就很可能和服务器端持有的会话状态不匹配,导致解密或者长度校验失败,出现“bad length”错误。

问题修复与验证

测试环境

为了快速验证问题，我尝试搭建一个 WebSocket 测试服务器，在 github 中找到了一个 go 语言的版本的 WebSocket 服务器。但是我们的 WebSocket Client 实现有点问题，连接这个测试服务器时遇到了一些问题。

Sec-WebSocket-Key 不合法

Sec-WebSocket-Key是WebSocket协议中的一个重要字段,它用于WebSocket连接的握手过程中。

其规则及用途可以总结如下:

  1. 格式:Sec-WebSocket-Key字段的值是一个base64编码的随机字符串。
  2. 长度:随机字符串的长度必须是16个字节,即24个base64编码后的字符。所以服务端要验证长度是否合法。
  3. 用途:用于计算Sec-WebSocket-Accept的值,这个值会在服务器端响应首部中返回,这样可以完成WebSocket握手。计算方式是:将Sec-WebSocket-Key的值与一个特定的字符串“258EAFA5-E914-47DA-95CA-C5AB0DC85B11”连接起来,取SHA-1哈希值,然后base64编码。
  4. 目的:这一握手机制的目的是为了防止误连接,确认这确实是一个要升级为WebSocket的HTTP请求,避免被非法连接利用。

但是我们的 WebSocket Client 格式不规范，所以连接测试服务器时报错。

以下是具体的错误信息：

客户端 Log

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[46528:41076:12-21/10:29:59.773:INFO:SBCUrlRequest_WebSocket.cc(326)] [CSBCUrlRequest::WebSocket_NotifyConnectionGood] End to post data, head:
GET /f HTTP/1.1
Host: 127.0.0.1
Upgrade: websocket
Connection: Upgrade
**Sec-WebSocket-Key: **{15E21AB6-6AE4-4****
Sec-WebSocket-Version: 13
ZM-CAP: 8300567970761955255,6445493618999263140,7795585261064146175,7998097959182395391,18587783470514173
ZM-PROP: Win.Zoom
X-Zoom-AccountId: 

 Sent:287 Return:0 Curl Error String:No error 
[46528:41076:12-21/10:29:59.788:INFO:SBCUrlRequest_WebSocket.cc(207)] [CSBCUrlRequest::WebSocket_ParseHeadResponse] Heads:
**HTTP/1.1 400 Bad Request**
Content-Type: text/plain; charset=utf-8
Sec-Websocket-Version: 13
X-Content-Type-Options: nosniff
Date: Thu, 21 Dec 2023 02:29:59 GMT
Content-Length: 12

Bad Request

服务端 Log

1
Upgrade: websocket: not a websocket handshake: 'Sec-WebSocket-Key' header must be Base64 encoded value of 16-byte in length

修复代码

1
2
3
4
5
6
/*Upgrade: websocket: not a websocket handshake: 'Sec-WebSocket-Key'
			header must be Base64 encoded value of 16-byte in length*/

CAString trimed_client_guild = CMM_T2UTF(CString(m_clientGUID, 16));

CAString secKey = base64EncodeA((CmmUInt8*)trimed_client_guild.c_str(), trimed_client_guild.size());

测试用例

模拟发送大数据帧，期望能否复现 CURLE_AGAIN 错误，这样就能验证我们是否修复这个问题。

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
TEST(WebSocketServiceTest, SendBigData)
{
    CSBWebService *ws = CWebServiceTestInstManager::GetInstance().SetUp(Env_Dev);
		Cmm::CFileName fn;
		fn.GetModuleFilePath();
		fn += _T("\\big_size_file.log");
		std::ifstream file(fn.c_str());
		std::stringstream buffer;
		buffer << file.rdbuf();
		std::string longString = buffer.str();
	
		WebSocketTestApp app;
		CString channel_id;
		EXPECT_TRUE(app.ConnectTo(GetTestWebSocketHost(), channel_id));
		CmmUInt32 result = -1;
		app.CheckConnectState(channel_id, result);
		//EXPECT_EQ(result, SB_ERROR_SUCCESS);
	
		CAString test_str(longString);
    for (int i = 0; i < 100; i++) {
        ZLOG(INFO, "WebSocketServiceTest SendData test_str length: " << longString.size());
        EXPECT_TRUE(app.SendDataEx(0x2, channel_id, test_str));
        app.CheckSendDataEvent(channel_id, result);
    }

		app.Close(channel_id);
		app.CheckCloseEvent(channel_id, result);
		EXPECT_EQ(result, 0);

    CWebServiceTestInstManager::GetInstance().TearDown();
}

CURLE_AGAIN 处理和重试逻辑

需要增加 CURLE_AGAIN 等待逻辑，等待 socket 就绪时，再重发数据。

以下是基于 poll 事件驱动的伪代码：

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
#include <curl/curl.h>
#include <string>
#include <poll.h>

std::string curle_again_cache; 

struct pollfd poll_fd;

CURLcode try_send_data(CURL* curl, const std::string& data) {

  CURLcode res;
  size_t sent = 0;  

  res = curl_easy_send(curl, data.c_str(), data.size(), &sent);

  if(res == CURLE_AGAIN) {

    // 缓存数据 
    curle_again_cache = data;
    
    // 注册curl socket
    poll_fd.fd = curl_easy_getfd(curl);
    poll_fd.events = POLLOUT;

    // 等待socket就绪
    poll(&poll_fd, 1, -1);

    // 重试发送
    return try_send_data(curl, curle_again_cache);
  
  } else {

    return res;

  }

}

int main() {

  CURL* curl = curl_easy_init();
  std::string data = "123"; 

  CURLcode ret = try_send_data(curl, data);

  if(ret != CURLE_OK) {
    // 错误处理
  }

  curl_easy_cleanup(curl);

}

总结

troubleshooting 过程回顾

  1. 收到问题反馈后，我们随即启动 mitmproxy 代理，让同事连接这个服务器复现问题。期间准备验证所需的 build 折腾了大半天。
  2. 通过 Log 定位到具体的错误原因，Review 分析代码以后确定 Root Cause 是，我们的 WebSocket 发送数据没有处理 again 错误
  3. 讨论了大体的解决方案
  4. 分工并行: 着手修改代码，搭建测试服务器，写测试 Case，模拟复现验证问题
  5. Fix Patch 基于测试代码联调、优化、验证，单元测试通过
  6. 给业务方提供 Fix Patch 验证，end to end case 验证通过
  7. 19/12/2023 5:10 PM 同事反馈问题，21/12/2023 6:45 PM end to end 解决，耗时 2 天

两点启发

可以复现问题，并且能 Debug，基本上离找到 Root Cause 并且解决问题不远了。我们面临的很多问题都有类似的困惑，要么很难复现，要不测试环境非常复杂。有时候解决问题的关键就是能否找到复现问题的路径并模拟出测试环境。这个 Case 中，我们自己搭建了一个测试服务器，模拟发送大文件失败的 Case，我跟同事通过修改 test case 反复修改验证我们的代码，确保没问题以后交给使用方在真是业务场景下验证。

给我的启发有两个：

  1. 首先无论多么简单的代码调整都需要配上相应的测试代码，这个测试代码有助于我们在后续 toubleshooting 时快速调试、定位以及验证问题。
  2. 其次，测试环境对与模拟和复现问题非常关键，这个测试环境包括了诸如 NTLM & Kerberos 等复杂的认证流程，也包括了测试路径很复杂的业务流程，比如 SSO 登录，IPD，飞机模式代理域名登录等，我们无法保证每次 Regression 测试都能 Cover 所有的点，但是可以通过代码方式模拟测试验证。

三个收获

  1. 我们一直没有 WebSocket 的测试服务器，虽然有单元测试代码，但也是连接产线的一个数据推送服务器，现有的测试代码只是验证了 WebSocket 的连接建立、数据收发以及连接关闭，无法根据测试需求定制 Case，为了验证解决这个问题，我们也搭建了测试服务器，优化了测试代码，这个对后续验证 WebSocket 的问题提供了便利。
  2. 优化了对 WebSocket 发送大数据的处理，增强了 WebSocket 连接的鲁棒性
  3. 搭建 WebSocket 测试服务器的过程中，我们参考了一些开源项目。在这个过程中，我们了解到了 autobahn test-suite，这是一个专用于验证 WebSocket 实现是否符合规范的测试工具。autobahn test-suite 提供了丰富的测试用例，覆盖了 WebSocket 协议的多个边界情况。通过测试，我们发现了我们的 WebSocket 客户端存在许多不符合规范的地方。因此，我们计划基于这个 test-suite 对我们的 WebSocket 客户端进行进一步的测试和改进。