Please enable Javascript to view the contents

实时跟踪内核 TCP 连接失败与重试 - 基于 BPF

 ·  ☕ 4 分钟

引

生产环境的问题，按出现频率，大体可以分为两类：

  • 高频问题
  • 低频问题
    • 周期性低频问题
    • 无周期随机发生问题
      • 单例发生
      • 多例发生

一般，遇到 无周期随机发生问题 且 单例发生 的情况，是最难定位问题根源的。

前不久，我就遇到应用对外发起连接 无周期随机发生 且 单例发生 的情况 。你不可能在大流量的情况下，做 tcpdump 去分析连接情况的。而能透视内核状态的 eBPF/BPF 可能是个更合适的选择。

eBPF 可以在以下事件发生时，抓取到 连接信息：

  • 应用发起 connect()，连接进入 SYN_SENT 状态时
  • 在发送 SYN 一定时间后，无收到响应而重传 SYN 时
  • connect timeout 后，应用 close() socket。连接从 SYN_SENT 状态变为CLOSE状态时

这里说的连接信息，包括：

  • 连接 4 元组： source_IP: local_port <-> destination_IP:dest_port
  • 事发时的连接状态

而这些 事件 + 连接信息 可以为进一步研判问题的方向，提供一个客观的事实证据。

应用场景例子

之前，我了一篇：特定条件下 Istio 发生 half-close 连接泄漏与出站连接失败 。其中模拟了一个场景：

应用程序出站outbound连接超时因为应用程序选择了一个与-15001outboundlistener-上的现有套接字冲突的临时端口

  1. App invoke syscall connect(sockfd, peer_addr) , kernel allocation a ephemeral port(44410 in this case) , bind the new socket to that ephemeral port and sent SYN packet to peer.

  2. SYN packet reach conntrack and it create a track entry in conntrack table:

$ conntrack -L
tcp  6 108 SYN_SENT src=172.29.73.7 dst=172.21.206.198 sport=44410 dport=7777 src=127.0.0.1 dst=172.29.73.7 sport=15001 dport=44410

  1. SYN packet DNAT to 127.0.0.1:15001

  2. SYN packet reach the already existing FIN-WAIT-2 127.0.0.1:15001 172.29.73.7:44410 socket, then sidecar reply a TCP Challenge ACK (TCP seq-no is from the old FIN-WAIT-2) packet to App

大体意思是，如果应用在发起出站连接时，内核自动选择的临时本地端口如果与 “Envoy 在 15001 上的 FIN-WAIT-2 状态的 socket 的对端端口” 相同时，就会有问题。为了提高问题发生机率，我当时用 nc -p $临时本地端口号 的方法指定 临时本地端口号，而不是让内核自动选择， 模拟端口号冲突的。

但实际应用是让内核自动选择临时本地端口号 的。那么问题来了，如果要证明在问题发生时， 内核自动选择的临时本地端口号 就是我设想的情况？

实时跟踪 TCP 连接失败与重试

我们知道，TCP 连接超时的处理过程，大概会有发下几个事件(函数)点：

  • 应用调用 connect()。连接进入 SYN_SENT 状态
    • 对应内核的 tcp_connect()
  • 在发送 SYN 一定时间后，因无收到响应而间歇重传 SYN
    • 对应内核的tcp_retransmit_skb()
  • connect timeout 后，应用 close() socket。连接从 SYN_SENT 状态变为CLOSE状态时
    • 对应内核的inet_sk_state_store()

Talk is cheap, show you the code :

  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
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111

#!/usr/local/bin/bpftrace
#include <asm-generic/errno.h>
#include <linux/in.h>
#include <net/tcp_states.h>
#include <net/sock.h>
#include <net/inet_sock.h>
#include <linux/socket.h>

// trace-poll-timeout.bt file

BEGIN
{
    printf("Tracing IP TCP connect latency and SYN retry with stacks. Ctrl-C to end.\n");

    @tcp_states[1] = "ESTABLISHED";
    @tcp_states[2] = "SYN_SENT";
    @tcp_states[3] = "SYN_RECV";
    @tcp_states[4] = "FIN_WAIT1";
    @tcp_states[5] = "FIN_WAIT2";
    @tcp_states[6] = "TIME_WAIT";
    @tcp_states[7] = "CLOSE";
    @tcp_states[8] = "CLOSE_WAIT";
    @tcp_states[9] = "LAST_ACK";
    @tcp_states[10] = "LISTEN";
    @tcp_states[11] = "CLOSING";
    @tcp_states[12] = "NEW_SYN_RECV";    
}

kprobe:tcp_connect
{
    $sk = (struct sock *)arg0;
    $inet = (struct inet_sock *)arg0;

    @sk2connectUS[$sk] = nsecs;
}



kprobe:inet_sk_state_store
{
    $sk = (struct sock *)arg0;
    $inet = (struct inet_sock *)arg0;
    $newstate = arg1;
    if( $newstate == TCP_CLOSE ) {
        if( $sk->__sk_common.skc_state == TCP_SYN_SENT && @sk2connectUS[$sk] ) {

            $dport = $sk->__sk_common.skc_dport;
            $dport = ($dport >> 8) | (($dport << 8) & 0x00FF00);

            $sport = $inet->inet_sport;
            $sport = ($sport >> 8) | (($sport << 8) & 0x00FF00);

            $sk_family = $sk->__sk_common.skc_family;


            time("%H:%M:%S ");
            printf("TCP_SYN_SENT to CLOSE: %-6d %-16s %d ms %-3d ", 
                pid, comm, (nsecs - @sk2connectUS[$sk])/1000000,
                $sk_family == AF_INET ? 4 : 6);
            printf("%-15s:%-5d  -->  %-15s:%-5d\n", ntop($sk_family , $inet->inet_saddr), $sport,
                ntop($sk_family, $sk->__sk_common.skc_daddr), $dport);
            printf("kstack: %s\n", kstack);
            printf("ustack: %s\n", ustack);
        }
        else {

        }
        delete(@sk2connectUS[$sk]);
    }

}

kprobe:tcp_retransmit_skb
{
    $sk = (struct sock *)arg0;
    $inet_family = $sk->__sk_common.skc_family;
    if ($inet_family == AF_INET || $inet_family == AF_INET6)
    {
        $state = $sk->__sk_common.skc_state;
        if( $state == 2/*SYN_SENT*/ ) {
            $daddr = ntop(0);
            $saddr = ntop(0);
            if ($inet_family == AF_INET)
            {
                $daddr = ntop($sk->__sk_common.skc_daddr);
                $saddr = ntop($sk->__sk_common.skc_rcv_saddr);
            }
            else
            {
                $daddr = ntop(
                    $sk->__sk_common.skc_v6_daddr.in6_u.u6_addr8);
                $saddr = ntop(
                    $sk->__sk_common.skc_v6_rcv_saddr.in6_u.u6_addr8);
            }
            $lport = $sk->__sk_common.skc_num;
            $dport = $sk->__sk_common.skc_dport;
            // Destination port is big endian, it must be flipped
            $dport = ($dport >> 8) | (($dport << 8) & 0x00FF00);
            $statestr = @tcp_states[$state];
            time("%H:%M:%S ");
            printf("%-8d %14s:%-6d %14s:%-6d %6s\n", pid, $saddr, $lport,
                $daddr, $dport, $statestr);
        }
    }
}


END
{
    clear(@tcp_states);
}

运行 bpftrace ，执行上面脚本：

1

bpftrace trace-poll-timeout.bt

向一个不会回复的 ip 发送连接请求。且指定 10s 超时时长：

1

nc -w 10 1.1.1.146 22

这时，bpftrace 会出现跟踪信息：

$ bpftrace trace-poll-timeout.bt

Attaching 5 probes...
Tracing IP TCP connect latency and SYN retry with stacks. Ctrl-C to end.
21:47:55 0          192.168.1.14:42636       1.1.1.146:22     SYN_SENT
21:47:57 0          192.168.1.14:42636       1.1.1.146:22     SYN_SENT
21:48:01 0          192.168.1.14:42636       1.1.1.146:22     SYN_SENT
21:48:04 TCP_SYN_SENT to CLOSE: 23023  nc 10009ms（尝试连接用时） 4   192.168.1.14:42636（内核自动分配的本地临时端口号）  -->  1.1.1.146:22   
kstack: 
        inet_sk_state_store+1
        __tcp_close+678
        tcp_close+37
        inet_release+69
        __sock_release+63
        sock_close+21
        __fput+156
        ____fput+14
        task_work_run+106
        exit_to_user_mode_loop+343
        exit_to_user_mode_prepare+160
        syscall_exit_to_user_mode+39
        do_syscall_64+105
        entry_SYSCALL_64_after_hwframe+97

ustack: 
        0x7f1b1c6f8117
        0x600000001

^C

就这样，应用对外发起连接 无周期随机发生 且 单例发生 的连接问题，就可以找到证据了。

谢谢阅读！

分享
Mark Zhu
作者
Mark Zhu
An old developer

相关内容