tracing – CFC4N的博客

前言在eCapture最初支持golang的https明文捕获时，是不支持request\response完整的匹配的。这点不同于C语言编写的程序，是因为golang的uretprobe类型钩子有个较为致命的bug，会导致被挂载进程崩溃，这问题在BCC社区也有讨论过：Go crash with uretprobe #1320，火焰图作者brendangregg也提到，在他的一篇博客里，用户评论如下： Another problem I ran into: the uretprobe seems to place the return probes by modifying the stack, which is in conflict with how Go manages stack (stacks in Go can grow/shrink at anytime, it does so by copying entire stack to a new larger area, adjusting the pointers in the stack to point to new area etc). So if we are doing a uretprobe, and stack happens to grow (or shrink) at that time, it can lead Go runtime panics. Please see here for an example panic message:go.stp#L32-L58 也就是说 uretprobe似乎通过修改堆栈来放置返回探针，这与Go管理堆栈的方式冲突（Go中的堆栈可以在任何时候增长/缩小，它通过将整个堆栈复制到一个新的较大区域，调整堆栈中的指针以指向新区域等方式实现）。因此，如果我们正在进行uretprobe操作，并且堆栈在此期间发生增长（或缩小），它可能导致Go运行时发生错误。请参阅此处的示例错误消息：go.stp#L32-L58 亲自验证是的，笔者在为eCapture增加go tls的明文捕获时，也是attach到Go 函数的uretprobe上，结果自然是，被挂载的进程崩溃了。经过漫长的debug、查资料，终于有点眉目。这其实跟Golang的runtime、寄存器等实现机制有关，我写了一个DEMO，验证一番。这个DEMO是我在5月初写的，期间一直想写篇简单的文章给大家介绍一下，奈何太忙了，接着这次出差的机会，周末整理一下，分享给大家。时间相隔太久，可能很多细节都忘记了，笔者水平有限，如有错误，欢迎指出。 golang uretprobe冲突话不多说，Go程序崩溃的核心原因为Go的栈在runtime管理时，被插入了异常的内存地址。Go中常见的堆栈变化为协程goroutine的创建与销毁。栈内被插入异常内存地址是因为eBPF的实现机制是向函数的返回地址前，插入了断点指令（i386和x86_64是INT3）。两个条件的叠加，就出现了这个错误。那么重现起来也比较简单，写一个协程goroutine数量不停变化的程序，并使用eBPF uretprobe挂载上去即可。案例演示被HOOK的测试代码 package main import ( "flag" "fmt" "time" ) //go:noinline func recursion(level, maxLevel int) int { if level > maxLevel { return level } return recursion(level+1, maxLevel) } //go:noinline func NewTestFunc() int { //nothing print("NewTestFunc\n") return 100 } // uretprobe挂载的目标函数 // //go:noinline func CountCC(maxLevel int) (a int) { a = NewTestFunc() fmt.Println(a) if a > 100 { return a } a = recursion(0, maxLevel) fmt.Printf("CountCC return :%d\n", a) return a } func main() { var maxLevel = flag.Int("l", 100, "max recursion level") flag.Parse() for { go CountCC(*maxLevel) time.Sleep(time.Second) } } 被挂载的函数是CountCC，他的返回值应该是101，这段代码被Go编译后，CountCC在符号表里名字是main.CountCC，这个就是eBPF挂载的函数名。要注意，在代码里务必使用go:noline语法来让Go编译器不要对这段代码进行内联inline，否则编译后的可执行文件中，符号表内就找不到main.CountCC函数了。执行挂载动作的代码内核空间代码： SEC("uretprobe/countcc") int uretprobe_countcc(struct pt_regs *ctx) { bpf_printk("new countCC[RET] detected\n"); return 0; }; 其中SEC的参数uretprobe/countcc在编译为ebpf字节码后，会被用户空间程序读取，关联到uretprobe_countcc这个符号上。用户空间代码：执行挂载动作的代码，也很好实现，使用笔者的golang eBPF管理SDK ebpfmanager，只需要几行代码，以下为用户空间程序： const COUNT_CC_SYMBOL = "main.CountCC" var sec = "uretprobe/countcc" var ebpfFunc = "uretprobe_countcc" var m = &manager.Manager{ Probes: []*manager.Probe{ { Section: sec, EbpfFuncName: ebpfFunc, AttachToFuncName: COUNT_CC_SYMBOL, BinaryPath: goAppPath, }, }, } // Initialize the manager buf, err := Asset("/probe.o") if err != nil { log.Fatal(errors.New(fmt.Sprintf("error:%v , couldn't find asset", err))) } if err = m.Init(bytes.NewReader(buf)); err != nil { log.Fatal(err) } // Start the manager if err = m.Start(); err != nil { log.Fatal(err) } 挂载类型uretprobe/countCC，被Go的eBPF类库解析为uretprobe类型程序。挂载的eBPF执行函数为uretprobe_countcc，挂载目标符号为main.CountCC。执行重现编译后，观测程序是main，被观测程序是demo。启动观测程序bin/main 启动被观测程序bin/demo 崩溃栈信息可以看到被观测程序立刻崩溃，崩溃的信息如下： bin/demo NewTestFunc 100 runtime: unexpected return pc for main.CountCC called from 0x7fffffffe000 stack: frame={sp:0xc000069f50, fp:0xc000069fc8} stack=[0xc000069000,0xc00006a000) 0x000000c000069e50: 0x000000c0000560d8 0x000000c0000140b8 0x000000c000069e60: 0x000000c000069e80 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069e70: 0x000000000047a0a0 <internal/poll.(*FD).Write.func1+0x0000000000000000> 0x000000c0000560c0 0x000000c000069e80: 0x000000c000069ea0 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069e90: 0x0000000000468efe <sync.(*Pool).pin+0x000000000000001e> 0x000000c0000560c0 0x000000c000069ea0: 0x000000c000069ec0 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069eb0: 0x000000000052e3c0 0x0000000000000000 0x000000c000069ec0: 0x000000c000069ee0 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069ed0: 0x000000000047d76a <fmt.(*pp).free+0x00000000000000ca> 0x000000000052e3c0 0x000000c000069ee0: 0x000000c000069f00 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069ef0: 0x000000c000036740 0x000000000047dc4e <fmt.Fprintln+0x000000000000008e> 0x000000c000069f00: 0x000000c000069f20 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069f10: 0x0000000000000004 0x000000000000000c 0x000000c000069f20: 0x000000c000069f40 0x000000000048802b <main.recursion+0x000000000000002b> 0x000000c000069f30: 0x0000000000000000 0x0000000000000000 0x000000c000069f40: 0x000000c000069fb8 0x0000000000488147 <main.CountCC+0x0000000000000087> 0x000000c000069f50: <0x00000000004c0798 0x000000c00000e018 0x000000c000069f60: 0x000000c0000367a8 0x0000000000000001 0x000000c000069f70: 0x0000000000000001 0x0000000000000000 0x000000c000069f80: 0x0000000000000000 0x0000000000000064 0x000000c000069f90: 0x0000000000000064 0x0000000000000000 0x000000c000069fa0: 0x0000000000000000 0x0000000000490180 0x000000c000069fb0: 0x0000000000528bc0 0x000000c0000367d0 0x000000c000069fc0: !0x00007fffffffe000 >0x0000000000000000 0x000000c000069fd0: 0x0000000000000000 0x000000000045bd81 <runtime.goexit+0x0000000000000001> 0x000000c000069fe0: 0x0000000000000000 0x0000000000000000 0x000000c000069ff0: 0x0000000000000000 0x0000000000000000 fatal error: unknown caller pc runtime stack: runtime.throw({0x4a2fba?, 0x522940?}) /usr/local/go1.18.8/go/src/runtime/panic.go:992 +0x71 runtime.gentraceback(0x423d45?, 0x7f46d2dc2fff?, 0x1?, 0x400?, 0x0, 0x0, 0x7fffffff, 0x4a92e0, 0x7f46d2dc2fff?, 0x0) /usr/local/go1.18.8/go/src/runtime/traceback.go:258 +0x1c2a runtime.copystack(0xc000003860, 0x800000002?) /usr/local/go1.18.8/go/src/runtime/stack.go:930 +0x2f5 runtime.newstack() /usr/local/go1.18.8/go/src/runtime/stack.go:1110 +0x497 runtime.morestack() /usr/local/go1.18.8/go/src/runtime/asm_amd64.s:547 +0x8b 其中致命的错误信息是fatal error: unknown caller pc，是的，重现了。 Go程序uretprobe挂载解决方案冲突点正如前文所说，这是golang 协程收缩容，导致stack变动， int3指令执行后，添加到stack中，破坏原来的栈，执行报错。如何解决这个问题呢，在之前的issue里，有人提了一个用uprobe模拟uretprobe的思路。给定一个Golang二进制文件，解析ELF符号表并获取我们想要跟踪的符号的地址。如果需要，在该地址附加一个uprobes。不要将uretprobe附加到符号地址，而是从该地址开始读取ELF文本部分，并解码汇编指令，直到达到符号的结束。在扫描过程中，在每个返回过程的指令（例如对于x86-64，RETN指令，操作码为0xC2和0xC3）处放置一个uprobes。对于我感兴趣的符号，通常只有很少的RET指令，大约在1到5个范围内，这是合理的。当在上述点安装的任一uprobes触发时，实际上就像我们执行了一个uretprobe一样，除了我们没有干扰堆栈，因此当Go运行时移动堆栈时，解决方案足够稳健以避免崩溃（至少看起来是这样）。而且，由于uprobes恰好放置在RET指令之前，栈指针已经方便地放置在帧的开头，因此我们可以轻松访问输入参数和返回值，因为它们在Go中都存储在栈上。评论者还提到，这种方法具有一些轻微的性能优势，因为我们避免了uretprobe的开销。但缺点是我们现在必须在用户空间中解码ELF文件的汇编指令，所以相比标准的替代方案要麻烦得多，而且，无法使用BCC之类工具，只能自己实现eBPF程序。 Go函数的RET偏移地址这可难不到我，笔者一直不太用BCC，更喜欢自己写eBPF程序。实现起来也很简单，只需要按照DWARF Debugging Standard规范，读取Golang的ELF文件，查找符号表内对应main.CountCC函数对应符号的汇编指令，并按照X86格式解析，循环判断是否为RET，并记录当前指令在整个函数符号的偏移地址即可。 goElf, err = elf.Open(elfPath) // ... goSymbs, err = goElf.Symbols() // ... var found bool var symbol elf.Symbol for _, s := range goSymbs { if s.Name == symbolName { symbol = s found = true break } } section := goElf.Sections[symbol.Section] var elfText []byte elfText, err = section.Data() // ... start := symbol.Value - section.Addr end := start + symbol.Size var instHex []byte instHex = elfText[start:end] for i := 0; i < len(instHex); { inst, err := x86asm.Decode(instHex[i:], 64) // ... if inst.Op == x86asm.RET { offsets = append(offsets, i) } i += inst.Len } 内核空间程序因为是用uprobe来模拟uretprobe，eBPF内核代码肯定要调整的了，为了要验证能否拿到返回值，这里也增加了返回值的获取。 SEC("uprobe/countcc") int uprobe_countcc(struct pt_regs *ctx) { bpf_printk("new countCC detected\n"); int num; num = (int)GO_PARAM1(ctx); bpf_printk("countCC :: num:%d, ret_num:%d\n", num); return 0; }; 可以看到，这里新增一个函数uprobe_countcc，将用于用户空间的eBPF执行函数。用户空间程序调整经过ELF文件分析，将RET指令的偏移地址保存到offsets中，在用户空间挂载到函数的偏移位置上： sec = "uprobe/countcc" ebpfFunc = "uprobe_countcc" m.Probes = m.Probes[:0] // 清空slice for _, offset := range offsets { m.Probes = append(m.Probes, &manager.Probe{ Section: sec, UprobeOffset: uint64(offset), EbpfFuncName: ebpfFunc, AttachToFuncName: COUNT_CC_SYMBOL, BinaryPath: goAppPath, UID: fmt.Sprintf("%s_%d", ebpfFunc, offset), }) } 可以看到Section改成了uprobe/countcc，并挂载到内核函数uprobe_countcc上。以及新增 UprobeOffset字段，并设定offset，这样就实现自动的uprobe偏移量挂载。（PS：你就说，笔者的 ebpfmanager方便不方便吧）模拟验证按照之前的步骤，先启动观测程序，打开内核调试的日志，再启动被观测程序：启动观测程序，bin/main -e，这里多了-e参数，来使用模拟模式。打开内核调试日志，方便观察是否能拿到main.CountCC函数的返回值，命令为cat /sys/kernel/debug/tracing/trace_pipe。启动被观测程序，bin/demo 观测程序观测程序启动后，可以看到终端日志中，搜索到两处RET指令，并分别进行uprobe`挂载。 root@vm-server-2004:/home/cfc4n/project/go_uretprobe_demo# bin/main -e 2023/06/11 23:49:18 Github repo : https://github.com/cfc4n/go_uretprobe_demo 2023/06/11 23:49:18 Use uprobe+offset address instead of uretprobe:true 2023/06/11 23:49:18 traced ELF file:/home/cfc4n/project/go_uretprobe_demo/bin/demo 2023/06/11 23:49:18 attach function: main.CountCC 2023/06/11 23:49:18 Golang uretprobe hook main.CountCC [RET] at 0x7A 2023/06/11 23:49:18 Golang uretprobe hook main.CountCC [RET] at 0xE3 2023/06/11 23:49:18 successfully started, head over to /sys/kernel/debug/tracing/trace_pipe main.CountCC函数内，RET汇编指令的偏移地址分别为0x7A、0xE3 ，且都挂载成功，执行的内核函数为uprobe_countcc。被观察程序如你所见，被观测程序没有崩溃，可以正常运行，并输出结果。 bin/demo NewTestFunc 100 CountCC return :101 NewTestFunc 100 CountCC return :101 NewTestFunc 100 CountCC return :101 观察结果笔者的DEMO里没有将内核调试结果传输到用户空间，直接打印了。 root@vm-server-2004:/home/cfc4n# cat /sys/kernel/debug/tracing/trace_pipe demo-18960 [000] .... 5125.277053: 0: new countCC detected demo-18960 [000] .... 5125.277089: 0: countCC :: num:101, ret_num:0 demo-18962 [001] .... 5126.276907: 0: new countCC detected demo-18962 [001] .N.. 5126.276940: 0: countCC :: num:101, ret_num:0 可以看到，demo-18960 （程序名+PID）运行结果后，出现了我们打印的日志。并且，捕获的结果是101，符合预期。总结 eBPF挂载uretprobe崩溃的问题，只在Golang程序上发生，这跟Golang的协程缩容、扩容机制有关，受到CPU中断指令插入影响，破坏原有调用栈，导致问题发生。其他编译型语言上，不会有这个问题。假如有的语言也跟Golang一样，使用stack来做运动时管理，哪也会遇到这个问题。关于 Golang的这个问题，在其社区里也有关于runtime: fatal error: unknown caller pc when uprobes are attached #27077的讨论，Go语言开发者aclements认为，这不是Go的问题，近期也不会考虑修复，希望uretprobe的管理层面，自动做返回地址栈的修复。感谢提供的参考资料，@sillyousu。这些资料确认了我的猜测，很不幸地，我们实际上无法有效地解决uretprobes损坏堆栈的问题。既然我们无能为力，而且这并不是一个Go的错误，我决定关闭这个问题。如果将来uretprobes能够提供足够的信息来恢复用户空间中被破坏的返回地址，我们可以重新考虑这个问题，并可能找到解决方法。所以，这个问题，大家还是自己使用模拟的方法来解决Golang程序的函数返回值观测需求吧。eCapture也是自己写了PR支持了Go TLS的明文捕获：support gotls request and response #357。本次DEMO的测试代码在GitHub仓库：cfc4n/go_uretprobe_demo ，祝大家玩得开心。写于2023年6月11日，周末，雷阵雨，北京望京。

前言此文章将解释如何使用 Delve 跟踪 Go 程序，以及 Delve 如何利用 eBPF 在后台优化效率和速度。Delve 的目标是为开发人员提供愉快且高效的 Go 调试体验。因此，本文重点介绍了我们如何优化函数跟踪子系统，以便您可以更快地检查程序并找到根本原因分析。Delve 的跟踪实现有两个不同的后端，一个是基于 ptrace 的，另一个使用 eBPF。如果您不熟悉任何这些术语，请不要担心，我会随着解释一起说明。什么是程序跟踪？跟踪是一种允许开发人员在执行时看到程序正在做什么的技术。与典型的调试技术相反，这种方法不需要直接用户交互。最知名的跟踪工具之一是 strace，它允许开发人员在执行期间查看程序的系统调用。尽管上述的 strace 工具对于了解系统调用很有用，但 Delve trace 命令允许您洞察 "用户空间" 中 Go 程序的情况。这种 Delve 跟踪技术允许您跟踪程序中的任意函数，以便查看这些函数的输入和输出。此外，您还可以使用此工具了解程序的控制流，而无需交互式调试会话的开销，因为它还会显示正在执行该函数的 Goroutine。对于高度并发的程序，这可能是获得程序执行洞察力的更快方法，而无需启动完整的交互式调试会话。如何使用 Delve 跟踪 Go 程序 Delve 允许您通过调用 dlv trace 子命令来跟踪 Go 程序。该子命令接受一个正则表达式，并将执行您的程序，在与正则表达式匹配的每个函数上设置跟踪点，并实时显示结果。以下是示例程序： package main import "fmt" func foo(x, y int) (z int) { fmt.Printf("x=%d, y=%d, z=%d\n", x, y, z) z = x + y return } func main() { x := 99 y := x * x z := foo(x, y) fmt.Printf("z=%d\n", z) } 程序跟踪将给出以下输出： $ dlv trace foo > goroutine(1): main.foo(99, 9801) x=99, y=9801, z=0 >> goroutine(1): => (9900) z=9900 Process 583475 has exited with status 0 如您所见，我们在正则表达式中提供了 foo，它在这种情况下与主包中同名的函数匹配。以>为前缀的输出表示被调用的函数，并显示调用函数的参数，而以>>为前缀的输出表示从函数返回并与其相关联的返回值。所有输入和输出行均以在该时刻执行的 Goroutine 作为前缀。默认情况下，dlv trace 命令使用基于 ptrace 的后端，但添加 --ebpf 标志将启用基于 eBPF 的实验性后端。使用上面的示例，如果我们要像以下方式调用 trace 子命令： $ dlv trace –ebpf foo 我们将收到类似的输出。但是，背后发生的情况要大大不同并且更加高效。 ptrace低效率默认情况下，Delve 会使用 ptrace 系统调用来实现跟踪功能。ptrace 是一个系统调用，允许程序观察和操纵同一台机器上的其他程序。实际上，在 Unix 系统上，Delve 使用这个 ptrace 功能来实现调试器提供的许多低级功能，例如读写内存、控制执行等。虽然 ptrace 是一个有用和强大的机制，但它存在固有的效率低下。首先，ptrace 是一个系统调用，意味着我们必须跨越用户空间/内核空间边界，这增加了每次使用函数时的开销。这是由于我们必须调用 ptrace 的次数越多，开销就越大。考虑前面的示例，以下是使用 ptrace 实现跟踪的大致步骤概述：使用 ptrace(PT_ATTACH) 启动程序并附加调试器。使用 ptrace 在匹配所提供的正则表达式的每个函数处设置断点，并在被跟踪的进程的可执行内存中插入断点指令。另外，在该函数的每个返回指令处设置断点。再次使用 ptrace(PT_CONT) 继续程序。此步骤可能涉及多次ptrace调用，因为我们需要读取函数入口的CPU寄存器、堆栈上的内存以及如果必须取消指针引用的堆上的内存。再次使用ptrace(PT_CONT)继续程序。在函数返回时遇到断点，通过读取变量，可能涉及到更多的ptrace调用，以读取寄存器和内存。再次使用ptrace(PT_CONT)继续程序。直到程序结束。显然，函数的参数和返回值越多，每次停止就越昂贵。所有调试器花费在进行 ptrace 系统调用的时间，我们跟踪的程序都处于暂停状态，没有执行任何指令。从用户的角度来看，这使得程序的运行速度比原本要慢得多。现在，对于开发和调试来说，这也许不是什么大问题，但是时间是宝贵的，我们应该尽量快速地完成事情。程序在跟踪过程中的运行速度越快，你就能越快找到问题的根本原因。现在的问题是，我们如何使其更好呢？在下一节中，我们将讨论新的基于 eBPF 的后端，以及它如何改进这种方法。 eBPF 为何比 ptrace 更快一个最大的速度和效率改进是避免大量的系统调用开销。这是 eBPF 发挥作用的地方，因为我们可以在函数入口和出口设置 uprobes，并将小 eBPF 程序附加到它们上。Delve 使用 Cilium eBPF Go 库加载和与 eBPF 程序交互。每次触发 probe 时，内核将调用我们的 eBPF 程序，然后在它完成后继续主程序。我们编写的小 eBPF 程序将处理函数入口和出口中列出的所有步骤，但不会有所有的系统调用上下文切换，因为程序直接在内核空间中执行。我们的 eBPF 程序可以通过 eBPF 环形缓冲区和映射数据结构与用户空间中的调试器通信，使 Delve 能够收集所需的所有信息。这种方法的优点是，我们正在跟踪的程序需要暂停的时间大大减少。在触发 probe 时运行我们的 eBPF 程序比在函数入口和出口处调用多个系统调用要快得多。使用eBPF调试与跟踪步骤这里再概括一遍使用 eBPF 跟踪调试的流程：启动程序并使用 ptrace(PT_ATTACH) 附加到进程上。在内核中加载所有需要跟踪的函数的 uprobes。使用 ptrace(PT_CONT) 继续执行程序。在函数入口和出口触发 uprobes。每当 probe 被触发，内核部分将运行我们的 eBPF 程序，该程序获取函数的参数或返回值，并将其发送回用户空间。在用户空间中，从 eBPF 环形缓冲区读取函数参数和返回值。重复此过程直到程序结束。通过使用这种方法，Delve 可以比使用默认的 ptrace 实现更快地跟踪程序。现在，你可能会问，为什么不将这种方法默认使用？事实上，未来很有可能会成为默认方法。但目前，仍在进行开发，以改进这种基于 eBPF 的后端并确保它与基于 ptrace 的后端具有平衡性。然而，您仍然可以在执行 dlv trace 时使用 --ebpf 标志来使用它。为了给出一个使用不同跟踪方法的程序的效率差异的大致数字，我测量了另一个程序的运行情况，如下所示： Program execution: 23.7µs With eBPF trace: 683.1µs With ptrace tracing: 2.3s 数字本身就是最好的证明！为什么不使用uretprobe 如果您熟悉 eBPF、uprobes / uretprobes，您可能会问为什么我们对一切都使用 uprobes，而不是仅使用 uretprobes 捕获返回参数。关于此的解释相当复杂，但简短版本是，Go 运行时在执行 Go 程序过程中需要多次检查调用堆栈。当 uretprobes 附加到函数时，它们将该函数的返回地址覆盖在堆栈上。当 Go 运行时检查堆栈时，它会找到该函数的意外返回地址，最终会导致程序致命退出。为了解决这个问题，我们只需使用 uprobes，并利用 Delve 的能力检查程序的机器指令来在每个函数的返回指令处设置探测器。 Delve使用eBPF更快地调试Go代码 Delve的总体目标是帮助开发人员尽快地找到Go代码中的错误。为此，我们利用最新的方法和技术，并试图推动调试器可以完成的范围。 Delve在内部利用eBPF来最大化效率和速度。用户空间跟踪是任何工程师工具箱中的重要工具，我们的目标是使其高效易用。原文： How debugging Go programs with Delve and eBPF is faster