一个使用 tracepoint 追踪 execve 系统调用时无法正确获取系统调用参数的场景

背景¶

前段时间有网友在 slack 上的 ebpf 频道中咨询一个他遇到的问题：

在编写使用 tracepoint/syscalls/sys_enter_execve 追踪 execve 系统调用的 ebpf 程序时，遇到了记录的部分事件中存在使用 bpf_probe_read_user_str 读取 execve 的 filename 参数失败的现象，错误码为 -14/EFAULT。尤其是在执行 tmux 命令的时候，必定会伴随一个读取失败的事件:

ret = bpf_probe_read_user_str(event->args, ARGSIZE, (const char*)ctx->args[0]);
if (ret < 0) {
        bpf_printk("comm=%s XXX cannot read file name", tgid, pid, event->comm);
        return 0;
}

utempter-4031732 [027] d...1 3878624.643948: bpf_trace_printk: comm=tmux: server XXX cannot read file name
   <...>-4035723 [077] d...1 3878668.047954: bpf_trace_printk: comm=tmux: server XXX cannot read file name

本文将探讨一下该问题出现的原因以及针对该场景的一种解决方法。

复现问题的代码¶

因为问题中提到只要执行 tmux 命令就必定会复现该问题，并且我们在 bpf_printk 的输出中看到对应事件的进程名称为 utempter ，因此，我们可以基于这两点信息来尝试编写一个简单的复现问题的程序。

通过在网络上查找 tmux 与 utempter 的关联关系，以及阅读了相关的 tmux 源代码后，我了解到了如下信息：

tmux 会调用 utempter.h 提供的 utempter_add_record 函数创建所需的伪终端（pseudo-terminal）:
```
xasprintf(&cp, "tmux(%lu).%%%u", (long)getpid(), new_wp->id);
utempter_add_record(new_wp->fd, cp);
```

utempter_add_record 函数中会首先使用传入的参数构造一个 args 然后调用 execute_helper 函数:

#define UTEMPTER_DEFAULT_PATHNAME     LIBEXECDIR "/utempter/utempter"
static const char *utempter_pathname;

int utempter_add_record(int master_fd, const char *hostname)
  {
      const char *const args[] = {
          utempter_pathname ? : UTEMPTER_DEFAULT_PATHNAME,
          "add",
          hostname,
          0
      };
      int status = execute_helper(master_fd, args);
      // ...
  }

execute_helper 函数中最终会使用传入的 args 调用 fork() 和 execv() 函数启动一个新的进程（源代码）:

static int execute_helper(int master_fd, const char *const argv[])
{
    // ...
    child = fork();
    if (!child) {
        do_child(master_fd, argv[0], (char *const *) argv);
    } else if (child < 0) {
    // ...
}
static void __attribute__((__noreturn__))
do_child(int master_fd, const char *path, char *const *argv)
{
    // ...
    execv(path, argv);
    print_dbg("execv: %s", strerror(errno));
    //...
}

根据上面这些信息，我们可以编写如下这个可复现该问题的程序 reproduce.c:

#define PATHNAME "/usr/bin/echo"

int main(int argc, char **argv) {
    const char *hostname = argv[0];
    const char *const args[] = {
        PATHNAME,
        "add",
        hostname,
        0
    };
    if (!fork()) {
        execv(args[0], (char *const *) args);
    }
}

下面测试一下这个程序的效果:

使用 gcc 编译:
```
gcc -o reproduce reproduce.c
```

在另一个终端使用 bpftrace 追踪 tracepoint/syscalls/sys_enter_execve 事件:

sudo bpftrace -e 'tracepoint:syscalls:sys_enter_execve{printf("%s[%d]: %s\n", comm, pid, str(args->filename));}'

运行示例程序:
```
./reproduce
```

此时，运行 bpftrace 的终端将输出类似下面这样的结果:

bash[34882]: ./reproduce
reproduce[34883]:

在上面结果中，我们没有获取到 reproduce 进程执行 execve() 系统调用时使用的 filename 参数的值。由此可见，我们的这个程序复现了最初的问题。

原因¶

经 @ssfdust 提醒，bpftrace 社区之前已经有人提过类似的问题： #2523 。在这个 issue 中 @fbs 给出的解释是：

Like I said earlier, the data you're using isn't in memory yet. These static strings are compiled in and are not actually faulted into memory until they're accessed. The access won't happen until its read, which is after your bpftrace probe ran. BPF won't pull the data in so you get an EFAULT/-14.

By printing the values or just a random print of a constant string you pull the small amount of data into memory (as it goes by page, not by var) and then it works

即：

示例程序中，执行 execve() 时传入的 argv[0] 指向的文件名称字符串是一个静态字符串（这些静态字符串在程序被编译后存储在 ELF（Executable and Linkable Format）文件的 .rodata section），这些字符串只会在程序真正去访问他们的时候（访问 .rodata section 存储的数据时）才会被加载到内存中。
由1可知，示例程序中 argv[0] 指向的静态字符串只会在执行 execve() 系统调用的时候被读取到内存中，但是我们的 ebpf 程序其实是在执行 execve() 系统调用之前被执行的，因此 ebpf 程序里使用 bpf_probe_read_user_str 读取 argv[0] 会失败并返回 EFAULT/-14 。
通过 printf 等方式主动将字符串加载到内存中可以让该问题消失。

来自 @jschwinger233 的总结：

bpf_probe_read_user 只能读到已经载入内存 (page-faulted into memory) 的数据，而上面代码直到 execve(2) 之时都还未读过 .rodata，未曾触发 page fault。这可以用 tracepoint:exceptions:page_fault* 来验证。

验证¶

增加 printf¶

由上面可知，其实我们只需要修改程序在执行 execve() 之前主动将 .rodata 中的数据加载到内存中即可避免该问题，比如使用 printf 函数。

既可以使用 printf 函数打印 argv[0] ，也可以直接打印一个静态字符串:

if (!fork()) {
    printf("test\n");
    // or
    // printf("argv[0]: %s\n", args[0]);
    execv(args[0], (char *const *) args);
}

经验证，修改后的程序 reproduce_printf1.c 确实可以让 ebpf 程序正确读取到 filename 的值。

不使用静态字符串¶

既然是因为 argv[0] 是静态字符串导致的问题，那么可以尝试将 argv[0] 改为使用非静态字符串，看看问题是否还存在。修改的内容如下:

const char *const args[] = {
    argv[1],
    "add",
    hostname,
    0
};

经验证，修改后的程序 reproduce_non_static.c 也可以让 ebpf 程序正确读取到 filename 的值。

不知道大家有没有注意到，我们的复现问题的程序里 argv[2] 的值其实是一个非静态字符串，所以也可以通过在 ebpf 程序中读取这个数据的内容来验证，预期是不做任何修改就可以读取到 argv[2] 这个非静态字符串的内容：

执行新的 bpftrace 命令:

sudo bpftrace -e 'tracepoint:syscalls:sys_enter_execve{
    printf("%s[%d]: filename: %s, argv[1]: %s, argv[2]: %s\n", comm, pid, str(args->filename), str(args->argv[1]), str(args->argv[2]));
}'

执行 ./reproduce

bpftrace 命令的输出示例如下:

bash[36523]: filename: ./reproduce, argv[1]: , argv[2]:
reproduce[36524]: filename: , argv[1]: , argv[2]: ./reproduce

page fault¶

在现代 Linux 系统中，当我们运行二进制可执行文件的时候，程序加载器（ELF executable loader）会根据 ELF 文件中定义的信息使用 mmap 进行懒加载（lazy loading），延迟加载一些数据。当程序真正去读取这些数据的时候，如果被读取的数据还没有被加载到内存里，就会触发 page fault。

ELF 文件的 .rodata section 中存储的数据恰好就是会被延迟加载的数据。

.rodata¶

ELF 文件中的 .rodata section 存储了一些只读数据，比如静态字符串。我们首先来看一下编译后的示例程序二进制 ELF 文件中的 .rodata section 的数据。

可以使用 objdump 命令进行查看:

$ objdump -s -j .rodata ./reproduce

./reproduce:     file format elf64-x86-64

Contents of section .rodata:
2000 01000200 2f757372 2f62696e 2f656368  ..../usr/bin/ech
2010 6f006164 6400                        o.add.

也可以使用 python 社区的 pwntools 库进行读取:

>>> from pwn import ELF
>>> elf = ELF('reproduce')
>>> elf.section('.rodata')
b'\x01\x00\x02\x00/usr/bin/echo\x00add\x00'

从上面的输出中可以看到其中包含了源码中使用的两个静态字符串。

观测 page fault¶

在 Linux 系统中，当内核执行 execve() 系统调用时，会调用内核函数 strncpy_from_user （ execve() -> getname() -> getname_flags(),strncpy_from_user() ）将 argv 中包含的字符串数据从用户态复制到内核态，这个过程涉及读取用户态数据的操作。如果被读取的用户态数据还未被加载到内存中，就会触发 page fault。

我们可以通过观测 exceptions/page_fault_kernel 和 exceptions/page_fault_user 感知到这个事件:

为了方便验证，我们需要先修改一下示例代码，在执行 execv() 函数前增加一行 sleep(15) ，避免程序太快结束（reproduce_sleep.c ）
```
if (!fork()) {
     sleep(15);
     execv(args[0], (char *const *) args);
}
```

在一个终端中运行下面这个 bpftrace 脚本，观测 page fault:

cat <<EOF | sudo bpftrace -
tracepoint:exceptions:page_fault_kernel /comm == "reproduce_sleep"/ {
    printf("[%s] page_fault_kernel: %s[%d] addr=%llx ip=%llx err=%lld\n",
            strftime("%M:%S", nsecs), comm, pid, args->address, args->ip, args->error_code);
}

tracepoint:exceptions:page_fault_user /comm == "reproduce_sleep"/ {
    printf("[%s] page_fault_user:   %s[%d] addr=%llx ip=%llx err=%lld\n",
            strftime("%M:%S", nsecs), comm, pid, args->address, args->ip, args->error_code);
}
EOF

然后在另一个终端中运行 ./reproduce_sleep

在第3个终端中查看运行中的 reproduce_sleep 进程的内存映射关系（memory mapping）:

$ sudo cat /proc/41291/maps | grep reproduce_sleep
55b4d9e31000-55b4d9e32000 r--p 00000000 08:01 1634479                    /XXX/reproduce_sleep
55b4d9e32000-55b4d9e33000 r-xp 00001000 08:01 1634479                    /XXX/reproduce_sleep
55b4d9e33000-55b4d9e34000 r--p 00002000 08:01 1634479                    /XXX/reproduce_sleep
55b4d9e34000-55b4d9e35000 r--p 00002000 08:01 1634479                    /XXX/reproduce_sleep
55b4d9e35000-55b4d9e36000 rw-p 00003000 08:01 1634479                    /XXX/reproduce_sleep

由上面可知，该进程的内存映射起始地址是 55b4d9e31000 ，即 0x55b4d9e31000

待示例程序运行结束后，bpftrace 命令的输出中的最后两条数据将类似下面这样:
```
[47:40] page_fault_user:   reproduce_sleep[41290] addr=7f669db86a50 ip=7f669d9f8940 err=7
[47:55] page_fault_kernel: reproduce_sleep[41291] addr=55b4d9e33004 ip=ffffffff8e092a40 err=0
```
这两个输出间隔了 15 秒，由此可以确定最后那个 page fault 事件是执行 execv() 函数的时候触发的。下面来通过事件中的 addr 结果定位对应的数据。
上面最后那条 page_fault_kernel 事件输出的 addr 的值是 55b4d9e33004 ，即触发这个 page fault 事件的虚拟内存地址是 0x55b4d9e33004 。

基于 @jschwinger233 分享的秘籍： real_addr = start_addr + (elf_address - section.Address + section.Offset) 可知:

0x55b4d9e33004 = 0x55b4d9e31000 + (elf_address - section.Address + section.Offset)
(elf_address - section.Address + section.Offset) = 0x55b4d9e33004 - 0x55b4d9e31000 = 8196 = 0x2004

使用 readelf 命令读取二进制文件 reproduce_sleep 中 ELF .rodata section 的虚拟地址、偏移量以及数据大小:
```
$ readelf -S -W reproduce_sleep  | egrep '.rodata|Address'
  [Nr] Name              Type            Address          Off    Size   ES Flg Lk Inf Al
  [18] .rodata           PROGBITS        0000000000002000 002000 000016 00   A  0   0  4
```
由上面的输出可知，该 ELF 文件中 .rodata section 的虚拟地址是 0000000000002000 即 0x2000 ，偏移量是 002000 即 0x2000 ，数据大小是 0x16 ，即地址范围是 0x2000-0x2016 。

通过 7 和 8 可知，执行 execv() 函数时触发的 page fault 事件的虚拟内存地址 0x55b4d9e33004 对应的 ELF 地址是 0x2004

0x55b4d9e33004 = 0x55b4d9e31000 + (elf_address - section.Address + section.Offset)
(elf_address - section.Address + section.Offset) = 0x55b4d9e33004 - 0x55b4d9e31000 = 8196 = 0x2004
(elf_address - 0x2000 + 0x2000) = 0x2004
elf_address = 0x2004

这个地址在 ELF 文件的 .rodata 地址范围（ 0x2000-0x2016 ）内，对应的是 argv[0] 中使用的静态字符串 /usr/bin/echo:

$ objdump -s -j .rodata ./reproduce_sleep

./reproduce_sleep:     file format elf64-x86-64

Contents of section .rodata:
 2000 01000200 2f757372 2f62696e 2f656368  ..../usr/bin/ech
 2010 6f006164 6400                        o.add.

>>> elf = ELF('reproduce_sleep')
>>> elf.read(0x2004, 14)
b'/usr/bin/echo\x00'

$ gdb -ex 'disas/m main' -ex q reproduce_sleep | grep 'args\[\]' -A 13
9       const char *const args[] = {
   0x00000000000011d6 <+45>:        lea    0xe27(%rip),%rax        # 0x2004
   0x00000000000011dd <+52>:        mov    %rax,-0x30(%rbp)
   0x00000000000011e1 <+56>:        lea    0xe2a(%rip),%rax        # 0x2012
   0x00000000000011e8 <+63>:        mov    %rax,-0x28(%rbp)
   0x00000000000011ec <+67>:        mov    -0x38(%rbp),%rax
   0x00000000000011f0 <+71>:        mov    %rax,-0x20(%rbp)
   0x00000000000011f4 <+75>:        movq   $0x0,-0x18(%rbp)

10          PATHNAME,
11          "add",
12          hostname,
13          0
14      };

也可以通过在 ebpf 程序或 bpftrace 脚本中打印 args->filename 的指针地址来确认，这个地址的值会跟前面 page fault 事件中 addr 的值一致，都是 0x55b4d9e33004
```
tracepoint:syscalls:sys_enter_execve {
    printf("%s[%d]: %p\n", comm, pid, args->filename);
}
```

BTW，可以通过 perf trace -F all 命令追踪触发 page fault 事件的函数信息。

解决方法¶

解决这个问题的方法有很多，其中一种解决方法是改为通过追踪 tracepoint/sched/sched_process_exec 事件来获取 execve() 系统调用中 filename 和 argv 参数的值。下面是对应实现的示例程序：

通过 bpftrace 追踪 tracepoint/sched/sched_process_exec 事件的示例脚本（来自 @jschwinger233 ）:

tracepoint:sched:sched_process_exec {
  $task=curtask;
  $arg_start=$task->mm->arg_start;
  $arg_end=$task->mm->arg_end;
  printf("%s[%d]: filename: %s, argv: %r\n", comm, pid, str(args->filename), buf(uptr($arg_start), $arg_end-$arg_start));
}

通过 ebpf c 代码追踪 tracepoint/sched/sched_process_exec 事件的示例程序： main.bpf.c