記一次Redis連接池問題引發的RST

某個項目，因爲監控尚不完善，所以我時常會人肉查查狀態，終於有一天發現了異常：

watch -d -n1 ‘netstat -s | grep reset’

如圖所示，服務器發送了大量的 reset，在我 watch 的時候還在發，多半有問題。

通過 tcpdump 我們可以簡單抓取一下 RST 包：

shell> tcpdump -nn 'tcp[tcpflags] & (tcp-rst) != 0'

不過更好的方法是通過 tcpdump 多抓一些流量然後用 wireshark 來分析：

RST

如圖所示，描述了一個 web 服務器和一個 redis 服務器的交互過程，有兩個問題：

在我的場景裏，使用了 lua-resty-redis 連接池，爲什麼還會發送 FIN 來關閉連接？
即便關閉連接，爲什麼 web 服務器收到 FIN 後還會發送 RST 補刀？

因爲項目代碼比較多，我一時確定不了 lua-resty-redis 連接池的問題在哪，所以我打算先搞定爲什麼 web 服務器收到 FIN 後還會發送 RST 補刀的問題。

我們可以通過 systemtap 來查查內核（3.10.0-693）是通過什麼函數來發送 RST 的：

shell> stap -l 'kernel.function("*")' | grep tcp | grep reset
kernel.function("bictcp_hystart_reset@net/ipv4/tcp_cubic.c:129")
kernel.function("bictcp_reset@net/ipv4/tcp_cubic.c:105")
kernel.function("tcp_cgroup_reset@net/ipv4/tcp_memcontrol.c:200")
kernel.function("tcp_fastopen_reset_cipher@net/ipv4/tcp_fastopen.c:39")
kernel.function("tcp_highest_sack_reset@include/net/tcp.h:1538")
kernel.function("tcp_need_reset@net/ipv4/tcp.c:2183")
kernel.function("tcp_reset@net/ipv4/tcp_input.c:3916")
kernel.function("tcp_reset_reno_sack@net/ipv4/tcp_input.c:1918")
kernel.function("tcp_sack_reset@include/net/tcp.h:1091")
kernel.function("tcp_send_active_reset@net/ipv4/tcp_output.c:2792")
kernel.function("tcp_v4_send_reset@net/ipv4/tcp_ipv4.c:579")
kernel.function("tcp_v6_send_reset@net/ipv6/tcp_ipv6.c:888")

雖然我並不熟悉內核，但並不妨礙解決問題。通過查看源代碼，可以大致判斷出 RST 是 tcp_send_active_reset 或者 tcp_v4_send_reset 發送的。

爲了確認到底是誰發送的，我啓動了兩個命令行窗口：

一個運行 tcpdump：

shell> tcpdump -nn 'tcp[tcpflags] & (tcp-rst) != 0'

另一個運行 systemtap：

#! /usr/bin/env stap

probe kernel.function("tcp_send_active_reset") {
    printf("%s tcp_send_active_reset\n", ctime())
}

probe kernel.function("tcp_v4_send_reset") {
    printf("%s tcp_v4_send_reset\n", ctime())
}

通過對照兩個窗口顯示內容的時間點，最終確認 RST 是 tcp_v4_send_reset 發送的。

接下來確認一下 tcp_v4_send_reset 是誰調用的：

#! /usr/bin/env stap

probe kernel.function("tcp_v4_send_reset") {
    print_backtrace()
    printf("\n")
}

// output

0xffffffff815eebf0 : tcp_v4_send_reset+0x0/0x460 [kernel]
0xffffffff815f06b3 : tcp_v4_rcv+0x5a3/0x9a0 [kernel]
0xffffffff815ca054 : ip_local_deliver_finish+0xb4/0x1f0 [kernel]
0xffffffff815ca339 : ip_local_deliver+0x59/0xd0 [kernel]
0xffffffff815c9cda : ip_rcv_finish+0x8a/0x350 [kernel]
0xffffffff815ca666 : ip_rcv+0x2b6/0x410 [kernel]
0xffffffff81586f22 : __netif_receive_skb_core+0x572/0x7c0 [kernel]
0xffffffff81587188 : __netif_receive_skb+0x18/0x60 [kernel]
0xffffffff81587210 : netif_receive_skb_internal+0x40/0xc0 [kernel]
0xffffffff81588318 : napi_gro_receive+0xd8/0x130 [kernel]
0xffffffffc0119505 [virtio_net]

如上所示，tcp_v4_rcv 調用 tcp_v4_send_reset 發送了 RST，看看 tcp_v4_rcv 的源代碼：

int tcp_v4_rcv(struct sk_buff *skb)
{
    ...

    sk = __inet_lookup_skb(&tcp_hashinfo, skb, th->source, th->dest);
    if (!sk)
        <strong>goto no_tcp_socket;</strong>

process:
    if (sk->sk_state == TCP_TIME_WAIT)
        goto do_time_wait;

    ...

no_tcp_socket:
    if (!xfrm4_policy_check(NULL, XFRM_POLICY_IN, skb))
        goto discard_it;

    if (skb->len < (th->doff << 2) || tcp_checksum_complete(skb)) {
csum_error:
        TCP_INC_STATS_BH(net, TCP_MIB_CSUMERRORS);
bad_packet:
        TCP_INC_STATS_BH(net, TCP_MIB_INERRS);
    } else {
        tcp_v4_send_reset(NULL, skb);
    }

    ...

do_time_wait:

    ...

    switch (tcp_timewait_state_process(inet_twsk(sk), skb, th)) {

        ...

        case TCP_TW_RST:
            <strong>goto no_tcp_socket;</strong>

        ...

    }

    ...
}

有兩處 no_tcp_socket 調用，也就是說有兩處可能會觸發 tcp_v4_send_reset。先看後面的 no_tcp_socket 代碼，也就是 do_time_wait 相關的部分，只有進入 TIME_WAIT 狀態纔會執行相關邏輯，而本例中發送了 RST，並沒有正常進入 TIME_WAIT 狀態，不符合要求，所以問題的癥結應該是前面的 no_tcp_socket 代碼，也就是 __inet_lookup_skb 相關的部分：當 sk 不存在的時候，reset。

不過 sk 爲什麼會不存在呢？當 web 服務器發送 FIN 的時候，進入 FIN_WAIT_1 狀態，當 redis 服務器回覆 ACK 的時候，進入 FIN_WAIT_2 狀態，如果 sk 不存在，那麼就說明 FIN_WAIT_1 或者 FIN_WAIT_2 中的某個狀態丟失了，通過 ss 觀察一下：

shell> watch -d -n1 'ss -ant | grep FIN'

通常，FIN_WAIT_1 或者 FIN_WAIT_2 存在的時間都很短暫，不容易觀察，不過在本例中，流量比較大，所以沒問題。結果發現，可以觀察到 FIN_WAIT_1，但是卻很難觀察到 FIN_WAIT_2，看上去 FIN_WAIT_2 似乎丟失了。

想到這裏我突然想到 TIME_WAIT 有一個相關的控制項：tcp_max_tw_buckets，用來控制 TIME_WAIT 的數量，可能與此有關：

shell> sysctl -a | grep tcp_max_tw_buckets
net.ipv4.tcp_max_tw_buckets = 131072

shell> cat /proc/net/sockstat
sockets: used 1501
TCP: inuse 117 orphan 0 tw 127866 alloc 127 mem 56
UDP: inuse 9 mem 8
UDPLITE: inuse 0
RAW: inuse 0
FRAG: inuse 0 memory 0

對比系統現有的 tw，可以發現已經臨近 tcp_max_tw_buckets 規定的上限，試着提高閾值，會發現又能觀察到 FIN_WAIT_2 了，甚至 RST 的問題也隨之消失。

如此一來，web 服務器收到 FIN 後還會發送 RST 補刀的問題算是有眉目了：TIME_WAIT 數量達到 tcp_max_tw_buckets 規定的上限，進而影響了 FIN_WAIT_2 的存在，於是在 tcp_v4_rcv 調用 __inet_lookup_skb 查找 sk 的時候查不到，最終只好發送 RST。

結論：tcp_max_tw_buckets 不能太小！

…

問題到這裏還不算完，別忘了我們還有一個 lua-resty-redis 連接池的問題尚未解決。

如何驗證連接池是否生效呢？

最簡單的方法是覈對連接 redis 的 TIME_WAIT 狀態是否過多，肯定的話那麼就說明連接池可能沒生效，爲什麼是可能？因爲在高併發情況下，當連接過多的時候，會按照 LRU 機制關閉舊連接，此時出現大量 TIME_WAIT 是正常的。

When the connection pool would exceed its size limit, the least recently used (kept-alive) connection already in the pool will be closed to make room for the current connection.

最準確的方法是使用 redis 的 client list 命令，它會打印每個連接的 age 連接時長。通過此方法，我驗證發現 web 服務器和 redis 服務器之間的連接，總是在 age 很小的時候就被斷開，說明有問題。

在解決問題前瞭解一下 lua-resty-redis 的連接池是如何使用的：

local redis = require "resty.redis"
local red = redis:new()

red:connect(ip, port)

...

red:set_keepalive(0, 100)

只要用完後記得調用 set_keepalive 把連接放回連接池即可。一般出問題的地方有兩個：

openresty 禁用了 lua_code_cache，此時連接池無效
redis 的 timeout 太小，此時長鏈接可能會頻繁被關閉

在我的場景裏，如上問題均不存在。每當我一籌莫展的時候我就重看一遍文檔，當看到 connect 的部分時，下面一句話提醒了我：

Before actually resolving the host name and connecting to the remote backend, this method will always look up the connection pool for matched idle connections created by previous calls of this method.

也就是說，即便是短鏈接，在 connect 的時候也會嘗試從連接池裏獲取連接，這樣的話，如果是長短連接混用的情況，那麼連接池裏長鏈接建立的連接就可能會被短鏈接關閉掉。順着這個思路，我搜索了一下源代碼，果然發現某個角落有一個短鏈接調用。

結論：不要混用長短連接！