解Bug之路-記一次對端機器宕機後的tcp行爲

時間 2020-09-24

原文原文鏈接

解Bug之路-記一次對端機器宕機後的tcp行爲

前言

機器通常過質保以後，就會由於各類各樣的問題而宕機。而這一次的宕機，讓筆者觀察到了日常觀察不到的tcp在對端宕機狀況下的行爲。通過詳細跟蹤分析緣由以後，發現能夠經過調整內核tcp參數來減小宕機形成的影響。java

Bug現場

筆者所在的公司用某個中間件的古老版本作消息轉發，此中間件在線上運行有些年頭了，大約剛開始部署的時候機器仍是全新的，如今都已通過保了。機器的宕機致使了一些詭異的現象。以下圖所示:linux

在中間件所在機器宕機以後，出現了調用中間件超時的現象。拋開各類業務細節，會發現出現了時間很長的超時。其中一波在821s以後報出了Connection reset異常，還有一波在940s以後報出了Connection timed out(Read failed)異常。網絡

線索追查

發現出bug的時間點很微妙,有將近10個請求是在22:32:22.300左右集中報錯，而且這個時間點有Connection reset。
另外一波是在22:34.11.450左右集中報錯,而且這個時間點由Connection timed out(Read failed)。
因而筆者看了下此中間件client的網絡模型,以下圖所示:

這就很容易理解，爲什麼請求爲什麼都是在同一時刻超時，由於是順序請求，後面的幾個請求還沒發送出去，就因爲第一個請求超時而致使後面的全部請求報錯。以下圖所示:

進一步推出，真正的socket超時時間是請求1(最長)的超時時間。
即對應oracle

Connection reset的821s
Connection timed out(Read failed)的940s

client設置了socket.soTimeOut爲0

這個中間件採用了bio模型，而且socket沒有設置超時時間，其業務超時時間經過業務層的future來控制。可是這個超時時間只有在真正發送請求的時間起做用，每一個請求以前還會有其它的一段交互，以下圖所示:

至此，問題緣由已經很明顯了，在(do something)的那個過程因爲socket設置soTimeOut爲0，致使卡住了至關長的一段時間。代碼以下圖所示:運維

.....
protected int soTimeout;
......
protected void initialiseSocket(Socket sock) throws SocketException, IllegalArgumentException {
	 ......
 	 // 默認是0
 	 sock.setSoTimeout(soTimeout);
 	 ......
}

socket設置soTimeOut爲0的表現

問題自己的查找是比較簡單的，若是僅僅只有這些的話，筆者也不會將其寫成一篇博客。
因爲socket設置timeout(>0)是一種常識，不多遇到設置爲0的狀況。因而其引發的現象引發了筆者的興趣。咱們看看socket設置timeout爲0後jdk源碼的描述:dom

/**
	  * ......
     *  A timeout of zero is interpreted as an infinite timeout.
     * ......
     */
    public synchronized void setSoTimeout(int timeout) throws SocketException {
        if (isClosed())
            throw new SocketException("Socket is closed");
        if (timeout < 0)
          throw new IllegalArgumentException("timeout can't be negative");

        getImpl().setOption(SocketOptions.SO_TIMEOUT, new Integer(timeout));
    }

裏面有這麼一段話socket

A timeout of zero is interpreted as an infinite timeout

按上述字母解釋爲若是設置爲0的話，應該是等待無限長的時間(直到進程重啓)。
但是按照線上業務的表現，確是有超時時間的，只不過期間很長。最長的達到了940s，即15分鐘多。
這就引發了筆者的興趣，究竟是什麼讓這個無限的超時時間被打斷呢？咱們繼續分析。tcp

Connection reset

首先咱們聚焦於第一個異常報錯Connection reset(22:32分), 筆者自己閱讀過tcp協議棧源碼，知道基本上全部Connection reset都由對端發出。因此筆者料定在22:32分的時候，機器確定又活過來了，可是對應的中間件進程確沒有起來，因此沒有對應的端口，進而當包過來的時候，發送tcp reset包回去(即便當前中間件起來了也會發送reset,由於tcp自己的seq序列號校驗失敗)。以下圖所示:

而後瞭解到在22:32左右，爲了拷貝宿主機內部的消息記錄，運維確實將宕掉的機器從新給拉起來了，這進一步印證了個人想法。可是按照筆者的推論，在22:32分新發出重傳的全部的請求都被Connection reset了，爲什麼在將近兩分鐘以後(準確的說是在1分49s以後由又報了一波錯？)繼續往下分析。
(注意22:32分和22:34分報錯的是不一樣的socket鏈接)ui

Connection timed out(Read failed)

這個錯誤不多遇到。不知道是在哪一種狀況下觸發。具體的異常棧爲:this

Caused by: java.net.SocketException: Connection timed out(Read failed)
		 at java.net.SocketInputStream.socketRead0(Native Method) ~[?1.8.0_121]
		 at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_121]
		 ......

因而用sublime搜索Connection timed out,發現其只在Java_java_net_PlainSocketImpl_socketConnect出現，和上面的異常棧明顯不符合。
那麼就從socketRead0入手，咱們詳細看看源代碼:

JNIEXPORT jint JNICALL
Java_java_net_SocketInputStream_socketRead0(JNIEnv *env, jobject this,
                                            jobject fdObj, jbyteArray data,
                                            jint off, jint len, jint timeout)
{
	......
	 nread = NET_Read(fd, bufP, len);

    if (nread <= 0) {
        if (nread < 0) {

            switch (errno) {
                case ECONNRESET:
                case EPIPE:
                    JNU_ThrowByName(env, "sun/net/ConnectionResetException",
                        "Connection reset");
                    break;

                case EBADF:
                    JNU_ThrowByName(env, JNU_JAVANETPKG "SocketException",
                        "Socket closed");
                    break;

                case EINTR:
                     JNU_ThrowByName(env, JNU_JAVAIOPKG "InterruptedIOException",
                           "Operation interrupted");
                     break;

                default:
                    NET_ThrowByNameWithLastError(env,
                        JNU_JAVANETPKG "SocketException", "Read failed");
            }
        }
    } 
    ......
}

答案就在NET_ThrowByNameWithLastError裏面，其最後調用的是os::stderr來獲取kernel返回的error字符串。
查了下linux stderr手冊，發現是ETIMEDOUT對應了Connection timed out。
可是後面的Connection timed out(Read failed)中的(Read failed)不該該拼接在後面，由於其邏輯是kernel返回error就用kernel的error,不然用defaultDetail即(Read failed和errno的組合)。具體緣由，筆者並無在openJdk源碼中找到，猜想多是版本的緣由或者oracleJdk和openJdk之間細微的差異。

ETIMEDOUT

既然是linux kernel返回的，筆者就立馬翻了linux源碼。
(這其中有個插曲，就是筆者一開始看的是2.6.24內核源碼，發現怎麼計算都對不上數據。後來看到線上用的是2.6.32內核版本，翻了對應版本的源碼，才搞定)
既然是sockRead0返回的，那確定不是socket建立鏈接階段(SYN)，確定到了establish的send/rcv階段。這個錯誤最有可能就是在重傳失敗的時候返回的錯誤。因而翻了下重傳的源代碼:

static void tcp_retransmit_timer(struct sock *sk)
{
	......
	// 檢查當前重傳是否已經超過最大時間
	if (tcp_write_timeout(sk))
		goto out;
	......
	icsk->icsk_backoff++;
	icsk->icsk_retransmits++;
out_reset_timer:
	// 從新重傳定時器，rto最大爲TCP_RTO_MAX即爲120s
	icsk->icsk_rto = min(icsk->icsk_rto << 1, TCP_RTO_MAX);
	inet_csk_reset_xmit_timer(sk, ICSK_TIME_RETRANS, icsk->icsk_rto, TCP_RTO_MAX);
	if (retransmits_timed_out(sk, sysctl_tcp_retries1 + 1))
		__sk_dst_reset(sk);
}

上面邏輯是首先斷定是否超時，若是未超時則設置下一個超時時間。邏輯以下圖所示：

咱們再看下tcp_write_timeout:

static int tcp_write_timeout(struct sock *sk){
	...
	// 對SYN，即建立鏈接過程當中的處理
	...
	// retry即便kernel中的tcp_retries2
	// 即cat /proc/sys/net/ipv4/tcp_retries2便是15
	retry_until = sysctl_tcp_retries2;
	// 下面就是超時判斷的過程
 	if (retransmits_timed_out(sk, retry_until)) {
		/* Has it gone just too far? */
		// 若是超過最大時間，則調用tcp_write_err
		tcp_write_err(sk);
		return 1;
	}
	return 0;
}

tcp_write_err確實返回了ETIMEDOUT,以下面源碼所示:

static void tcp_write_err(struct sock *sk)
{
	sk->sk_err = sk->sk_err_soft ? : ETIMEDOUT;
	// 返回ETIMEDOUT
	sk->sk_error_report(sk);

	tcp_done(sk);
	NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_TCPABORTONTIMEOUT);
}

至此，基本能夠斷定就是tcp_write_timeout超時了，也即其中的
retransmits_timed_out斷定超時。
很明顯爲何940s的時候沒有Connection reset，就是因爲先判斷了tcp_write_timeout超時致使沒有發送下一個重傳包，而直接time_out,若是發了，那就是Connection reset。

retransmits_timed_out的計算過程

這個計算過程直接上源碼:

static inline bool retransmits_timed_out(struct sock *sk,
					 unsigned int boundary)
{
	unsigned int timeout, linear_backoff_thresh;
	unsigned int start_ts;

	if (!inet_csk(sk)->icsk_retransmits)
		return false;

	if (unlikely(!tcp_sk(sk)->retrans_stamp))
		start_ts = TCP_SKB_CB(tcp_write_queue_head(sk))->when;
	else
		start_ts = tcp_sk(sk)->retrans_stamp;

	linear_backoff_thresh = 
(TCP_RTO_MAX/TCP_RTO_MIN);

	if (boundary <= linear_backoff_thresh)
		timeout = ((2 << boundary) - 1) * TCP_RTO_MIN;
	else
		timeout = ((2 << linear_backoff_thresh) - 1) * TCP_RTO_MIN +
			  (boundary - linear_backoff_thresh) * TCP_RTO_MAX;

	return (tcp_time_stamp - start_ts) >= timeout;
}

上述源碼中,boundary = 15，那麼
TCP_RTO_MAX=120s,TCP_RTO_MIN=200ms
linear_backoff_thresh = ilog2(120s/200ms)=ilog2(600)=ilog2(1001011000二進制),ilog的實現爲:

#define ilog2(n)
(						\
	__builtin_constant_p(n) ? (		\
		(n) < 1 ? ____ilog2_NaN() :	\
		(n) & (1ULL << 63) ? 63 :	\
		......
		(n) & (1ULL <<  9) ?  9 :	\
		/* 即(1001011000 & 1000000000)=1=>返回9 */
		......
)

因爲boundary=15 > linear_backoff_thresh(9)因此，計算超時時間爲:
timeout = ((2 << linear_backoff_thresh) - 1) * TCP_RTO_MIN +(boundary - linear_backoff_thresh) * TCP_RTO_MAX;
即(TCP_RTO_MIN=200ms,TCP_RTO_MAX=120s)
timeout = ((2 << 9 - 1) * 0.2s + (15 - 9) * 120s=924.6s

值得注意的是，由上面的代碼邏輯，咱們tcp_retries=15指的並非重傳15次，而是在rto初始值爲200ms的狀況下計算一個最終超時時間，實際重傳次數和15並無直接的關係。

重傳最終超時的上下界

重傳最終超時的下界

由上面的計算可知,
即在重傳後的tcp_time_stamp（當前時間戳）- start_ts(第一次重傳時間戳)>=924.6s的時候,即拋出異常，那麼重傳最終超時的下界就是924.6s，以下圖所示:

重傳最終超時的上界

咱們假設在第N次的時候tcp_time_stamp - start_ts=924.5999s時候進行超時斷定，那麼勢必會進行下一次重傳，並在924.5999+120=1044.5999s後超時，以下圖所示:

那麼，重傳最終超時的上界就是1044.6s
最終結論:

重傳最終超時的上下界是:
[924.6,1044.6]

用不一樣的rto計算下最終超時

由上面代碼可知，重傳rto是不停的*2,一直到TCP_RTO_MAX(120s)爲止,閱讀linux代碼可知,在筆者的線上狀況下,初始rto=srtt>>3 + rttvar(TCP_RTO_MIN)(固然了，實際比這個複雜的多,計算暫以TCP_RTO_MIN代替),即初始rto=200ms+(一個計算出來的值)
筆者寫了個模擬程序:

public class RetransSimulate {

    public static void timeOutCaclulate(double rto) {
        double initialRto = rto;
        double sum = 0;
        while (true) {
            sum += rto;
            if (sum > 924600) {
                break;
            }
            rto = rto * 2;
            rto = rto < 120000 ? rto : 120000;
        }
        // 以50ms做爲偏差
        if(Math.abs(sum - 939997) < 50){
            System.out.println("rto="+initialRto+",timeout=" + sum);
            System.out.println();
        }
    }

    public static void main(String[] args) {
        // rtt > 3 + rttval(這個計算有點複雜，這邊能夠直接用TCP_RTO_MIN作計算)
        // 以0.01ms爲精度
        double rto =  0.01 + 200;// 0.01 for random rtt > 3（初始擾動）,200 for TCP_RTO_MIN
        // 最多計算到300
        for (int i = 0; i < 10000; i++) {
            timeOutCaclulate(rto);
            rto += 0.01 ;
        }
    }
}

發現距離線上真實表現超時時間最近的是:

rto=215.00999999998635,timeout=939955.229999986

rto=215.01999999998634,timeout=939965.459999986

rto=215.02999999998633,timeout=939975.689999986

rto=215.03999999998632,timeout=939985.919999986

rto=215.0499999999863,timeout=939996.1499999859

rto=215.0599999999863,timeout=940006.3799999859

rto=215.0699999999863,timeout=940016.609999986

rto=215.07999999998628,timeout=940026.839999986

這樣，基本就能基本肯定在宕機的時候，用的rto是215了
題外話:
以前博客裏面筆者想固然的將rto認爲成rtt，致使以前的模擬程序在rto的初始值沒有加上200ms,咱們同事在復現現場的時候，發現第一次重傳包確實是200ms左右，和筆者的推理並不同。
使得筆者從新閱讀了rto源碼，發現其rto初始就要加上TCP_RTO_MIN(實際上是rttvar,細節有點複雜,在此略過不表),感謝那位同事，也向以前閱讀過筆者此篇博客的人道歉,筆者犯了想固然的毛病。

機器響應的時間窗口

因爲到了800s/900s的時候，確定已經到了TCP_RTO_MAX(120s),因此咱們能夠根據兩個socket的報錯時間計算一下機器響應的時間窗口。在這裏爲了簡便分析，咱們忽略包在網絡中的最長存活時間,以下圖所示:

即機器開始應答的時間應該在22:32:11至22:32:22之間。
固然了，很難獲取到機器真正開始應答的精確時間來證明筆者的計算。可是這個計算的意義在於若是二者的應答窗口沒有交疊，那麼筆者的上述推論就是錯的，須要推倒重來。存在這個時間窗口，可讓筆者的推測在邏輯上自洽。