起因

这一次的问题出现在我开发的安全系统的 agent 中,在正式发布之前,测试到了这个问题,还算幸运😅 在内网测试环境中,agent 一直都没出现问题,直到运行五六天后,突然发现 lua 虚拟机崩溃了…

日志分析

{"level":"error","ts":"2021-05-31 19:50:27.023","caller":"workers/luaworker.go:132","msg":"call run func failed","error":"/data/dep/agent/lua/utils.lua:38: registry overflow\nstack traceback:\n\t[G]: in function 'gsub'\n\t/data/dep/agent/lua/utils.lua:38: in function 'split'\n\tlua/port.lua:42: in function 'inspect'\n\tlua/port.lua:21: in main chunk\n\t[G]: ?","lua":"port.lua"}
{"level":"error","ts":"2021-05-31 19:51:27.104","caller":"workers/luaworker.go:132","msg":"call run func failed","error":"/data/dep/agent/lua/utils.lua:38: registry overflow\nstack traceback:\n\t[G]: in function 'gsub'\n\t/data/dep/agent/lua/utils.lua:38: in function 'split'\n\tlua/port.lua:42: in function 'inspect'\n\tlua/port.lua:21: in main chunk\n\t[G]: ?","lua":"port.lua"}
{"level":"error","ts":"2021-05-31 19:53:27.296","caller":"workers/luaworker.go:132","msg":"call run func failed","error":"/data/dep/agent/lua/utils.lua:38: registry overflow\nstack traceback:\n\t[G]: in function 'gsub'\n\t/data/dep/agent/lua/utils.lua:38: in function 'split'\n\tlua/port.lua:42: in function 'inspect'\n\tlua/port.lua:21: in main chunk\n\t[G]: ?","lua":"port.lua"}

这里只截取了几条,可以看到,关键信息就是 registry overflow

故障定位

项目中的 Lua 虚拟机是 GopherLua 是用 Go 语言编写的 Lua 5.1 的虚拟机和编译器。轻量化、性能高。

先看一下这个 registry 是什么,在项目中的解释:

The registry of an LState implements stack storage for calling functions (both Lua and Go functions) and also for temporary variables in expressions. Its storage requirements will increase with callstack usage and also with code complexity.

就是调用函数(包括 lua 和 go)和临时变量的堆栈。

底层源码阅读

来看下 registry 的底层结构

type registry struct {
	array   []LValue
	top     int
	growBy  int
	maxSize int
	alloc   *allocator
	handler registryHandler
}

主要看 arraytop,其中 array 用来保存栈值,top 是用来记录栈顶指针。

然后,我们看一下什么情况下会触发堆栈溢出。

func (rg *registry) Push(v LValue) {
	newSize := rg.top + 1
	// this section is inlined by go-inline
	// source function is 'func (rg *registry) checkSize(requiredSize int) ' in '_state.go'
	{
		requiredSize := newSize
		if requiredSize > cap(rg.array) {
			rg.resize(requiredSize)
		}
	}
	rg.array[rg.top] = v
	rg.top++
}

Push 操作中可以看到,每一次 Push 都会检查栈容量是否足够,如果不够就会触发 resize

func (rg *registry) resize(requiredSize int) { // +inline-start
	newSize := requiredSize + rg.growBy // give some padding
	if newSize > rg.maxSize {
		newSize = rg.maxSize
	}
	if newSize < requiredSize {
		rg.handler.registryOverflow()
		return
	}
	rg.forceResize(newSize)
} // +inline-end

而在 resize 函数中,可以清楚的看到,当栈容量超过 maxSize (默认为 5120)的时候就会触发 registryOverflow 即堆栈溢出。

至此,问题其实已经十分明确了。应该是某些操作压栈之后没有取出,导致堆栈一直堆积,最后导致溢出。

Debug

Debug 的时候发现,每一次虚拟机回收的时候,栈顶指针一直在递增:

前一次回收: 图1

后一次回收: 图2

栈值都是 LNil图3

按照时间推算,agent 的脚本一分钟执行一次,那么堆满一个容量 5120 的虚拟机堆栈,需要 1 天多,4 个虚拟机实例正好就是 5 天左右,完全符合故障现象。

排查问题

接下来,最主要就是找到问题的原因,首先需要明确到底是 go 导致了堆栈堆积还是调用 lua 脚本的时候导致的。

于是,我就写了一个十分简单的 lua 脚本,只 print 一条信息。

结果发现虚拟机回收的时候堆栈依旧在堆积,说明问题大概率出在 go 里。

所以我又仔细回顾了 agent 里虚拟机的执行流程,发现这处代码:

// 调用 run 函数
if err := vm.CallByParam(lua.P{
	Fn:      rfn,
	NRet:    1,
	Protect: true,
}, nil); err != nil {
	log.Logger.Error("call run func failed", zap.Error(err), zap.Any("lua", lname))
}
// 归还虚拟机
luavm.Put(vm)

问题可能就在这里,go 调用 lua 脚本中的 run 方法后将结果压栈了,然后没有进行 POP

run 方法是不返回值的,这也解释了为什么栈值都是 LNil

为了验证这个问题,我将测试脚本中的 run 方法改成了如下:

function run()
    print("uhhhhhhhh")
    return 123
end

然后,再来 Debug 看下堆栈里的情况

图4

果然,类型从 LNil 变成了 LNumber,问题就在这里!

修复

// 调用 run 函数
if err := vm.CallByParam(lua.P{
	Fn:      rfn,
	NRet:    1,
	Protect: true,
}, nil); err != nil {
	log.Logger.Error("call run func failed", zap.Error(err), zap.Any("lua", lname))
}

// 相信我,调用 call 后一定要 pop !!不然一定不会让你失望
vm.Pop(1)
// 归还虚拟机
luavm.Put(vm)

修复这个问题很简单,只需在归还虚拟机前,执行一次 POP。随后虚拟机再回收的时候,就没有栈堆积的情况了。

另外,其实也可以在虚拟机回收的时候做一些资源清理。

总结

多阅读底层实现,多去揪揪问题的本质,一般没有什么解决不了的问题😎