周一(5 月 27 日)上班在验证个功能的时候,发现功能异常了。
周一排查了一整天,心都要滴血了,都没能排查出功能异常的原因。
周二排查出原因了,是同事修改了某个 bpf 函数的默认返回值。不过,在对 bpf 程序进行 trace 时,却没有拿到这个异常的返回值,这又排查了一整天。
周三排查出原因了,这是个 bpf 子系统的 BUG;不过,在最新内核里,已经被修复了。
背景
项目是一个超级复杂的 XDP 项目,采用了 bpf2bpf
+ freplace
混合 bpf2bpf
+ tailcall
的方式实现了模块化。参考 eBPF Talk: eBPF 程序模块化与单测构想。
其中,bpf2bpf
子程序用来当作 XDP 模块的桩;该桩要么被 freplace
替换成 XDP 模块,要么使用 tailcall
去调 XDP 模块。为什么不能统一成 freplace
呢?因为 eBPF Talk: tailcall in freplace 有 BUG。
发生异常的模块使用的桩是 bpf2bpf
+ tailcall
实现的。
此时,对 bpf2bpf
子程序使用 fentry
+ fexit
进行 trace。fentry/fexit
的资料,请看 eBPF Talk: trampoline on x86。
对 bpf2bpf
子程序进行 trace,请看 eBPF Talk: trace bpf2bpf 函数调用。
能否对 freplace
程序进行 trace?请看 eBPF Talk: trace freplace 程序。
直接对 tailcall
进行 trace?
排查过程
改进了内部的 XDP trace 工具后,实现了对 bpf2bpf
和 freplace
的 trace 功能;如此,便能够对 XDP 模块进行精准 trace 了。
对所有 XDP 模块同时使用 fentry
+ fexit
进行 trace,发现其中有个模块的返回值是 33(该值是 bpf2bpf
桩没有按预期运行的默认返回值)。
如果桩程序按预期运行,预期应该拿到 255 这个返回值;噢,这个就是同事改错的地方。预期应该拿到 XDP_PASS
/XDP_TX
/XDP_DROP
/XDP_REDIRECT
的。我是在 review 代码时,发现了这个错误的地方。
不过,即使我修正了这里,使用 fexit
进行 trace 时,拿到的返回值还是 33。这是为什么呢?如果不使用 fentry
/fexit
,就没问题了。
kernel BUG 分析过程
先看看桩程序的源码:
__noinline int
module3(struct xdp_md *ctx)
{
volatile int retval = 33;
bpf_tail_call_static(ctx, &prog_array, 3);
return retval;
}
__noinline
防止该函数被编译器内联优化掉了。volatile
强行将变量retval
写到栈上。bpf_tail_call_static()
如果该函数没有被freplace
替换掉,则进行tailcall
。return retval;
从栈上读取retval
,然后返回给 caller;同时能阻止编译器对函数返回值的优化。
一切尽在源代码中。在项目的源代码中?非也。在内核源代码中?是也不是。
一切尽在机器码中。
使用 drgn-bpf[1] 找到那个桩程序和对应的 trampoline:
# drgn ./tools/bpf_inspect.py p
26: BPF_PROG_TYPE_XDP xdp_xxx bpf_prog_8715bbbd4b4ee80f_xdp_dispatcher 0xffffffffc02e433c tail_call_reachable
// ...
4: 0 BPF_PROG_TYPE_XDP xdp_xxx bpf_prog_e62ce70b7576e225_F 0xffffffffc1009620
# drgn ./tools/bpf_inspect.py l
47: BPF_LINK_TYPE_TRACING
linked prog: 106 BPF_PROG_TYPE_TRACING fexit_xdp bpf_prog_fcc2f82f74950a24_fexit_xdp 0xffffffffc10aa71c
target prog: 26 BPF_PROG_TYPE_XDP xdp_xxx bpf_prog_8715bbbd4b4ee80f_xdp_xxx 0xffffffffc02e433c tail_call_reachable
target func: module3
current image: 0xffffffffc10b0000 bpf_trampoline_111669149702_1 0xffffffffc10b0000
直接看桩程序的反汇编吧。
# gdb -q -c /proc/kcore -ex 'disas/r 0xffffffffc100bb58,+1000' -ex 'quit'
Dump of assembler code from 0xffffffffc100bb58 to 0xffffffffc100bc0c:
// call trampoline of fentry/fexit
0xffffffffc100bb58: e8 a3 44 0a 00 callq 0xffffffffc10b0000
// nop2
0xffffffffc100bb5d: 66 90 xchg %ax,%ax
// prepare stack frame
0xffffffffc100bb5f: 55 push %rbp
0xffffffffc100bb60: 48 89 e5 mov %rsp,%rbp
// reserve 8 bytes stack space
0xffffffffc100bb63: 48 81 ec 08 00 00 00 sub $0x8,%rsp
// push tail_call_cnt to stack
0xffffffffc100bb6a: 50 push %rax
// push callee saved regs
0xffffffffc100bb6b: 53 push %rbx
0xffffffffc100bb6c: 41 55 push %r13
// cache the first arg to rbx
0xffffffffc100bb6e: 48 89 fb mov %rdi,%rbx
// save retval(0x1f, 33) to stack
0xffffffffc100bb71: bf 1f 00 00 00 mov $0x21,%edi
0xffffffffc100bb76: 89 7d fc mov %edi,-0x4(%rbp)
// &prog_array
0xffffffffc100bb79: 49 bd 00 72 9c d4 09 8d ff ff movabs $0xffff8d09d49c7200,%r13
// prepare args for bpf_tail_call()
0xffffffffc100bb83: 48 89 df mov %rbx,%rdi
0xffffffffc100bb86: 4c 89 ee mov %r13,%rsi
0xffffffffc100bb89: ba 04 00 00 00 mov $0x3,%edx
// load tail_call_cnt from stack
0xffffffffc100bb8e: 8b 85 f4 ff ff ff mov -0xc(%rbp),%eax
// jmp 0xffffffffc100bbb7 if tail_call_cnt > 32
0xffffffffc100bb94: 83 f8 20 cmp $0x20,%eax
0xffffffffc100bb97: 77 1e ja 0xffffffffc100bbb7
// inc tail_call_cnt
0xffffffffc100bb99: 83 c0 01 add $0x1,%eax
// store tail_call_cnt to stack
0xffffffffc100bb9c: 89 85 f4 ff ff ff mov %eax,-0xc(%rbp)
// nops5
0xffffffffc100bba2: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
// pop callee saved regs
0xffffffffc100bba7: 41 5d pop %r13
0xffffffffc100bba9: 5b pop %rbx
// pop tail_call_cnt
0xffffffffc100bbaa: 58 pop %rax
// restore stack frame
0xffffffffc100bbab: 48 81 c4 08 00 00 00 add $0x8,%rsp
// jmp tailcall tgt bpf prog
0xffffffffc100bbb2: e9 98 f7 02 00 jmpq 0xffffffffc103b34f
// load retval from stack
0xffffffffc100bbb7: 8b 45 fc mov -0x4(%rbp),%eax
// pop callee saved regs
0xffffffffc100bbba: 41 5d pop %r13
0xffffffffc100bbbc: 5b pop %rbx
// leave
0xffffffffc100bbbd: c9 leaveq
// ret
0xffffffffc100bbbe: c3 retq
0xffffffffc100bbbf: cc int3
留意其中的 rax
,即 tail_call_cnt
。
再来看 fentry
/fexit
的 trampoline 的反汇编。
# gdb -q -c /proc/kcore -ex 'disas/r 0xffffffffc10b0000,+1000' -ex 'quit'
Dump of assembler code from 0xffffffffc10b0000 to 0xffffffffc10b0258:
// prepare stack frame
0xffffffffc10b0000: 55 push %rbp
0xffffffffc10b0001: 48 89 e5 mov %rsp,%rbp
// reserve stack space
0xffffffffc10b0004: 48 83 ec 10 sub $0x10,%rsp
// push callee saved regs
0xffffffffc10b0008: 53 push %rbx
// save the first arg to stack
0xffffffffc10b0009: 48 89 7d f0 mov %rdi,-0x10(%rbp)
0xffffffffc10b000d: 48 bf 00 a8 b3 73 19 8d ff ff movabs $0xffff8d1973b3a800,%rdi
0xffffffffc10b0017: e8 04 65 9a c0 callq 0xffffffff81a56520
0xffffffffc10b001c: 48 bf 00 50 24 47 e3 b9 ff ff movabs $0xffffb9e347245000,%rdi
0xffffffffc10b0026: e8 c5 63 9a c0 callq 0xffffffff81a563f0
0xffffffffc10b002b: 48 89 c3 mov %rax,%rbx
0xffffffffc10b002e: 48 85 c0 test %rax,%rax
0xffffffffc10b0031: 74 09 je 0xffffffffc10b003c
0xffffffffc10b0033: 48 8d 7d f0 lea -0x10(%rbp),%rdi
0xffffffffc10b0037: e8 0c aa fc ff callq 0xffffffffc107aa48
0xffffffffc10b003c: 48 bf 00 50 24 47 e3 b9 ff ff movabs $0xffffb9e347245000,%rdi
0xffffffffc10b0046: 48 89 de mov %rbx,%rsi
0xffffffffc10b0049: e8 e2 63 9a c0 callq 0xffffffff81a56430
// restore the first arg
0xffffffffc10b004e: 48 8b 7d f0 mov -0x10(%rbp),%rdi
// call the tgt bpf prog
0xffffffffc10b0052: e8 06 bb f5 ff callq 0xffffffffc100bb5d
// save retval of bpf prog to stack
0xffffffffc10b0057: 48 89 45 f8 mov %rax,-0x8(%rbp)
0xffffffffc10b005b: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
0xffffffffc10b0060: 48 bf 00 90 41 47 e3 b9 ff ff movabs $0xffffb9e347419000,%rdi
0xffffffffc10b006a: e8 81 63 9a c0 callq 0xffffffff81a563f0
0xffffffffc10b006f: 48 89 c3 mov %rax,%rbx
0xffffffffc10b0072: 48 85 c0 test %rax,%rax
0xffffffffc10b0075: 74 09 je 0xffffffffc10b0080
0xffffffffc10b0077: 48 8d 7d f0 lea -0x10(%rbp),%rdi
0xffffffffc10b007b: e8 9c a6 ff ff callq 0xffffffffc10aa71c
0xffffffffc10b0080: 48 bf 00 90 41 47 e3 b9 ff ff movabs $0xffffb9e347419000,%rdi
0xffffffffc10b008a: 48 89 de mov %rbx,%rsi
0xffffffffc10b008d: e8 9e 63 9a c0 callq 0xffffffff81a56430
0xffffffffc10b0092: 48 bf 00 a8 b3 73 19 8d ff ff movabs $0xffff8d1973b3a800,%rdi
0xffffffffc10b009c: e8 af 64 9a c0 callq 0xffffffff81a56550
0xffffffffc10b00a1: 48 8b 45 f8 mov -0x8(%rbp),%rax
0xffffffffc10b00a5: 5b pop %rbx
0xffffffffc10b00a6: c9 leaveq
0xffffffffc10b00a7: 48 83 c4 08 add $0x8,%rsp
0xffffffffc10b00ab: c3 retq
留意其中调用原 bpf prog 的地方。
Kernel BUG 发生过程:
trampoline 里没有使用 push rax
去缓存tail_call_cnt
。trampoline 里 call
原 bpf prog 前,没有恢复tail_call_cnt
。trampoline 里 call
原 bpf prog 前,rax
的值是不确定的。桩程序里把 rax
当作tail_call_cnt
。桩程序里使用 tail_call_cnt
跟MAX_TAIL_CALL_CNT
对比时,tail_call_cnt
超出了限制。桩程序里使用栈上保存的 retval
当作返回值返回了。
咦,这个 BUG 发生过程有点似曾相识:eBPF Talk: 内核 bpf 子系统贡献之修复 tailcall 无限循环。如果桩程序里的 tail_call_cnt
一直没超出 MAX_TAIL_CALL_CNT
的限制,就可以利用这个 BUG 构造一个无限循环。
bpf, x64: Fix tailcall infinite loop[2] since 6.7 kernel
好吧,这个 patch 其实也修复了这个 BUG,让 tail_call_cnt
正确地经过 trampoline 传递给桩程序。
白白错失又一个内核贡献的机会。
总结
由一行代码引发的一个 BUG,排查 BUG 的过程中触发了一个 kernel BUG,导致未能顺利地解决代码 BUG。
排查 BUG 搞得身心疲惫,一行代码两行泪。
更多 XDP 资料,请加入「eBPF Talk」知识星球来学习《XDP 进阶手册》吧。
drgn-bpf: https://github.com/Asphaltt/drgn-bpf
[2]bpf, x64: Fix tailcall infinite loop: https://github.com/torvalds/linux/commit/2b5dcb31a19a2e0acd869b12c9db9b2d696ef544