skynet icon indicating copy to clipboard operation
skynet copied to clipboard

Published 20 hours ago • verified publisher icon cloudwu

最近在阿里雲上轉用 skynet built in https 後，出現奇怪的 socket 問題

Open tomlau10 opened this issue 5 years ago • 11 comments

抱歉因為這個問題奇怪非常 無法定位到問題在哪裡，很難作出精簡的描述 請容我用比較長的篇幅做描述 🙏

背景

  • skynet 版本: 1.3.0rc release tag 的 commit
  • 我們的項目 在國外使用 google kubernetes engine (GKE) 在國內使用阿里雲 container kubernetes (ACK)
  • 在早期由於 skynet 框架沒有 https 支援 我們額外用 nodejs 寫了個 https proxy micro service 在另外的 container 跑 並將 server 所有 http / https request 都用 http request + 改 header host 方式 先發到這個 https proxy GKE 及 ACK 2邊也是這樣使用，一直正常
  • 針對 http(s) request，我們是有個 httpc skynet service 來集中做管理 並限制並發連接數上限 256 超過的話，http request 會在該 service 排隊處理 不過正常情況下，最大並發連接多數 < 5的
  • 到7月左右我們修改了提到的 httpc service 的代碼 可以直接使用 skynet built in https 去掉 nodejs proxy 的使用 並且測試通過後於 8月底 server 更新版本推出 奇怪的 socket 情況就開始出現了。。。

問題

  • GKE 上的 server 一直正常 (直到今天也正常)
  • 但是 ACK 上偶爾會有大量玩家回報 lag / 爆 ping (幾乎是全個服，客服從當前世界頻截圖得出這樣的判斷)
  • 不論人多還是人少 / 早上下午或凌晨都曾出現 一開始是週末才出現，嚴重時一天可以爆 ping 幾次 後來是隔天就出現一次
  • 當出現問題時，server log 會有一堆 socket error / closed 的 msg
2020-09-13 13:40:54.051721 [:00000013] socket: error on 107963 Connection reset by peer
2020-09-13 13:40:54.057327 [:00000013] socket: error on 107965 Connection reset by peer
2020-09-13 13:40:54.059430 [:00000013] fd = 107963, [Socket Error]
2020-09-13 13:40:54.060925 [:00000013] fd = 107965, [Socket Error]
2020-09-13 13:41:20.986025 [:00000013] socket: error on 108220 Connection reset by peer
2020-09-13 13:41:20.988263 [:00000013] socket: error on 108222 Connection reset by peer
2020-09-13 13:41:20.994423 [:00000013] fd = 108220, [Socket Error]
2020-09-13 13:41:20.996318 [:00000013] fd = 108222, [Socket Error]
...

這裡 service 13 是我們的 httpd service 做法是參考 skynet/example/simpleweb.lua 用另外端口來監聽外部 command eg shutdown / reboot / gm 後台對 server 做操作 且這個端口跟 game client 連接端口不相同 (下個部分再解釋為什麼這 httpd service 會經常有這麼多 socket 嘗試連接)

早期的測試

  • 由於 GKE 並沒有出現問題，所以最初懷疑跟 ACK 有關 ACK 的 loadbalancer 針對 exposed tcp port 有個 不能關掉的 health check loadbalancer 會不斷做 health check，這解釋了 httpd service 經常都會有 socket connect 而當連接失敗被判 unhealthy，loadbalancer 就會不再 route 該端口 的 traffic 到該 instance
  • 上邊的 service 13 socket error log 應該就是 health check 的 connection 而出現 error 感覺 是果不是因 即 network 異常，所有 connection 都被 pause / close 了 因此 log 才會出現 error 而並非 health check error 導致 container network 被中斷
  • 上點提到 httpd 端口跟 server 端口不相同 若果單純 httpd 端口出異常，理應不影響 game client 端口的 但當爆 ping 情況出現時，總有上述的 error log 相伴 所以暫時能解釋的，要麼是 skynet 框架中的 socket 處理有異常 要麼是 ACK 中 game server container 網絡有異常 單純到這裡來看，後者概率較高 因為同份代碼，在 GKE 下用相近 deployment 方式都沒有異常
  • 所以我們試著修改 ACK deployment 中的 health check interval 和加大 unhealthy 判定的 threshold 但完全沒有改善到問題。。。

後期的測試

  • 這個問題一直沒進展 😓 直到9月底左右，回想起問題是於 8月底更新 才出現 背景中提到當時 改用了 built in https 由於十一假期臨近，想到什麼方式也只能試試 於是抱著測試的心態，revert 了上述改動，轉回原有的 https proxy 方式 結果竟然問題就消失了
  • 然後就這樣過了愉快的十一假期 😐 到上週六早上 server 例行重啟前 我嘗試再改回去用 built in https 結果不到一天再次出現爆 ping 情況 ... server log 情況同前
2020-10-10 18:37:14.192075 [:00000013] socket: error on 127594 Connection reset by peer
2020-10-10 18:37:14.200870 [:00000013] socket: error on 127596 Connection reset by peer
2020-10-10 18:37:14.202783 [:00000013] fd = 127594, [Socket Error]
2020-10-10 18:37:14.203821 [:00000013] fd = 127596, [Socket Error]
2020-10-10 20:25:45.290115 [:00000013] socket: error on 135587 Connection reset by peer
2020-10-10 20:25:45.290139 [:00000013] socket closed
2020-10-10 23:18:56.362953 [:00000013] socket: error on 149113 Connection reset by peer
2020-10-10 23:18:56.363672 [:00000013] socket: error on 149115 Connection reset by peer
2020-10-10 23:18:56.363847 [:00000013] fd = 149113, [Socket Error]
2020-10-10 23:18:56.364811 [:00000013] fd = 149115, [Socket Error]
...

嚇得我慌忙又換回去 https proxy 的做法 😑 然後週日就又回復正常了

暫時結論

  • 貌似只有使用 skynet built in https 時，才會在 ACK 出現這個問題 => skynet 問題，ACK 未必有問題
  • 然而 GKE 上同一套代碼，無論運行 https proxy 還是 skynet built in https 都沒事 => skynet 沒問題，是 ACK 問題
  • 但以上2點好像又互相予盾 因而無從判斷究竟是單純 skynet https 還是單純 ACK 的問題 又或是 ACK + skynet https 才會出問題。。。 並且目前也沒有進一步訊息判斷 哪一個環節 出問題

請問各位有遇過這種奇怪情況嗎? 有沒有 debug 方向建議? 個人還是希望能用上 skynet https 的 這樣 server 架構可以簡潔點，去掉 nodejs https proxy 🤔

tomlau10 avatar Oct 12 '20 07:10 tomlau10

skynet 并没有 1.3.0rc 这个 tag ，不知道准确版本是什么？

另外，8 月份的 https://github.com/cloudwu/skynet/commit/a4dc6b909478a7397eb205f3ca5a2800e9391d65 增加了一个 pause 的特性，这个今天查出来是有 bug 的。因为原意是在客户端到服务器上行流量超过了处理能力后，可以暂停接收数据。但是这个 pause 同时把下行也中断了，导致在 pause 发生时，无法写出数据。

这个 bug 在今天 https://github.com/cloudwu/skynet/commit/f3acbe46df1bfe15170bf54a79df650dcb791b6a 修复。

但我看不出这个 bug 和这里有什么关系？

上行过载本身是比较罕见的事情，一般不会触发。如果使用了该版本，可以通过修改 https://github.com/cloudwu/skynet/blob/master/lualib/skynet/socket.lua#L6 BUFFER_LIMIT 为一个极大的数值来避免触发。目前是 128K ，即，如果单条连接上堆积了超过 128K 数据未被读取，那么会主动 pause 上行数据（但 bug 会导致下行写出的数据也同时被 pause ）。

你可以去掉 build-in https ，而用最新 skynet 代码，看看是否还有问题。

cloudwu avatar Oct 12 '20 11:10 cloudwu

我理解是：玩家走的 https 协议的通道上并没有出错信息，但有 lag 延迟。 ACK 会出现 error 信息是因为某种超时机制导致请求方主动断开？

看文档介绍，ACK 走的是 http 协议，而不是 https 协议。是不是 ACK 用 http 请求去请求了 https 端口？能不能在 httpd 服务中加入更多的 log 观察 ACK 发送了怎样的数据包？

cloudwu avatar Oct 12 '20 11:10 cloudwu

想到一种解释：

因为你限制了最大连接数 256 ，如果被占满，会导致 ACK 请求被搁置。一旦超时，ACK 会任务不健康，然后转而不再转发。

建议：

  1. 给 ACK 的 IP 设立白名单 。
  2. 到达最大连接数后增加 log 。
  3. 排除潜在的服务过载问题（找出超出 256 的可能性）。

cloudwu avatar Oct 13 '20 02:10 cloudwu

skynet 并没有 1.3.0rc 这个 tag ，不知道准确版本是什么？

確實沒有這個 tag，估計是我看錯 commit msg 成 release tag 了。。。 準確 commit hash 是 a6293f27cd08cbe33b5dc99b561e54659d544d54 是 2019 年 11月中左右 換句話應該後提到的 增加了一个 pause 的特性 無關 🤔 (因為 skynet 版本還未去到這 commit)

我理解是：玩家走的 https 协议的通道上并没有出错信息，但有 lag 延迟。

理解有誤，客戶端是直接用 socket 跟 server 做數據交互 跟 https 無關 上文提到的 httpc service 是 server 自身發 http request 所使用的

  • eg server 收到客戶端 socket 傳來 login(param)
  • 玩家可能是用 weixin login
  • server 需要通過 weixin api 驗證 token => server 就會透過 httpc service 來發 http request
  • server 收到 http reply 後，再 socket write data 給客戶端

看文档介绍，ACK 走的是 http 协议

是的 可能上文寫得太長，我表達得不清晰 🙈 我們項目中是有這麼 2個 service

  • httpc => server 集中管理 自身對外發 http request 之用，限制了 server 同時最多發 256 request 這個 service 可按我們的 deployment config，去選擇
    • 是否 所有 request 都通過 nodejs proxy 使用時 url 會改成 httpc.request("http://<nodejs-proxy>/<path/...>") 並透過改 header host 傳原本的 host
    • 還是單純用 skynet 的 httpc.request("原有url") 來處理所有 request
  • httpd (上邊的 service 13) => server 用來接收外部 http request command，eg reboot / shutdown

這2個 service 都不是面向客戶端的 前者只是類 http connection pool 管理 後者則因為要接收外部 http request 而 expose 了端口到 ACK loadbalancer 繼而 ACK loadbalancer 會對這端口做 http health check

以上 2個 service，功能上及代碼上都完全隔離，貌似沒什麼關聯 而目前是 httpc service 在使用 httpc.request() 處理所有 https request 時 偶爾 會導致 整個 container 所有 network 異常 的情況

  • 影響玩家普通的 socket 傳輸
  • 也影響 httpd ACK 的 health check reply

假如是跟 skynet 有關，2者共通的部分就只有 socket 層 (?) 🤔

ACK 会出现 error 信息是因为某种超时机制导致请求方主动断开？

同意 ACK 的 health check 有 timeout 選項，我們配置了 10s 理論上 server 應該可以秒回的 除非是 container network 出異常，又或 skynet 框架 socket 層出了異常 (讀不到 / 寫不到 socket)

是不是 ACK 用 http 请求去请求了 https 端口？

按上邊 httpc 跟 httpd 是2個分開 service 的解釋 應該不會出現這問題 httpd service 自身只會回應 http 而不回應 https 的

能不能在 httpd 服务中加入更多的 log 观察 ACK 发送了怎样的数据包？

對方是發一個 HEAD http request 過來 HEAD /test.html HTTP/1.0\r\n\r\n 然後我們的 httpd service 能用 httpd.read_request() 正確 decode 接著 httpd.write_response() 200 ok 回敬他

tomlau10 avatar Oct 13 '20 10:10 tomlau10

你可以去掉 build-in https

我前文表述有誤。。。 轉用 built in https 後出問題 並非指 compile skynet 加上 TLS_MODULE=ltls 就會造成問題 我們目前 GKE 和 ACK 上的 skynet 都是 compile 帶有 TLS_MODULE=ltls flag 的

經測試後，發現造成 ACK 上的問題 是 業務邏輯，會否將 https request 傳入 httpc.request()

上邊提到我們最初架構是用 nodejs https proxy 就是 轉化業務邏輯所有 request (http / https) 都改成 httpc.request("http://nodejs-proxy/path...", { host = "原host", proxy_https = 0/1 }) 然後由 nodejs 應用按 header.proxy_https == 1 來轉換成 https，並返回 reply 給 server 這種情況下，server 代碼就 不會觸發到任何 "http.tlshelper" library 的代碼 server 不會有偶爾爆 ping / 任何 network 問題

但若是直接讓業務邏輯上的 https request 經由 httpc.request("https://原host/path...") 方式處理 就會偶爾出現 network 問題 🤔

但暫時無法解釋為何相同的代碼 (GKE / ACK 都使用相同 server docker image) 在 GKE 上不會引起問題。。。

tomlau10 avatar Oct 13 '20 10:10 tomlau10

我觉得你可以在 http.tlshelper 模块内多加一些 log 帮助分析到底发生了什么事情，收发了怎样的数据。

我们最近一年用 skynet 做了一些内部用的非常高负荷高流量高并发连接的服务，暂时没有发现网络层有什么 bug 。我认为可以信任网络层的实现。

倒是在处理高流量复杂的业务时，需要做一些流量控制操作，避免把数据堆积在网络层造成 OOM (out of memory) 问题，这就是最近新添的 api 的作用。

倒是 tls 可以多测试一下。但是有好些朋友使用基于 tsl 的 websocket 服务，似乎没有类似反馈。

我倾向于认为首先是 ACK 出错，导致阿里云判断健康有问题，从而停止了端口转发，继而造成玩家 lag 。

cloudwu avatar Oct 13 '20 11:10 cloudwu

啊~ 另外有一個觀察 不確定會否有關

我們的業務會用到 zendesk 來處理客服相關 server 會調用到 zendesk 相關 api 而 ACK 上由於有 GFW 的關係 zendesk api 調用偶爾會抽風 短則 <30s，長則抽5分鐘 GKE 上則不會有抽風情況

當 ACK 出現相關 api request 抽風時 在 container 內，另外跑 curl -vvv <zendesk> 看到是卡在 client hello 1步

/app # curl -vvv https://test.zendesk.com/api/v2/tickets/show_many.json
*   Trying 104.16.51.111...
* TCP_NODELAY set
* Connected to test.zendesk.com (104.16.51.111) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: none
  CApath: /etc/ssl/certs
* (304) (OUT), TLS handshake, Client hello (1):

卡了良久 (1分鐘左右?) 後會彈出 ssl error syscall

* OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to test.zendesk.com:443
* stopped the pause stream!
* Closing connection 0
curl: (35) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to test.zendesk.com:443
/app #

  • server 在有使用 nodejs https proxy 架構下 對於 server 來說，socket.connect() 是正常的 (因為只是 connect 到 https proxy container 而已) 而由於用 proxy 機制下，所有 request 皆轉換成 http 就不會調用到 httpc.request() 中的 interface.init()

  • 若然 server 不使用 nodejs https proxy 架構 等同於 server 自己跟 https 打交道 => 會執行 interface.init() (也就會轉到 c層 lts.c 的 _ltls_context_handshake() 之類)

請教一下 若按上邊 curl verbose 的卡在 client tls handshake 這步的情況 skynet https 若也卡在這步的話 c 層調用會否出現任何問題? (eg blocking) 🤔

tomlau10 avatar Oct 13 '20 11:10 tomlau10

lts.c 问题需要 @lvzixun 来看。 不过该模块是一个纯 C 模块，不涉及网络 api ，它只负责处理数据。也就是说，不应该在 C 模块内部有任何阻塞。如果能增加更多 log 显示 lts.c 的内部的信息可能可以帮助排查问题。

阻塞一定发生在 lua 层，任何 c 层次的阻塞都会触发监控 log 。这个现象更像是 lts.c 模块需要的网络数据没有收全，导致 block 在 lua 层的 socket.read 上。

cloudwu avatar Oct 13 '20 11:10 cloudwu

我建议可以把 https://github.com/cloudwu/skynet/blob/master/lualib/http/tlshelper.lua#L7 这里这个 socket.readfunc 包装一层，单独加上额外的 log ，观察在阻塞发生的时候的数据流。

cloudwu avatar Oct 13 '20 12:10 cloudwu

记录一下：

我们在2021.12.15也出现过大量 http/https 调用失败的问题， 具体原因还在查。 表现是：所有从skynet 请求外部的 http/https 全部超时，甚至根本就没发出去，持续时间有10多分钟，后来不知什么原因自行恢复。 这段时间运维监控上来看， 外部http接口都是正常的。 同时受影响的还有 mysql 服务， 数据不能写入mysql，mysql 服务的消息堆积很多。

skynet 版本: 1.3.0

aceyin avatar Dec 16 '21 08:12 aceyin

1.3.0 版本 socket 没有 pause/resume 机制，在两端收发不对等时，容易出问题；另外，没有对半关闭状态妥善处理。

ps. skynet 版本更迭很少破坏兼容性，所以提倡尽量用 github 最新版本，勤更新比长期大更新更少出问题。现在没有维护特定稳定版的计划。

cloudwu avatar Dec 16 '21 09:12 cloudwu