一次请求超时问题排查记录

int tcp_v4_rcv(struct sk_buff *skb)
{
	const struct iphdr *iph;
	const struct tcphdr *th;
	struct sock *sk;
	/* 中间省略 */
process:
  // TCP连接处于TIMT_WAIT状态时，跳转到do_time_wait
	if (sk->sk_state == TCP_TIME_WAIT)
		goto do_time_wait;
  /* 中间省略 */
do_time_wait:
	/* 中间省略 */
  // 根据tcp_timewait_state_process函数返回值，确定下一步动作
	switch (tcp_timewait_state_process(inet_twsk(sk), skb, th)) {
  // 合法SYN包，可以复用TCP连接，tcp状态可以切换至SYN_RECV
	case TCP_TW_SYN: {
		struct sock *sk2 = inet_lookup_listener(dev_net(skb->dev),
							&tcp_hashinfo,
							iph->saddr, th->source,
							iph->daddr, th->dest,
							inet_iif(skb));
		if (sk2) {
			inet_twsk_deschedule(inet_twsk(sk), &tcp_death_row);
			inet_twsk_put(inet_twsk(sk));
			sk = sk2;
			goto process;
		}
		/* Fall through to ACK */
	}
  /* 发送ACK包
  	1.TCP_FIN_WAIT2状态收到FIN包，发送最后一次挥手的ACK包
  	2.TCP_TIME_WAIT状态下发送上一次的ACK包
  */
	case TCP_TW_ACK:
		tcp_v4_timewait_ack(sk, skb);
		break;
  // 发送RESET包
	case TCP_TW_RST:
		tcp_v4_send_reset(sk, skb);
		inet_twsk_deschedule(inet_twsk(sk), &tcp_death_row);
		inet_twsk_put(inet_twsk(sk));
		goto discard_it;
  // 直接丢弃，不做处理
	case TCP_TW_SUCCESS:;
	}
	goto discard_it;
}

tcp_timewait_state_process(struct inet_timewait_sock *tw, struct sk_buff *skb,
			   const struct tcphdr *th)
{
	struct tcp_options_received tmp_opt;
	struct tcp_timewait_sock *tcptw = tcp_twsk((struct sock *)tw);
	bool paws_reject = false;

	tmp_opt.saw_tstamp = 0;
  // tcp header中开启了options且当前tcp连接开启了时间戳选项
	if (th->doff > (sizeof(*th) >> 2) && tcptw->tw_ts_recent_stamp) {
		tcp_parse_options(skb, &tmp_opt, 0, NULL);
		if (tmp_opt.saw_tstamp) {
			if (tmp_opt.rcv_tsecr)
				tmp_opt.rcv_tsecr -= tcptw->tw_ts_offset;
			tmp_opt.ts_recent	= tcptw->tw_ts_recent;
			tmp_opt.ts_recent_stamp	= tcptw->tw_ts_recent_stamp;
      /* 如果开启了TCP timestamp可选项，判断是否发生时间戳回绕
      1. paws_reject = false 时间戳没有回绕
      2. paws_reject = true  时间戳回绕 */
			paws_reject = tcp_paws_reject(&tmp_opt, th->rst);
		}
	}

  // tcp状态是FIN_WAIT2的处理逻辑
	if (tw->tw_substate == TCP_FIN_WAIT2) {
    /* 中间省略 */
  }

  // 时间戳没有回绕
	if (!paws_reject &&
      // 报文序列号 等于 预期接收的序列号
	    (TCP_SKB_CB(skb)->seq == tcptw->tw_rcv_nxt &&
       /* TCP_SKB_CB(skb)->end_seq = (TCP_SKB_CB(skb)->seq + th->syn + th->fin +
       										skb->len - th->doff * 4);
      		没有携带数据报文，只有tcp header且没有syn/fin标志位，只能是reset或者ack
       */
	     (TCP_SKB_CB(skb)->seq == TCP_SKB_CB(skb)->end_seq || th->rst))) {
		/* In window segment, it may be only reset or bare ack. */

		if (th->rst) {
      // net.ipv4.tcp_rfc1337内核参数等于0时
			if (sysctl_tcp_rfc1337 == 0) {
kill:
        //清理TIME_WAIT连接
				inet_twsk_deschedule(tw, &tcp_death_row);
				inet_twsk_put(tw);
				return TCP_TW_SUCCESS;
			}
		} else {
      // 重置TIME_WAIT状态timeout时间
			inet_twsk_schedule(tw, &tcp_death_row, TCP_TIMEWAIT_LEN,
					   TCP_TIMEWAIT_LEN);
		}

		if (tmp_opt.saw_tstamp) {
			tcptw->tw_ts_recent	  = tmp_opt.rcv_tsval;
			tcptw->tw_ts_recent_stamp = get_seconds();
		}

		inet_twsk_put(tw);
		return TCP_TW_SUCCESS;
	}

 // SYN包且没有rst/ack标志位，时间戳没有回绕
	if (th->syn && !th->rst && !th->ack && !paws_reject &&
      // 序列号没有回绕 或者
	    (after(TCP_SKB_CB(skb)->seq, tcptw->tw_rcv_nxt) ||
       // 请求报文中开启timestamp可选项并且时间戳没有回绕
	     (tmp_opt.saw_tstamp &&
	      (s32)(tcptw->tw_ts_recent - tmp_opt.rcv_tsval) < 0))) {
		u32 isn = tcptw->tw_snd_nxt + 65535 + 2;
		if (isn == 0)
			isn++;
		TCP_SKB_CB(skb)->tcp_tw_isn = isn;
		return TCP_TW_SYN;
	}

	if (paws_reject)
    // 更新 /proc/net/netstat
		NET_INC_STATS_BH(twsk_net(tw), LINUX_MIB_PAWSESTABREJECTED);

	if (!th->rst) {
		/* In this case we must reset the TIMEWAIT timer.
		 *
		 * If it is ACKless SYN it may be both old duplicate
		 * and new good SYN with random sequence number <rcv_nxt.
		 * Do not reschedule in the last case.
		 */
		if (paws_reject || th->ack)
      // 重置TIME_WAIT状态timeout时间
			inet_twsk_schedule(tw, &tcp_death_row, TCP_TIMEWAIT_LEN,
					   TCP_TIMEWAIT_LEN);
		/*
		if (*last_oow_ack_time) {
			s32 elapsed = (s32)(tcp_time_stamp - *last_oow_ack_time);
			// 计算当前的tcp timestamp(jiffies)和上次发送ack时的tcp timestamp 差值
			// 如果小于内核参数net.ipv4.tcp_invalid_ratelimit 表示速率过快，需要限速
			if (0 <= elapsed && elapsed < sysctl_tcp_invalid_ratelimit) {
			  // 更新 /proc/net/netstat
				NET_INC_STATS(net, mib_idx);
				return true;
		  }
	  }
		如果dupacks没有限速 return TCP_TW_ACK，否则return TCP_TW_SUCCESS
    */
		return tcp_timewait_check_oow_rate_limit(
			tw, skb, LINUX_MIB_TCPACKSKIPPEDTIMEWAIT);
	}
	inet_twsk_put(tw);
	return TCP_TW_SUCCESS;
}

static inline bool tcp_paws_reject(const struct tcp_options_received *rx_opt,
				   int rst)
{
  // tcp_paws_check()函数判断是否通过检查
	if (tcp_paws_check(rx_opt, 0))
		return false;
	if (rst && get_seconds() >= rx_opt->ts_recent_stamp + TCP_PAWS_MSL)
		return false;
	return true;
}

static inline bool tcp_paws_check(const struct tcp_options_received *rx_opt,
				  int paws_win)
{
	if ((s32)(rx_opt->ts_recent - rx_opt->rcv_tsval) <= paws_win)
		return true;
	if (unlikely(get_seconds() >= rx_opt->ts_recent_stamp + TCP_PAWS_24DAYS))
		return true;

	if (!rx_opt->ts_recent)
		return true;
	return false;
}

// after函数定义
static inline bool before(__u32 seq1, __u32 seq2)
{
        return (__s32)(seq1-seq2) < 0;
}
#define after(seq2, seq1) 	before(seq1, seq2)

#dnat 收到访问172.16.10.8:80请求路由转发到192.168.10.9:80
$ iptables -t nat -A PREROUTING -d 172.16.10.8/32 -i eth0 -p tcp -m tcp --dport 80 -j DNAT --to-destination 192.168.10.9:80

#snat 访问192.168.10.9:80的请求，源地址转换为3.3.10.10
$ iptables -t nat -A POSTROUTING -d 192.168.10.9/32 -o eth1 -p tcp -m tcp --dport 80 -j SNAT --to-source 3.3.10.10

$ sysctl -w net.ipv4.ip_forward=1
# 参考物理防火墙配置
$ systcl -w net.netfilter.nf_conntrack_tcp_timeout_time_wait=2

$ iptables -t nat -A PREROUTING -m conntrack --ctstate INVALID -j LOG --log-prefix "Conntrack INVALID: " --log-level 7

# conntrack日志记录文件
$ grep conntrack /etc/rsyslog.conf
kern.*                              /var/log/conntrack.log

$ sysctl -w net.ipv4.ip_forward=1
# 参照专用设备配置
$ systcl -w net.netfilter.nf_conntrack_tcp_timeout_time_wait=60

# SimpleHTTPServer默认是HTTP/1.0
$ nohup python -m SimpleHTTPServer 80 &

[root@node1] ~$ curl --local-port 54321 172.16.10.8:80
<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 3.2 Final//EN"><html>
<title>Directory listing for /</title>
<body>
<h2>Directory listing for /</h2>
<hr>
<ul>
<li><a href="nohup.out">nohup.out</a>
<li><a href="test.file">test.file</a>
</ul>
<hr>
</body>
</html>

[root@localhost] $ tcpdump -ieth0 port 80 -nnS
17:08:16.798635 IP 3.3.10.10.54321 > 192.168.10.9.80: Flags [S], seq 2851797271, win 29200, options [mss 1460,nop,nop,sackOK,nop,wscale 9], length 0
17:08:16.798704 IP 192.168.10.9.80 > 3.3.10.10.54321: Flags [S.], seq 912495348, ack 2851797272, win 29200, options [mss 1460,nop,nop,sackOK,nop,wscale 9], length 0
...省略...
17:08:16.806065 IP 3.3.10.10.54321 > 192.168.10.9.80: Flags [F.], seq 2851797347, ack 912495758, win 60, length 0
17:08:16.806073 IP 192.168.10.9.80 > 3.3.10.10.54321: Flags [.], ack 2851797348, win 58, length 0

[root@node2] /data0/fake$ python send_test.py 2851797340
[root@node2] /data0/fake$ cat send_test.py
#!/usr/bin/python
#-*- coding:utf-8 -*-
from scapy.all import *
import sys

if len(sys.argv) < 2:
    print 'lack args'
    sys.exit()
# 创建一个IP数据包，设置源IP、目标IP
ip_packet = IP(src="172.16.9.132", dst="172.16.10.8")

# 创建一个TCP数据包，设置源端口、目标端口和序列号
tcp_packet = TCP(sport=54321, dport=80,flags='S', seq=int(sys.argv[1]))

# 组装数据包
syn = ip_packet / tcp_packet
send(syn)

17:08:24.023783 IP 3.3.10.10.54321 > 192.168.10.9.80: Flags [S], seq 2851797340, win 8192, length 0
17:08:24.023842 IP 192.168.10.9.80 > 3.3.10.10.54321: Flags [.], ack 2851797348, win 58, length 0

[root@localhost] $ bpftrace trace-time_wait.bt
Attaching 4 probes...
tcp_timewait_state_process:
3.3.10.10:54321 -> 192.168.10.9:80
[syn:1,ack:0,fin:0,rst:0], seq:1351613457, ack:0, win:32120, tw_rcv_nxt:1125813282
tw_substate: TCP_TIME_WAIT
tcp_tw_status: TCP_TW_SYN
################################

static int tcp_rcv_synsent_state_process(struct sock *sk, struct sk_buff *skb,
					 const struct tcphdr *th, unsigned int len)
{
	struct inet_connection_sock *icsk = inet_csk(sk);
	struct tcp_sock *tp = tcp_sk(sk);
	struct tcp_fastopen_cookie foc = { .len = -1 };
	int saved_clamp = tp->rx_opt.mss_clamp;

	tcp_parse_options(skb, &tp->rx_opt, 0, &foc);
	if (tp->rx_opt.saw_tstamp && tp->rx_opt.rcv_tsecr)
		tp->rx_opt.rcv_tsecr -= tp->tsoffset;

	if (th->ack) {
		/* rfc793:
		 * "If the state is SYN-SENT then
		 *    first check the ACK bit
		 *      If the ACK bit is set
		 *	  If SEG.ACK =< ISS, or SEG.ACK > SND.NXT, send
		 *        a reset (unless the RST bit is set, if so drop
		 *        the segment and return)"
		 */
		if (!after(TCP_SKB_CB(skb)->ack_seq, tp->snd_una) ||
		    after(TCP_SKB_CB(skb)->ack_seq, tp->snd_nxt))
			goto reset_and_undo;

		if (tp->rx_opt.saw_tstamp && tp->rx_opt.rcv_tsecr &&
		    !between(tp->rx_opt.rcv_tsecr, tp->retrans_stamp,
			     tcp_time_stamp)) {
			NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_PAWSACTIVEREJECTED);
			goto reset_and_undo;
		}

 		/* Now ACK is acceptable.
		 *
		 * "If the RST bit is set
		 *    If the ACK was acceptable then signal the user "error:
		 *    connection reset", drop the segment, enter CLOSED state,
		 *    delete TCB, and return."
		 */

		if (th->rst) {
			tcp_reset(sk);
			goto discard;
		}

		/* rfc793:
		 *   "fifth, if neither of the SYN or RST bits is set then
		 *    drop the segment and return."
		 *
		 *    See note below!
		 *                                        --ANK(990513)
		 */
		if (!th->syn)
			goto discard_and_undo;

    ...省略...

[root@nod[root@node1] /data0$ python scapy_http.py 1
[root@nod[root@node1] /data0$ cat scapy_http.py
#!/usr/bin/python
#-*- coding:utf-8 -*-
from Scapy_Tcpsession import TcpSession
import sys

if len(sys.argv) < 2:
    print 'lack args'
    sys.exit()
sess = TcpSession(('172.16.10.8',80,int(sys.argv[1]),54321))
sess.connect()
http_get=(
    "GET / HTTP/1.0\r\n"
    "Host: 172.16.10.8:80\r\n"
    "User-Agent: Python Scapy\r\n"
    "Connection: close\r\n\r\n"
)
sess.send(http_get)

[root@node2] ~$ curl --local-port 54321 172.16.10.8:80
、<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 3.2 Final//EN"><html>
<title>Directory listing for /</title>
<body>
<h2>Directory listing for /</h2>
<hr>
<ul>
<li><a href="nohup.out">nohup.out</a>
<li><a href="test.file">test.file</a>
</ul>
<hr>
</body>
</html>

[root@node2] /data0/kernel$ bpftrace synsent.bt
#!/usr/bin/env bpftrace

#include <linux/tcp.h>
#include <net/tcp.h>

BEGIN
{
    @tcp_sk_status[2] = "TCP_SYN_SENT";
    @tcp_sk_status[9] = "TCP_LAST_ACK";
}

kprobe:tcp_rcv_state_process
{
    $sk=(struct sock *)arg0;
    $tp=(struct tcp_sock *)$sk;
    $skb = (struct sk_buff *)arg1;
    $iphd = ((struct iphdr *)($skb->head + $skb->network_header));
    $th = ((struct tcphdr *)($skb->head + $skb->transport_header));
    $dport = $th->dest;
    $dport = ($dport >> 8) | (($dport << 8) & 0x00FF00);
    if ($dport == 54321) {
        $ack = $th->ack_seq;
        $ack = ($ack >> 24) | (($ack & 0x00FF0000) >> 8) | (( $ack & 0x00FF00) << 8) | (($ack & 0xFF) << 24);
        $skc_state=$sk->__sk_common.skc_state;
        printf("%s:\ntcp_sk_status: %s, syn:%u,ack:%u,fin:%u,ack_seq:%u, snd_una:%u, snd_nxt:%u\n",func,@tcp_sk_status[$skc_state],$th->syn,$th->ack,$th->fin,$ack,$tp->snd_una,$tp->snd_nxt);

        $una = $tp->snd_una - $ack;
        $int_una = (int32) $una;
        // (!after(TCP_SKB_CB(skb)->ack_seq, tp->snd_una)
        if (!((int32)($tp->snd_una - $ack) < 0)) {
            printf("%d, SEG.ACK =< ISS\n",$int_una);
        }

        $nxt = $tp->snd_nxt - $ack;
        $int_nxt = (int32) $nxt;
        // after(TCP_SKB_CB(skb)->ack_seq, tp->snd_nxt))
        if ((int32)($tp->snd_nxt - $ack) < 0) {
            printf("%d, SEG.ACK > SND.NXT\n",$int_nxt);
        }
    }
}

END
{
    clear(@tcp_sk_status);
}

[root@node2] /data0/kernel$ bpftrace synsent.bt
tcp_rcv_state_process:
tcp_sk_status: TCP_SYN_SENT, syn:0,ack:1,fin:0,ack_seq:88, snd_una:2387012236, snd_nxt:2387012237
-1907955147, SEG.ACK > SND.NXT

tcp_rcv_state_process:
tcp_sk_status: TCP_SYN_SENT, syn:1,ack:1,fin:0,ack_seq:2387012237, snd_una:2387012236, snd_nxt:2387012237

tcp_rcv_state_process:
tcp_sk_status: TCP_LAST_ACK, syn:0,ack:1,fin:0,ack_seq:2387012313, snd_una:2387012312, snd_nxt:2387012313

[root@localhost] $ cat trace-time_wait.bt
#!/usr/bin/env bpftrace

#include <linux/tcp.h>
#include <net/tcp.h>
#include <net/inet_timewait_sock.h>

BEGIN
{
    @tw_substate[5] = "TCP_FIN_WAIT2";
    @tw_substate[6] = "TCP_TIME_WAIT";

    @tcp_tw_status[0] = "TCP_TW_SUCCESS";
    @tcp_tw_status[2] = "TCP_TW_ACK";
    @tcp_tw_status[3] = "TCP_TW_SYN";
}

kprobe:tcp_timewait_state_process
{
    $inet = (struct inet_timewait_sock *)arg0;
    $tw = (struct tcp_timewait_sock *)$inet;
    $skb = (struct sk_buff *)arg1;
    $th = (struct tcphdr *)arg2;

    $iphd = ((struct iphdr *)($skb->head + $skb->network_header));
     if ($iphd->protocol == IPPROTO_TCP) {

        $srcaddr = $iphd->saddr;
        $dstaddr = $iphd->daddr;
        $srcip = ntop($iphd->saddr);
        $dstip = ntop($iphd->daddr);

        // $th = ((struct tcphdr *)($skb->head + $skb->transport_header));
        $dport = $th->dest;
        $dport = ($dport >> 8) | (($dport << 8) & 0x00FF00);
        if ($dport == 80) {
            $sport = $th->source;
            $sport = ($sport >> 8) | (($sport << 8) & 0x00FF00);

            // $st = *$th;
            $seq = $th->seq;
            $seq = ($seq >> 24) | (($seq & 0x00FF0000) >> 8) | (( $seq & 0x00FF00) << 8) | (($seq & 0xFF) << 24);

            $ack = $th->ack_seq;
            $ack = ($ack >> 24) | (($ack & 0x00FF0000) >> 8) | (( $ack & 0x00FF00) << 8) | (($ack & 0xFF) << 24);
            $win = $th->window;
            $win = ($win >> 8) | (($win << 8) & 0x00FF00);

            $tw_rcv_nxt = $tw->tw_rcv_nxt;

            printf("%s:\n",func);
            printf("%s:%d -> %s:%d\n",$srcip, $sport, $dstip, $dport);

            /*
            TCP_FIN_WAIT2状态收到fin包:
            tcptw->tw_rcv_nxt = TCP_SKB_CB(skb)->end_seq; 回复对方的ack包中 ack=tw_rcv_nxt=seq+1
            TCP_SKB_CB(skb)->end_seq = (TCP_SKB_CB(skb)->seq + th->syn + th->fin + skb->len - th->doff * 4);
            */
            printf("[syn:%d,ack:%d,fin:%d,rst:%d], seq:%-u, ack:%u, win:%u, tw_rcv_nxt:%u\n",$th->syn, $th->ack, $th->fin, $th->rst, $seq, $ack, $win, $tw_rcv_nxt);
            // printf("%d compare %d\n",$th->doff,sizeof($st)>>2);
            $state = $inet->tw_substate;
            $statestr = @tw_substate[$state];
            printf("tw_substate: %s\n",$statestr);
        }
    }
}

kretprobe:tcp_timewait_state_process
{
    $ret = retval;
    $statestr = @tcp_tw_status[$ret];
    printf("tcp_tw_status: %s\n",$statestr);
    print("################################");
}

END
{
    clear(@tw_substate);
    clear(@tcp_tw_status);
}

[root@localhost] $ bpftrace trace-time_wait.bt
tcp_timewait_state_process:
3.3.10.10:54321 -> 192.168.10.9:80
[syn:1,ack:0,fin:0,rst:0], seq:2387012236, ack:0, win:32120, tw_rcv_nxt:88
tw_substate: TCP_TIME_WAIT
tcp_tw_status: TCP_TW_ACK
################################
tcp_timewait_state_process:
3.3.10.10:54321 -> 192.168.10.9:80
[syn:0,ack:0,fin:0,rst:1], seq:88, ack:0, win:0, tw_rcv_nxt:88
tw_substate: TCP_TIME_WAIT
tcp_tw_status: TCP_TW_SUCCESS
################################