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

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

要想能针对某个进程进行时间漂移的注入，首先要知道这个进程里面对于获取时间的调用是怎么进行的。对于golang程序而言，当我们调用time.Now()时，实际上是利用了vDSO (virtual dynamic shared object)机制，该机制可以让一些诸如gettimeofday、clock_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跳转修改掉。

   // 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)
      }

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

// 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 &

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

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。

程序会输出：

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程序也会启动很多线程。。。

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

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团队的分享中所说，很多开源项目均有或大或小的问题哦。