golang 下对时间漂移的故障注入

很多时候我们在做测试时候,需要对程序的时间或者定时器进行一些操纵,各个语言对于获取时间和定时器的实现都不尽相同,在网上找了一下,发现有一个chaos-mesh的项目里面提供了一个对golang和rust程序注入故障的方案。

要想能针对某个进程进行时间漂移的注入,首先要知道这个进程里面对于获取时间的调用是怎么进行的。对于golang程序而言,当我们调用time.Now()时,实际上是利用了vDSO (virtual dynamic shared object)机制,该机制可以让一些诸如gettimeofdayclock_gettime的系统调用更快,而golang的time.Now()或者golang的定时器实现中维护堆时使用的就是clock_gettime

知道了调用的函数,接下来就是需要想办法修改掉它,这里chaos-mesh使用的方案是通过ptrace去修改对应进程的内存空间,将clock_gettime的跳转改成一个自己的实现。

chaos-mesh还提供了一个测试程序的封装叫watchmaker,这个程序可以方便我们直接运行,只要直接输入pid和偏移量就可以完成注入。

主要功能的代码是func ModifyTime(pid int, deltaSec int64, deltaNsec int64, clockIdsMask uint64) error

大体流程如下
1. 利用runtime.LockOSThread(),将当期goroutine和linux的thread绑定,这个我猜应该是防止该goroutine被切走,ptrace失效。
2. ptrace.Trace(pid)attach到pid上。通过/proc/pid/task获取该进程的所有threads,并通过PtraceAttach syscall attach到每个tid上,同时通过/proc/pid/maps拿到该进程的虚拟内存映射信息。
3. 通过关键字[vdso]找到vDSO entry的起始地址。
4. 准备好一个fakeImage,里面直接写好了我们的跳转的程序,最后24 bytes是我们的三个参数。这块涉及汇编,没仔细看fakeImage里面的实现。
5. 在当前进程查询到是否曾经注入过我们的fakeImage,如果没有那么通过mmap新map进去我们的fakeImage,否则找到我们之前的entry。把最后24 bytes改写为当前设置的参数。
6. 找到vDSO entry中的clock_gettime的原始地址,这里需要利用golang的debug/elf包,来找到对应的symbol address。
7. 把vDSO entry中的clock_gettime跳转修改掉。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
// JumpToFakeFunc writes jmp instruction to jump to fake function
func (p *TracedProgram) JumpToFakeFunc(originAddr uint64, targetAddr uint64) error {
instructions := make([]byte, 16)

// mov rax, targetAddr;
// jmp rax ;
instructions[0] = 0x48
instructions[1] = 0xb8
binary.LittleEndian.PutUint64(instructions[2:10], targetAddr)
instructions[10] = 0xff
instructions[11] = 0xe0

return p.PtraceWriteSlice(originAddr, instructions)
}

我们可以写个程序测试下效果

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
// go build -o test test.go
func main() {
pid := os.Getpid()
if len(os.Args) > 1 {
// normal process
fmt.Println(pid, "start count", time.Now())
t := time.NewTicker(time.Second)
go func() {
for _ = range t.C {
fmt.Println(pid, "tick", time.Now())
}
}()
} else {
// time shift
fmt.Println(pid, "30s ticker", time.Now())
j := 0
t := time.NewTicker(time.Second*30)
go func() {
for tick := range t.C {
j++
fmt.Println(pid, "trigger tick", tick, "now", time.Now(), j)
}
}()
}
select {}
}

为了观察方便,同时起两个test进程,一个带参数,一个不带。
./test & ./test x &

如果正常运行,那么输出结果会是这样的:

1
2
3
4
5
6
7
8
99335 start count 2021-04-26 15:14:40.290945165 +0800 CST m=+0.000102053
99334 30s ticker 2021-04-26 15:14:40.290987246 +0800 CST m=+0.000068288
99335 tick 2021-04-26 15:14:41.291190225 +0800 CST m=+1.000347008
99335 tick 2021-04-26 15:14:42.291188665 +0800 CST m=+2.000345428
// 忽略当中的一些打印
99335 tick 2021-04-26 15:15:10.291344814 +0800 CST m=+30.000501519
99334 trigger tick 2021-04-26 15:15:10.291371963 +0800 CST m=+30.000452968 now 2021-04-26 15:15:10.291389026 +0800 CST m=+30.000470067 1 // 这是第一次30s定时器超时
99335 tick 2021-04-26 15:15:11.291317403 +0800 CST m=+31.000474367

我们先等到99334进程触发了一次定时器超时之后,我们立刻通过watchmaker工具注入一个30秒的漂移。
sudo ./bin/watchmaker -pid 99334 -sec_delta 30 -nsec_delta 0 -clk_ids "CLOCK_REALTIME,CLOCK_MONOTONIC"

注意如果我们只是想影响程序中time.Now(),只修改CLOCK_REALTIME就行了。这里我们需要影响定时器的超时,根据golang的定时器实现,定时器数据结构中取时间使用的是runtime·nanotime1,而对应的汇编实现里面取的是CLOCK_MONOTONIC,所以我们修改的clockid除了CLOCK_REALTIME还需要包含CLOCK_MONOTONIC

程序会输出:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
watchmaker Version: version.Info{GitVersion:"master-ge885846a41fd88", GitCommit:"e885846a41fd88aa3a46f8b318321b8e889312b9", BuildDate:"2021-04-13T08:09:23Z", GoVersion:"go1.14.14", Compiler:"gc", Platform:"linux/amd64"}
2021-04-26T15:15:18.764+0800 INFO zapr@v0.1.0/zapr.go:69 get clock ids mask {"mask": 3}
2021-04-26T15:15:18.764+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 attach successfully {"tid": 99334}
2021-04-26T15:15:18.764+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 attach successfully {"tid": 99337}
2021-04-26T15:15:18.764+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 attach successfully {"tid": 99339}
2021-04-26T15:15:18.764+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 attach successfully {"tid": 99341}
2021-04-26T15:15:18.764+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 attach successfully {"tid": 99343}
2021-04-26T15:15:18.765+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 detaching {"tid": 99334}
2021-04-26T15:15:18.765+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 detaching {"tid": 99337}
2021-04-26T15:15:18.765+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 detaching {"tid": 99339}
2021-04-26T15:15:18.765+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 detaching {"tid": 99341}
2021-04-26T15:15:18.765+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 detaching {"tid": 99343}
2021-04-26T15:15:18.765+0800 INFO ptrace zapr@v0.1.0/zapr.go:69 Successfully detach and rerun process {"pid": 99334}

这里也可以看到,一个普通的go程序也会启动很多线程。。。

然后回去看我们测试进程的输出变成了这样:

1
2
3
4
5
6
7
8
9
10
11
12
99335 tick 2021-04-26 15:15:10.291344814 +0800 CST m=+30.000501519
99334 trigger tick 2021-04-26 15:15:10.291371963 +0800 CST m=+30.000452968 now 2021-04-26 15:15:10.291389026 +0800 CST m=+30.000470067 1 // 这是上面第一次30s定时器超时
99335 tick 2021-04-26 15:15:11.291317403 +0800 CST m=+31.000474367
99335 tick 2021-04-26 15:15:12.291291676 +0800 CST m=+32.000448352
99335 tick 2021-04-26 15:15:13.291336311 +0800 CST m=+33.000493035
99335 tick 2021-04-26 15:15:14.291333735 +0800 CST m=+34.000490470
99335 tick 2021-04-26 15:15:15.29133939 +0800 CST m=+35.000496121
99335 tick 2021-04-26 15:15:16.291349531 +0800 CST m=+36.000506260
99335 tick 2021-04-26 15:15:17.291232264 +0800 CST m=+37.000389035
99335 tick 2021-04-26 15:15:18.291307312 +0800 CST m=+38.000464034
99334 trigger tick 2021-04-26 15:15:48.765121761 +0800 CST m=+68.474202738 now 2021-04-26 15:15:48.765129654 +0800 CST m=+68.474210641 2 // 由于我们修改了时间,里面触发了第二次的30s定时器超时
99335 tick 2021-04-26 15:15:19.291362269 +0800 CST m=+39.000519076 // 这里可以看见99335对比进程中的时间还是正常的

注意golang的默认的time这个数据结构的打印,m=+后面的数字就是进程启动后的monotinic时间,这里99334进程的monotinic时间一下子从38变成了68,所以立马触发了第二次超时。

至此,我们就完成了对一个golang进程的时间漂移的注入,赶快去测试下生产代码中是否有问题吧,据chaos-mesh团队的分享中所说,很多开源项目均有或大或小的问题哦。