逆向工程与云原生现场分析 Part3 —— eBPF 跟踪 Is

作者: MarkZhu | 来源:发表于2022-03-22 13:08 被阅读0次

image.png

注，原文来自 https://blog.mygraphql.com/zh/posts/low-tec/trace/trace-istio/trace-istio-part3/ 。如你看到的转载图片不清，请回到原文。

承上

在上一篇逆向工程与云原生现场分析 Part2 —— eBPF 跟踪 Istio/Envoy 之启动、监听与线程负载均衡中，介绍了如何用 bpftrace 去跟踪分析 Envoy Listener 的 socket 监听，和监听是如何分配到 worker 线程的。

逆向工程与云原生现场分析系列介绍

开始前先做个预告，逆向工程与云原生现场分析系列（将）包括：

Part 1: eBPF 跟踪 Istio/Envoy 之学步
Part 2: eBPF 跟踪 Istio/Envoy 之启动、监听与线程负载均衡
Part 3: eBPF 跟踪 Istio/Envoy 之 downstream TCP 连接 accept、TLS 握手与 filter_chain 的选择(本文)
Part 4: eBPF 跟踪 Istio/Envoy 之 http filter
Part 5: eBPF 跟踪 Istio/Envoy 之 http router
Part 6: eBPF 跟踪 Istio/Envoy 之 cluster、 connection pool 与 outbound load balance

在系列中，我将演示如何让 bpftrace "读" 懂运行期的由 C++ 11 编写成的 envoy 进程中的对象数据。我花了一个月的时间去补上几个技术债:

LLVM (clang++) 下 C++ 对象的内存结构，包括为 virtual 函数而生的 vtable
gdb 小恶魔的入坑，分析 C++ 对象结构

坐稳，扶好。为免吓跑人，还是老套图，多图少代码，不过有的图有点点复杂。程序员大叔开始讲故事了。🚜

为何

为何要了解 Envoy 的事件驱动实现

事件驱动，多路复用和 10k problem 已经是老套故事了。哪有开口就 Cloud Native，闭口就 Service Mesh 来得抢眼球。但不要以为成熟的东西就无趣，或者没故事。如果你是个 Performance Engineer。只停在这堆大词上，不去深究和实践求证，那么是不会有多少技术上的进步的。深藏于实现的性能问题，也不会被发现。

如，这前的观点是，事件驱动的线程，只有在等待事件时，才会变为非 Runnable 的状态。即在处理事件时，是不会有 block 线程的情况。所以 Evnoy 的 99% 百分位的 Latency，是其它原因。但当我用 BCC 工具去查看这些线程的离开 cpu 的 stack 时，惊讶地发现：
https://github.com/labilezhu/pub-diy/blob/6042b9f89f5aa3bb199ff3ad7227fd1f9399eee7/low-tec/trace/trace-istio/trace-istio-part3/offcputime.log

这也是为何，Envoy 还是要多个 worker 线程的原因之一吧？

为何要了解 TCP 连接建立过程

作为一个业务应用开发者，的确不必要了解。作为一个 DevOps/SRE/Performance Engineer ，不了解是不合格的。以下变数，足以大大影响应用性能：

Client 是长连接，还是短连接。连接建立是高频的吗？建立一个新连接的应用层成本真是那么低吗？
应用的线程和连接是什么关系？如何分派连接到线程？这个关系会影响应用的延迟和吞吐吗？

如果你不清楚这几个问题的答案，那么可能需要了解一下。

为何要了解 TLS 握手过程

可以不夸张地说，没有一家互联网公司不需要做 TLS 会话优化的。特别是对于短连接的接入。TLS 握手的优化空间，绝对比 TCP 握手大。如果我们可以用 trace 等手段拿到握手的延迟统计，就可以为优化指明方向。

为何要了解 filter_chain 的选择逻辑

Istio 控制下的 envoy 配置，是相当复杂的。可以这么说， Envoy 是一个执行 Envoy 配置的引擎，配置是指导 Envoy 代理行为的编程语言。而编程语言最关键的是控制流。filter_chain 就是控制流的 if/else。trace 过 filter_chain 的选择，我们才真实确认了 Envoy 的行为。才可以做相应的配置变更或优化。

TCP 连接建立

现在看看，事件驱动和连接的建立的过程和关系：

image.png

Envoy worker 线程挂起在 epoll_wait() 方法中。线程被移出 kernel 的 runnable queue。线程睡眠。
client 建立连接，server 内核完成3次握手，触发 listen socket 事件。
- 操作系统把 Envoy worker 线程被移入 kernel 的 runnable queue。Envoy worker 线程被唤醒，变成 runnable。操作系统发现可用 cpu 资源，把 runnable 的 envoy worker 线程调度上 cpu。（注意，runnable 和调度上 cpu 不是一次完成的）
Envoy 分析事件列表，按事件列表的 fd 调度到不同的 FilerEventImpl 类的回调函数（实现见：FilerEventImpl::assignEvents）
FilerEventImpl 类的回调函数调用实际的业务回调函数，进行 syscall accept，完成 socket 连接。得到新 socket 的 FD: $new_socket_fd。
业务回调函数把调用 epoll_ctl 把 $new_socket_fd 加到 epoll 监听中。
回到步骤 1 。

关于 listen socket fd

Part2 中，我们看到 socket 监听的情况如下：

$ sudo nsenter -t $POD_PID -n

$ ss -lnp | egrep '15001|15006'

tcp   LISTEN   0   4096   0.0.0.0:15001   0.0.0.0:*    users:(("envoy",pid=2062496,fd=37),("envoy",pid=2062496,fd=38),("envoy",pid=2062496,fd=31))
tcp   LISTEN   0   4096   0.0.0.0:15006   0.0.0.0:*    users:(("envoy",pid=2062496,fd=39),("envoy",pid=2062496,fd=40),("envoy",pid=2062496,fd=32))

可以看到，3 个 fd 都绑定到同一 listen socket 上。1 个 fd 用于主线程，其它 2 个对应自己的 worker 线程。

可以看到 图：Istio-Proxy Listener 逻辑架构举例 - virtualInbound Listener 中 virtualInbound Listener 监听于 15006。

TCP 连接建立步骤

在 ebpf trace 之前，我们先看看代码，了解大概的连接建立过程和相关的实现。

image.png

步骤是：

epoll 收到连接请求，完成3次握手。最好回调到 TcpListenerImpl::onSocketEvent()。
最终 syscall accept() 获得新 socket 的 FD。
调用 ActiveTcpListener::onAccept()
创建新连接专用的 ListenerFilterChain
创建新连接专用的 ActiveTcpSocket，发起 ListenerFilterChain 流程
执行 ListenerFilterChain 流程：
1. 如：TlsInspector::Filter 注册监听新 socket 的事件，以便在后续新 socket 发生事件时，读 socket，抽取出 TLS SNI/ALPN。
2. 当 ListenerFilterChain 中所有的 ListenerFilter 在新的事件和事件周期中完成其所有的数据交换和抽取的任务，本 fd 的控制权交到一环节。
调用核心函数 ActiveTcpListener：：newConnection()
调用 findFilterChain() 基于之前 ListenerFilter 抽取到的数据，和各 network filter chain 配置 的 match 条件，找到最匹配的 network filter chain 配置 。
创建 ServerConnection(ConnectionImpl的子类) 对象
1. 注册 socket 事件回调到 Network::ConnectionImpl::onFileEvent(uint32_t events) 中。即以后的 socket 事件将由这个ServerConnection处理。
用之前找到的 network filter chain 配置 对象，创建 transportSocket。
用之前找到的 network filter chain 配置 对象，创建运行期的 NetworkFilterChain。

跟踪 TCP 连接建立

TL;DR.

照惯例，我们先看 bpftrace 跟踪程序的输出。

1. 执行 BPF 程序：

git clone https://github.com/labilezhu/pub-diy
cd ./pub-diy/low-tec/trace/trace-istio/trace-istio-part3

export SCRIPT_HOME=`pwd`
export bpftrace_image=cndt-bcc-ub

export PID=4283

docker run -it --rm --init  --privileged --name bpftrace -h bpftrace \
    --pid host \
    --net host \
    -e SCRIPT_HOME=$SCRIPT_HOME \
    -e PID=$PID \
    -e ENVOY_PID=$PID \
    -e BT=trace-envoy-accept-flow.bt \
    -v /etc/localtime:/etc/localtime:ro \
    -v /sys:/sys:rw \
    -v /usr/src:/usr/src:rw \
    -v /lib/modules:/lib/modules:ro \
    -v ${SCRIPT_HOME}:${SCRIPT_HOME}:rw \
    $bpftrace_image \
    ${SCRIPT_HOME}/warp-bt.sh $PID

2. 发起测试连接和流量

然后发起测试连接和流量。我们将在另一个有 isto-proxy 的 pod 中（假设叫 downstream-pod），发起对目标 pod（假设叫 fortio-server:8080）的请求。 downstream-pod 的 isto-proxy 会把 http 转为 https，再到达 fortio-server:8080 。

# 需要重启 downstream-pod 的 istio-proxy。因为它与 fortio-server 建立了长连接。而我们需要新连接才能观察到 accept 的过程。
k exec -it -c istio-proxy  downstream-pod  -- bash -c 'kill `pgrep envoy`'

k exec  downstream-pod -- curl -v "http://fortio-server:8080/fortio/"

3. 查看输出跟踪结果

原始的结果在：
https://github.com/labilezhu/pub-diy/blob/main/low-tec/trace/trace-istio/trace-istio-part3/trace-envoy-accept-flow.5.log

以下是我精简和加入注解的结果：

##### TCP socket accept 信息：
OS handshaked TCP:
11:13:55 4283   wrk:worker_0(线程名)   172.21.206.219(对端 ip)                          43926(对端 port) 172.21.206.214                          15006(本地 listen 的 port)    0/4096
sys_exit_accept4 fd=42(新连接的 FD)

        accept4+96
        Envoy::Network::IoSocketHandleImpl::accept(sockaddr*, unsigned int*)+82
        Envoy::Network::TcpListenerImpl::onSocketEvent(short)+216
        std::__1::__function::__func<Envoy::Event::DispatcherImpl::createFileEvent(int, std::__1::function<void (unsigned int)>, Envoy::Event::FileTriggerType, unsigned int)::$_5, std::__1::allocator<Envoy::Event::DispatcherImpl::createFileEvent(int, std::__1::function<void (unsigned int)>, Envoy::Event::FileTriggerType, unsigned int)::$_5>, void (unsigned int)>::operator()(unsigned int&&)+65
        Envoy::Event::FileEventImpl::assignEvents(unsigned int, event_base*)::$_1::__invoke(int, short, void*)+92
        0x7fffffffe000
        event_base_loop+1953
        Envoy::Server::WorkerImpl::threadRoutine(Envoy::Server::GuardDog&, std::__1::function<void ()> const&)+621
        Envoy::Thread::ThreadImplPosix::ThreadImplPosix(std::__1::function<void ()>, absl::optional<Envoy::Thread::Options> const&)::{lambda(void*)#1}::__invoke(void*)+19
        start_thread+217
 
##### 构建 TlsInspector 
***** elapsed=-1017877702: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZNSt3__110__function6__funcIZN5Envoy10Extensions15ListenerFilters12TlsInspector25TlsInspectorConfigFactory36createListenerFilterFactoryFromProtoERKN6google8protobuf7MessageERKNS_10shared_ptrINS2_7Network21ListenerFilterMatcherEEERNS2_6Server13Configuration22ListenerFactoryContextEEUlRNSD_21ListenerFilterManagerEE_NS_9allocatorISO_EEFvSN_EEclESN_

...

##### 构建 TlsInspector 
***** elapsed=-1017866364: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZN5Envoy10Extensions15ListenerFilters12TlsInspector6FilterC1ENSt3__110shared_ptrINS2_6ConfigEEE

...

##### TlsInspector::Filter::onAccept()
***** elapsed=-1017822616: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZN5Envoy10Extensions15ListenerFilters12TlsInspector6Filter8onAcceptERNS_7Network23ListenerFilterCallbacksE

##### TlsInspector::Filter::onRead()
***** elapsed=-1017814524: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZN5Envoy10Extensions15ListenerFilters12TlsInspector6Filter6onReadEv

##### TlsInspector::Filter::parseClientHello()
***** elapsed=-1013081879: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZN5Envoy10Extensions15ListenerFilters12TlsInspector6Filter16parseClientHelloEPKvm

...

##### TlsInspector::Filter::onALPN()，从 TLS 数据中获取到 ALPN
***** elapsed=-1013042582: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZN5Envoy10Extensions15ListenerFilters12TlsInspector6Filter6onALPNEPKhj

***** elapsed=-1013030000: tid=4568,comm=wrk:worker_0: ConnectionSocketImpl::setRequestedApplicationProtocols

##### TlsInspector::Filter::onServername()，从 TLS 数据中获取到 SNI
***** elapsed=-1013010367: tid=4568,comm=wrk:worker_0: TlsInspector*, probe=uprobe:/proc/4283/root/usr/local/bin/envoy:_ZN5Envoy10Extensions15ListenerFilters12TlsInspector6Filter12onServernameEN4absl11string_viewE

...

##### 利用 ListnerFitler(包括 original_dst Filter、TlsInspector抽取到的数据)。最终匹配到的 Network Fitler Chain，名字为 0.0.0.0_8080
comm:wrk:worker_0,tid:4568: Got setFilterChainName=0.0.0.0_8080, lenght=12

        Envoy::StreamInfo::StreamInfoImpl::setFilterChainName(absl::string_view)+0
        Envoy::Server::ActiveTcpSocket::newConnection()+377
        Envoy::Server::ActiveTcpSocket::continueFilterChain(bool)+107

##### 注册 新 FD 相关的 epoll 事件回调
***** elapsed=-1012929361: tid=4568,comm=wrk:worker_0: sys_enter_epoll_ctl, epfd=10, op=1, fd=42, epoll_event*=0x7faddbda2c60

        epoll_ctl+14
        epoll_nochangelist_add+54
        evmap_io_add_+421
        event_add_nolock_+603
        event_add+54
        Envoy::Event::FileEventImpl::FileEventImpl(Envoy::Event::DispatcherImpl&, int, std::__1::function<void (unsigned int)>, Envoy::Event::FileTriggerType, unsigned int)+362
        Envoy::Event::DispatcherImpl::createFileEvent(int, std::__1::function<void (unsigned int)>, Envoy::Event::FileTriggerType, unsigned int)+284
        Envoy::Network::IoSocketHandleImpl::initializeFileEvent(Envoy::Event::Dispatcher&, std::__1::function<void (unsigned int)>, Envoy::Event::FileTriggerType, unsigned int)+126
        Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)+1026
        Envoy::Network::ServerConnectionImpl::ServerConnectionImpl(Envoy::Event::Dispatcher&, std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&, bool)+107
        Envoy::Event::DispatcherImpl::createServerConnection(std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::Network::TransportSocket, std::__1::default_delete<Envoy::Network::TransportSocket> >&&, Envoy::StreamInfo::StreamInfo&)+70
        Envoy::Server::ActiveTcpListener::newConnection(std::__1::unique_ptr<Envoy::Network::ConnectionSocket, std::__1::default_delete<Envoy::Network::ConnectionSocket> >&&, std::__1::unique_ptr<Envoy::StreamInfo::StreamInfo, std::__1::default_delete<Envoy::StreamInfo::StreamInfo> >)+307

##### 配置新 socket 的 sockopt
comm:wrk:worker_0    : setsockopt: level=6, fd=42, optname=1, optval=1, optlen=4. 

##### 本轮新 FD 事件处理完成
***** elapsed=-1012820877: tid=4568,comm=wrk:worker_0: END:EventFired

##### 本轮 epoll 唤醒的所有事件处理完毕
******* WAKE-ROUND:END Summary *******
***** elapsed=-1012807848: tid=4568,comm=wrk:worker_0: sys_enter_epoll_wait, runableDuaration=5158482, tid2epollNrFdReady=1
*** last_epoll_wait_args: epfd=10, events=2052059648, maxevents=32, timeout=100 
***************************




##### FD 相关的 epoll 事件回调
***** elapsed=-1012792293: tid=4568,comm=wrk:worker_0: BEGIN:EventFired:FileEventImpl::assignEvents()::Lambda1()
FileEventImpl*=0x56367a951500, fd=42, events=0x26

##### FD 相关的 epoll 事件处理完毕
***** elapsed=-1011476865: tid=4568,comm=wrk:worker_0: END:EventFired

##### 本轮 epoll 唤醒的所有事件处理完毕
******* WAKE-ROUND:END Summary *******
***** elapsed=-1011446745: tid=4568,comm=wrk:worker_0: sys_enter_epoll_wait, runableDuaration=1346699, tid2epollNrFdReady=1
*** last_epoll_wait_args: epfd=10, events=2052059648, maxevents=32, timeout=16 
***************************




##### FD 相关的 epoll 事件回调
***** elapsed=-976027033: tid=4568,comm=wrk:worker_0: BEGIN:EventFired:FileEventImpl::assignEvents()::Lambda1()
FileEventImpl*=0x56367a951500, fd=42, events=0x26

##### 删除 FD 相关的 epoll 事件回调
***** elapsed=-974127057: tid=4568,comm=wrk:worker_0: sys_enter_epoll_ctl, epfd=10, op=2, fd=42, epoll_event*=0x7faddbda29e0
##### 注册 FD 相关的 epoll 事件回调
***** elapsed=-974087535: tid=4568,comm=wrk:worker_0: sys_enter_epoll_ctl, epfd=10, op=1, fd=42, epoll_event*=0x7faddbda29d0

        epoll_ctl+14
        epoll_nochangelist_add+54
        evmap_io_add_+421
        event_add_nolock_+603
        event_add+54
        Envoy::Network::ConnectionImpl::readDisable(bool)+1077
        Envoy::Http::Http1::ServerConnectionImpl::onMessageCompleteBase()+86
        Envoy::Http::Http1::ConnectionImpl::onMessageComplete()+637
        Envoy::Http::Http1::LegacyHttpParserImpl::Impl::Impl(http_parser_type, void*)::{lambda(http_parser*)#3}::__invoke(http_parser*)+31
        http_parser_execute+7959
        Envoy::Http::Http1::LegacyHttpParserImpl::execute(char const*, int)+31
        Envoy::Http::Http1::ConnectionImpl::dispatchSlice(char const*, unsigned long)+52

##### FD 相关的 epoll 事件处理完毕
***** elapsed=-973377160: tid=4568,comm=wrk:worker_0: END:EventFired

##### 本轮 epoll 唤醒的所有事件处理完毕
******* WAKE-ROUND:END Summary *******
***** elapsed=-973322877: tid=4568,comm=wrk:worker_0: sys_enter_epoll_wait, runableDuaration=2738098, tid2epollNrFdReady=1
*** last_epoll_wait_args: epfd=10, events=2052059648, maxevents=32, timeout=100 
***************************





***** elapsed=-973302083: tid=4568,comm=wrk:worker_0: BEGIN:EventFired:FileEventImpl::assignEvents()::Lambda1()
FileEventImpl*=0x56367a951500, fd=42, events=0x24


***** elapsed=-973210034: tid=4568,comm=wrk:worker_0: END:EventFired

******* WAKE-ROUND:END Summary *******
***** elapsed=-970967200: tid=4568,comm=wrk:worker_0: sys_enter_epoll_wait, runableDuaration=2329760, tid2epollNrFdReady=3
*** last_epoll_wait_args: epfd=10, events=2052059648, maxevents=32, timeout=88 
***************************




***** elapsed=-970216003: tid=4568,comm=wrk:worker_0: sys_enter_epoll_ctl, epfd=10, op=2, fd=42, epoll_event*=0x7faddbda24b0
***** elapsed=-970198884: tid=4568,comm=wrk:worker_0: sys_enter_epoll_ctl, epfd=10, op=1, fd=42, epoll_event*=0x7faddbda24a0

        epoll_ctl+14
        epoll_nochangelist_add+54
        evmap_io_add_+421
        event_add_nolock_+603
        event_add+54
        Envoy::Network::ConnectionImpl::readDisable(bool)+938
        Envoy::Http::Http1::StreamEncoderImpl::~StreamEncoderImpl()+112
        non-virtual thunk to Envoy::Http::Http1::ServerConnectionImpl::onEncodeComplete()+54
        Envoy::Http::Http1::StreamEncoderImpl::endEncode()+166
        Envoy::Http::Http1::StreamEncoderImpl::encodeData(Envoy::Buffer::Instance&, bool)+340
        Envoy::Http::ConnectionManagerImpl::ActiveStream::encodeData(Envoy::Buffer::Instance&, bool)+679
        Envoy::Http::FilterManager::encodeData(Envoy::Http::ActiveStreamEncoderFilter*, Envoy::Buffer::Instance&, bool, Envoy::Http::FilterManager::FilterIterationStartState)+2138


***** elapsed=-969958893: tid=4568,comm=wrk:worker_0: BEGIN:EventFired:FileEventImpl::assignEvents()::Lambda1()
FileEventImpl*=0x56367a951500, fd=42, events=0x24


***** elapsed=-969845835: tid=4568,comm=wrk:worker_0: END:EventFired

******* WAKE-ROUND:END Summary *******
***** elapsed=-969831672: tid=4568,comm=wrk:worker_0: sys_enter_epoll_wait, runableDuaration=126155, tid2epollNrFdReady=1
*** last_epoll_wait_args: epfd=10, events=2052059648, maxevents=32, timeout=84 
***************************

回头看看 bpftrace 跟踪程序源代码：
https://github.com/labilezhu/pub-diy/blob/main/low-tec/trace/trace-istio/trace-istio-part3/trace-envoy-accept-flow.bt

#!usr/bin/bpftrace
/*
IMPORT-ENV: $ENVOY_PID
args: $1=ENVOY_PID
*/

/*
1. BPF Map 说明:

1.1. range tid map
- @watchedWakeRound[tid]=tid
       - sys_exit_accept4
- @fdFired[tid]=1;
       - uprobe: *FileEventImpl*assignEvents*
       - uretprobe: *FileEventImpl*assignEvents*

1.2. fd map
- @fd2sockpair[$fd]=@sockpair[tid]
       - sys_exit_accept4
       - sys_enter_close
- @fd2sockopt[$fd, $level, $optname, $optval_int] = 1
       - sys_enter_setsockopt

1.3. temp tid map
- @sockpair[tid]=($sk->__sk_common.skc_daddr, $dport, $sk->__sk_common.skc_rcv_saddr, $lport);
- @sockpair_exist[tid]=1

*/

#include <linux/in.h>
#include <linux/in6.h>
#include <linux/socket.h>
#include <net/sock.h>

BEGIN
{
    printf("Tracing Envoy. Hit Ctrl-C to end.\n");
       printf("#define EPOLL_CTL_ADD 1\n #define EPOLL_CTL_DEL 2\n #define EPOLL_CTL_MOD 3\n")
}

/*
获取 accept 连接时的本地和对端地址。并标记本轮 wakeup 需要监控
 */
kretprobe:inet_csk_accept
/pid==$1 /
{
    $sk = (struct sock *)retval;
    $inet_family = $sk->__sk_common.skc_family;

    if ($inet_family == AF_INET || $inet_family == AF_INET6) {
        // initialize variable type:
        $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 {
            printf("not support IPv6.\n");
            return;
        }
        
        $lport = $sk->__sk_common.skc_num;

              // printf("accept(), port=%d\n", $lport);

              //only watch listen port 15006
        if( 15006 != $lport ) { 
            return;
        }

        $dport = $sk->__sk_common.skc_dport;
        $qlen  = $sk->sk_ack_backlog;
        $qmax  = $sk->sk_max_ack_backlog;

        // Destination port is big endian, it must be flipped
        $dport = ($dport >> 8) | (($dport << 8) & 0x00FF00);

              printf("OS handshaked TCP:\n");
        time("%H:%M:%S ");
        printf("%-6d %-14s ", pid, comm);
        printf("%-39s %-5d %-39s %-5d ", $daddr, $dport, $saddr,
            $lport);
        printf("%d/%d\n", $qlen, $qmax);

        @sockpair[tid]=($sk->__sk_common.skc_daddr, $dport, $sk->__sk_common.skc_rcv_saddr, $lport);
        @sockpair_exist[tid]=1;

              @watchedWakeRound[tid]=tid;
    }
}

/**
 * 获取新连接的 FD 。并标记本轮 libevent 回调需要监控
 */
tracepoint:syscalls:sys_exit_accept4
/pid==$1 && @sockpair_exist[tid] /
{
    $fd = args->ret;
    if( $fd < 0 ) {
        return;
    }
    printf("sys_exit_accept4 fd=%d\n", $fd);
    @fd2sockpair[$fd]=@sockpair[tid];

       @fdFired[tid]=1;

    delete(@sockpair[tid]);
    delete(@sockpair_exist[tid]);
       printf("%s \n", ustack());
}

/**
 * 记录 FD 的 sockopt
 */
tracepoint:syscalls:sys_enter_setsockopt
/pid==$1/
{
       // socket opts: https://elixir.bootlin.com/linux/v5.16.3/source/include/uapi/linux/tcp.h#L92     
       $level = args->level;
       $fd = args->fd;

       if( @fd2sockpair[$fd].0 ) {
              $optname = args->optname;
              $optval = args->optval;
              $optval_int = *$optval;
              $optlen = args->optlen;
              // printf("\n########## setsockopt() ##########\n");
              printf("comm:%-16s: setsockopt: level=%d, fd=%d, optname=%d, optval=%d, optlen=%d. \n", comm, $level, $fd, $optname, $optval_int, $optlen);
              @fd2sockopt[$fd, $level, $optname, $optval_int] = 1;
       }
}

/*
记录 epoll 监听的 FD

cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_epoll_ctl/format
 */
tracepoint:syscalls:sys_enter_epoll_ctl
/pid==$1/
{
       $fd=args->fd;
       if( @fd2sockpair[$fd].0 ) {
              printf("***** elapsed=%d: tid=%d,comm=%s: sys_enter_epoll_ctl, epfd=%d, op=%d, fd=%d, epoll_event*=%p\n", 
                     elapsed, tid, comm, args->epfd, args->op, $fd, args->event);

              if( args->op == 1 ) { //add watch epoll event
                     printf("%s\n", ustack(12));
              }
              
       }
}

/*
结束本轮的 wakeRound/runnableRound，并等待下一轮
cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_epoll_wait/format
 */
tracepoint:syscalls:sys_enter_epoll_wait
/pid==$1/
{

       if( @watchedWakeRound[tid] ) {
              $runnableStartTime=@tid2Waketime[tid];
              if( $runnableStartTime ) {
                     $runableDuaration = elapsed - $runnableStartTime;
                     printf("\n******* WAKE-ROUND:END Summary *******\n");
                     printf("***** elapsed=%d: tid=%d,comm=%s: sys_enter_epoll_wait, runableDuaration=%d, tid2epollNrFdReady=%d\n", 
                            elapsed, tid, comm, $runableDuaration, @tid2epollNrFdReady[tid]);
                     $tid_last_epoll_wait_args = @last_epoll_wait_args[tid];
                     if( $tid_last_epoll_wait_args.0  ) {
                            printf("*** last_epoll_wait_args: epfd=%d, events=%d, maxevents=%d, timeout=%d \n", 
                                   $tid_last_epoll_wait_args.0, $tid_last_epoll_wait_args.1, $tid_last_epoll_wait_args.2, $tid_last_epoll_wait_args.3);
                     }
                     printf("***************************\n\n");
              }
       }

       delete(@tid2Waketime[tid]);
       delete(@watchedWakeRound[tid]);
       delete(@tid2epollNrFdReady[tid]);

       //read in next sys_enter_epoll_wait
       @last_epoll_wait_args[tid]=(args->epfd, args->events, args->maxevents, args->timeout);
}

/*
开始本轮 wakeRound/runnableRound
cat /sys/kernel/debug/tracing/events/syscalls/sys_exit_epoll_wait/format
 */
tracepoint:syscalls:sys_exit_epoll_wait
/pid==$1/
{
       // printf("\n***** elapsed=%d: tid=%d,comm=%s: sys_enter_epoll_wait\n", elapsed, tid, comm);

       // printf("epfd: 0x%08lx, events: 0x%08lx, maxevents: 0x%08lx, timeout: 0x%08lx \n", 
       //        ((args->epfd)), ((args->events)), ((args->maxevents)), ((args->timeout)) );

       @tid2Waketime[tid]=elapsed;
       @tid2epollNrFdReady[tid]=args->ret;
}

/*
记录本轮 epoll 事件触发的 FD 级回调开始

Envoy::Event::FileEventImpl::assignEvents(unsigned int, event_base*)::$_1::__invoke(int fd, short events, void* fileEventImplThis)  !!!NOT!!: FileEventImpl::assignEvents()
C++11 Lambda expressions:
event_assign( &raw_event_, base, fd_, xxx, [](evutil_socket_t, short what, void* arg)-> void {}, this );

event_assign(): https://libevent.org/doc/event_8h.html#a3e49a8172e00ae82959dfe64684eda11
       event_assign (   struct event *  ev,
              struct event_base *   base,
              evutil_socket_t   fd,
              short     events,
              event_callback_fn     callback,
              void *    callback_arg 
       )    

       https://libevent.org/doc/event_8h.html#aed2307f3d9b38e07cc10c2607322d758
       typedef void(* event_callback_fn) (evutil_socket_t, short, void *)
              fd    An fd or signal
              events    One or more EV_* flags
              arg   A user-supplied argument.
*/
uprobe:/proc/${ENVOY_PID}/root/usr/local/bin/envoy:*FileEventImpl*assignEvents*
/pid == $1/ 
{
       $fd = arg0;
       if( @fd2sockpair[$fd].0 ) {
              printf("\n***** elapsed=%d: tid=%d,comm=%s: BEGIN:EventFired:FileEventImpl::assignEvents()::Lambda1()\n", elapsed, tid, comm);
              printf("FileEventImpl*=%p, fd=%d, events=0x%x\n",arg2, $fd, arg1);
              printf("%s\n", kstack);
              @fdFired[tid]=1;
              @watchedWakeRound[tid]=tid;
       }
}

/*
记录本轮 epoll 事件触发的 FD 级回调结束
*/
uretprobe:/proc/${ENVOY_PID}/root/usr/local/bin/envoy:*FileEventImpl*assignEvents*
/pid == $1 && @fdFired[tid]/ 
{
       printf("\n***** elapsed=%d: tid=%d,comm=%s: END:EventFired\n", elapsed, tid, comm);
       delete(@fdFired[tid]);
}

/*
打印 TlsInspector 的所有函数调用
*/
uprobe:/proc/${ENVOY_PID}/root/usr/local/bin/envoy:*TlsInspector*
/pid == $1 && @fdFired[tid]/ 
{
       printf("\n***** elapsed=%d: tid=%d,comm=%s: TlsInspector*, probe=%s\n", elapsed, tid, comm, probe);
}

/*
打印连接确认协后的函数调用
*/
uprobe:/proc/${ENVOY_PID}/root/usr/local/bin/envoy:*ConnectionSocketImpl*setRequestedApplicationProtocols*
/pid == $1 && @fdFired[tid]/ 
{
       printf("\n***** elapsed=%d: tid=%d,comm=%s: ConnectionSocketImpl::setRequestedApplicationProtocols\n", elapsed, tid, comm);
       // printf("%s", ustack);
}

/*
打印匹配到的 Network Fitler Chain 名字
void setFilterChainName(absl::string_view filter_chain_name)
*/
uprobe:/proc/${ENVOY_PID}/root/usr/local/bin/envoy:_ZN5Envoy10StreamInfo14StreamInfoImpl18setFilterChainNameEN4absl11string_viewE 
/pid == $1 && @fdFired[tid]/ 
{ 
/**
[Assembly 2: Calling convention](https://cs61.seas.harvard.edu/site/2018/Asm2/)

1. A structure argument that fits in a single machine word (64 bits/8 bytes) is passed in a single register.
   
    Example: `struct small { char a1, a2; }`

2. A structure that fits in two to four machine words (16–32 bytes) is passed in sequential registers, as if it were multiple arguments.
   
    Example: `struct medium { long a1, a2; }`
*/
    $filterName = str(reg("si"));
    $filterNameLength = reg("dx");

    // printf("tid:%d: Got setFilterChainName=%s, lenght=%d\n %s \n", tid, $filterName, $filterNameLength, ustack ); 
    printf("comm:%s,tid:%d: Got setFilterChainName=%s, lenght=%d\n", comm, tid, $filterName, $filterNameLength ); 

    if( $filterNameLength > 0 ) {
        printf("%s\n", ustack(3));
    }
}

/*
清理关闭的 FD 相关的 Map
cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_close/format
*/
tracepoint:syscalls:sys_enter_close
/pid==$1/
{
    $fd = args->fd;
    if( $fd < 0 ) {
        return;
    }
       if( @fd2sockpair[$fd].0 ) {
              printf("sys_enter_close fd=%d\n", $fd);
       }
    delete(@fd2sockpair[$fd]);
}

END
{
       clear(@last_epoll_wait_args);
       clear(@tid2Waketime);
       clear(@tid2epollNrFdReady);
}

结尾

或者上面有很多未尽道明之处，请见谅。一个是时间实在有限，一个是我觉得能深入一行一行读完全文的同学，都是老司机了，多说无益。谢谢观看。

image.png

附录

术语

fd：是 file descriptor 的缩写，中文叫文件描述符（Windows 编程过来的同学叫：句柄 handle）。一个 socket 可以对应于多个 fd。不同的线程可以在不同的 fd 上 listen 同一个 socket。操作系统负责新连接的负载均衡（尽管做得不太好）。

逆向工程与云原生现场分析 Part3 —— eBPF 跟踪 Is

承上

逆向工程与云原生现场分析系列介绍

为何

为何要了解 Envoy 的事件驱动实现

为何要了解 TCP 连接建立过程

为何要了解 TLS 握手过程

为何要了解 filter_chain 的选择逻辑

相关的架构

逻辑架构

代码架构

事件驱动与线程模型

TCP 连接建立

关于 listen socket fd

TCP 连接建立步骤

跟踪 TCP 连接建立

1. 执行 BPF 程序：

2. 发起测试连接和流量

3. 查看输出跟踪结果

结尾

附录

术语

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

逆向工程与云原生现场分析 Part3 —— eBPF 跟踪 Is

承上

逆向工程与云原生现场分析 系列介绍

为何

为何要了解 Envoy 的事件驱动实现

为何要了解 TCP 连接建立过程

为何要了解 TLS 握手过程

为何要了解 filter_chain 的选择逻辑

相关的架构

逻辑架构

代码架构

事件驱动与线程模型

TCP 连接建立

关于 listen socket fd

TCP 连接建立步骤

跟踪 TCP 连接建立

1. 执行 BPF 程序：

2. 发起测试连接和流量

3. 查看输出跟踪结果

结尾

附录

术语

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

逆向工程与云原生现场分析系列介绍