Apache APISIX Lua 动态调试插件（inspect）详解

更新时间 1/20/2023

为什么需要 Lua 动态调试插件？

Apache APISIX 有很多 Lua 代码，如何在运行时不触碰源代码的情况下，检查代码里面的变量值？

修改 Lua 源码来调试有如下缺点：

  • 生产环境不允许也不应该修改源码
  • 修改源码需要 reload，使得业务功能失效
  • 容器环境难以修改源码
  • 产生的临时代码容易忘记回滚，导致维护问题

很多时候我们不仅仅需要在函数开始或结束的时候去检查变量，而且需要在满足一定条件，例如某个循环体被循环到了一定次数， 或者某个条件判断为真的时候我们才查看变量值，并且也不仅仅是简单打印变量值，有时候还可能需要将相关信息发送到外围系统。 并且，这个过程如何做到动态化呢？而且，开启调试后，能否不影响程序运行的性能呢？

Lua 动态调试插件就是辅助你完成以上需求的插件，该插件被命名为 inspect 插件。

  • 断点处理可定制
  • 断点设置动态化
  • 多个断点
  • 断点可被定义为只生效一次
  • 可控制性能影响范围

插件原理

它充分利用了 Lua 提供的 Debug API 来实现功能。解释器模式执行的每一个字节码都可以对应到它所属的文件以及行号，我们只需要判断行号是否等于期望值，然后执行我们定义的断点函数，对该行对应的上下文信息，包括 upvalue ，局部变量，还有一些元信息，例如堆栈，进行处理即可。

APISIX 使用的是 Lua 的 JIT 实现：LuaJIT，很多热点代码路径会被编译成机器码执行，而它们是不受 Debug API 的影响的，所以我们需要在开启断点前清空 JIT 缓存。关键就在这里了，我们可以选择只清空某个具体 Lua 函数的 JIT 缓存，减小对全局性能的影响。一个程序运行起来，会有很多 JIT 编译代码块，在 LuaJIT 里被称为 trace，这些 trace 跟 Lua 函数是关联起来的，一个 Lua 函数可能包括多个 trace ，指代函数内不同的热点路径。

对于全局函数、模块级别的函数，我们可以指定它们的函数对象，清空它们的 JIT 缓存。但是如果某行号对应的是其他函数类型，例如匿名函数，我们无法在全局获取函数的对象，那么只能清空所有 JIT 缓存了。在调试开启期间，新的 trace 无法被生成，但是已有的未被清理的 trace 还继续运行，所以只要控制的好，程序性能不会受到影响，因为一个已经运行很久的线上系统，基本不会有新 trace 的生成。当调试结束后，也就是所有断点都被撤销后，系统会恢复正常的 JIT 模式，被清理掉的 JIT 缓存，一旦重新进入热点，会被重新生成 trace。

安装与配置

该插件默认被启用。

配置好 conf/confg.yaml 启用插件：

1plugins:
2...
3  - inspect
4
5plugin_attr:
6  inspect:
7    delay: 3
8    hooks_file: "/usr/local/apisix/plugin_inspect_hooks.lua"

插件默认每隔3秒从文件 /usr/local/apisix/plugin_inspect_hooks.lua 读取断点定义，想调试就编辑该文件即可。

建议创建软链接到该路径，这样比较方便地存档不同历史版本的断点文件。

注意每次该文件的更改时间有变，插件会清空所有旧的断点，并且启用断点文件所定义的所有新断点。断点将在所有工作进程生效。

一般情况下不需要删除该文件，因为定义断点的时候，可以定义什么时候撤销断点。

删除文件会取消所有工作进程的所有断点。

断点的启停都会通过 WARN 日志级别打印日志。

定义断点

1require("apisix.inspect.dbg").set_hook(file, line, func, filter_func)
  • file 文件名，可以是任何无歧义的文件名部分，可包含路径
  • line 文件的行号，注意断点跟行号是密切挂钩的，所以如果代码变了，行号就得跟着变。
  • func 要清除哪个函数的 trace，如果为 nil，则清除 luajit vm 里面所有 trace
  • filter_func 处理该断点的自定义 Lua 函数
    • 函数的入参为一个 table，包含以下内容
      • finfo: debug.getinfo(level, "nSlf")的返回值
      • uv: upvalues hash table
      • vals: local variables hash table
    • 函数的返回值为 true，则该断点自动注销，返回为 false，则该断点继续生效

例子：

1local dbg = require "apisix.inspect.dbg"
2
3dbg.set_hook("limit-req.lua", 88, require("apisix.plugins.limit-req").access,
4function(info)
5    ngx.log(ngx.INFO, debug.traceback("foo traceback", 3))
6    ngx.log(ngx.INFO, dbg.getname(info.finfo))
7    ngx.log(ngx.INFO, "conf_key=", info.vals.conf_key)
8    return true
9end)
10
11dbg.set_hook("t/lib/demo.lua", 31, require("t.lib.demo").hot2, function(info)
12    if info.vals.i == 222 then
13        ngx.timer.at(0, function(_, body)
14            local httpc = require("resty.http").new()
15            httpc:request_uri("http://127.0.0.1:9080/upstream1", {
16                method = "POST",
17                body = body,
18            })
19        end, ngx.var.request_uri .. "," .. info.vals.i)
20        return true
21    end
22    return false
23end)
24
25--- more breakpoints ...

注意到 demo 这个断点，它将一些信息整理后发送到外部的服务器上，使用的 resty.http 库是基于 cosocket 的异步库。

凡是调用 OpenResty 的异步 API ，必须使用 timer 延迟发送，因为在断点上执行函数是同步阻塞的，不会再返回到 nginx 的主程序做异步处理，所以需要延后发送。

使用示例

根据请求体的内容来决定路由

假设我们有个需求，如何设置让某个路由仅接受请求体中携带了 APISIX: 666 的 POST 请求？

路由配置里面有个 vars 字段，是用来检查 nginx 变量的值来判断是否匹配该路由的， 而 $request_body 则是 nginx 提供的变量，包含请求体的值，那我们可以利用这个变量来实现我们的需求？

让我们来尝试一下，先配置一下路由：

1curl http://127.0.0.1:9180/apisix/admin/routes/var_route \
2-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -i -d '
3{
4    "uri": "/anything",
5    "methods": ["POST"],
6    "vars": [["request_body", "~~", "APISIX: 666"]],
7    "upstream": {
8        "type": "roundrobin",
9        "nodes": {
10            "httpbin.org": 1
11        }
12    }
13}'

然后我们尝试一下：

1curl http://127.0.0.1:9080/anything
2{"error_msg":"404 Route Not Found"}
3
4curl -i http://127.0.0.1:9080/anything -X POST -d 'hello, APISIX: 666.'
5HTTP/1.1 404 Not Found
6Date: Thu, 05 Jan 2023 03:53:35 GMT
7Content-Type: text/plain; charset=utf-8
8Transfer-Encoding: chunked
9Connection: keep-alive
10Server: APISIX/3.0.0
11
12{"error_msg":"404 Route Not Found"}

奇怪，为什么匹配不上这个路由呢？

我们再查看一下 NGINX 对该变量的文档说明：

The variable’s value is made available in locations processed by the proxy_pass, fastcgi_pass, uwsgi_pass, and scgi_pass directives when the request body was read to a memory buffer.

也就是说，使用该变量前需要先读取 request body 。

那是不是匹配路由的时候，这个变量为空呢？我们可以使用 inspect 插件来验证一下。

我们找到了匹配路由的代码行：

apisix/init.lua

1...
2api_ctx.var.request_uri = api_ctx.var.uri .. api_ctx.var.is_args .. (api_ctx.var.args or "")
3
4router.router_http.match(api_ctx)
5
6local route = api_ctx.matched_route
7if not route then
8...

我们就在 515 行，也就是 router.router_http.match(api_ctx) 这行验证一下变量 request_body 吧。

设置断点

编辑文件 /usr/local/apisix/example_hooks.lua：

1local dbg = require("apisix.inspect.dbg")
2dbg.set_hook("apisix/init.lua", 515, require("apisix").http_access_phase, function(info)
3    core.log.warn("request_body=", info.vals.api_ctx.var.request_body)
4    return true
5end)

创建软链接到断点文件路径：

1ln -sf /usr/local/apisix/example_hooks.lua /usr/local/apisix/plugin_inspect_hooks.lua

检查日志看看确认断点生效：

12023/01/05 12:02:43 [warn] 1890559#1890559: *15736 [lua] init.lua:68: setup_hooks():
2set hooks: err: true, hooks: ["apisix\/init.lua#515"], context: ngx.timer

再触发一次路由匹配：

1curl -i http://127.0.0.1:9080/anything -X POST -d 'hello, APISIX: 666.'

查看日志：

12023/01/05 12:02:59 [warn] 1890559#1890559: *16152
2[lua] [string "local dbg = require("apisix.inspect.dbg")..."]:39:
3request_body=nil, client: 127.0.0.1, server: _,
4request: "POST /anything HTTP/1.1", host: "127.0.0.1:9080"

果然，request_body 是空的！

解决方案

既然我们知道需要读取请求体才能用 request_body 变量，那么我们就不能通过 vars 来做了，那我们可以通过路由里面的 filter_func 字段来实现需求。

1curl http://127.0.0.1:9180/apisix/admin/routes/var_route \
2-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -i -d '
3{
4    "uri": "/anything",
5    "methods": ["POST"],
6    "filter_func": "function(_) return require(\"apisix.core\").request.get_body():find(\"APISIX: 666\") end",
7    "upstream": {
8        "type": "roundrobin",
9        "nodes": {
10            "httpbin.org": 1
11        }
12    }
13}'

验证一下：

1curl http://127.0.0.1:9080/anything -X POST -d 'hello, APISIX: 666.'
2{
3  "args": {},
4  "data": "",
5  "files": {},
6  "form": {
7    "hello, APISIX: 666.": ""
8  },
9  "headers": {
10    "Accept": "*/*",
11    "Content-Length": "19",
12    "Content-Type": "application/x-www-form-urlencoded",
13    "Host": "127.0.0.1",
14    "User-Agent": "curl/7.68.0",
15    "X-Amzn-Trace-Id": "Root=1-63b64dbd-0354b6ed19d7e3b67013592e",
16    "X-Forwarded-Host": "127.0.0.1"
17  },
18  "json": null,
19  "method": "POST",
20  "origin": "127.0.0.1, xxx",
21  "url": "http://127.0.0.1/anything"
22}
23

问题解决！

打印一些被日志级别屏蔽的日志

生产环境一般不会开启 INFO 级别的日志，但是有时候我们又需要检查一些详细信息，那怎么办呢？

我们一般不会直接设置 INFO 级别然后 reload，因为这样做有两个缺点：

  • 日志太多，影响性能和加大检查难度
  • reload 导致长连接被断开，影响在线流量

一般我们只需要检查具体某个点的日志，例如我们都知道 APISIX 使用 etcd 作为配置分发数据库，那么可否看看什么时候路由配置被增量更新到了数据面呢？更新了什么具体数据呢？

apisix/core/config_etcd.lua

1local function sync_data(self)
2...
3    log.info("waitdir key: ", self.key, " prev_index: ", self.prev_index + 1)
4    log.info("res: ", json.delay_encode(dir_res, true), ", err: ", err)
5...
6end

增量同步的lua函数是 sync_data()，但是它是通过 INFO 级别来打印从 etcd watch 到的增量数据的。

那么我们来试一下使用 inspect plugin 来显示一下？只显示路由资源的变化。

编辑 /usr/local/apisix/example_hooks.lua ：

1local dbg = require("apisix.inspect.dbg")
2local core = require("apisix.core")
3dbg.set_hook("apisix/core/config_etcd.lua", 393, nil, function(info)
4    local filter_res = "/routes"
5    if info.vals.self.key:sub(-#filter_res) == filter_res and not info.vals.err then
6        core.log.warn("etcd watch /routes response: ", core.json.encode(info.vals.dir_res, true))
7        return true
8    end
9    return false
10end)

这个断点处理函数的逻辑很好表达了过滤能力，如果 watch 的 key 是 /routes，以及 err 为空的情况下，就打印 etcd 返回的数据，并且打印一次就够了，就取消断点。

注意 sync_data() 是局部函数，所以无法获取它的引用，我们只能设置 set_hook 的第三个参数为 nil，这样做的副作用就是它会清空所有 trace。

上面例子我们已经创建了软链接，所以编辑后保存文件即可。等几秒钟后，断点就会被启用，可观察日志确认。

检查日志，我们可以得到我们需要的信息，而这些信息用 WARN 日志级别打印，并且也显示了我们在数据面获取到 etcd 增量数据的时间。

12023/01/05 14:33:10 [warn] 1890562#1890562: *231311
2[lua] [string "local dbg = require("apisix.inspect.dbg")..."]:41:
3etcd watch /routes response: {"headers":{"X-Etcd-Index":"24433"},
4"body":{"node":[{"value":{"uri":"\/anything",
5"plugins":{"request-id":{"header_name":"X-Request-Id","include_in_response":true,"algorithm":"uuid"}},
6"create_time":1672898912,"status":1,"priority":0,"update_time":1672900390,
7"upstream":{"nodes":{"httpbin.org":1},"hash_on":"vars","type":"roundrobin","pass_host":"pass","scheme":"http"},
8"id":"reqid"},"key":"\/apisix\/routes\/reqid","modifiedIndex":24433,"createdIndex":24429}]}}, context: ngx.timer

结论

Lua 动态调试是很重要的辅助功能。我们可以通过 APISIX inspect 插件来做很多事情，例如：

  • 排查问题，定位原因
  • 打印一些被屏蔽的日志，按需获取各种信息
  • 通过调试来学习 Lua 代码

更多详情请查阅相关文档介绍。

微信咨询

获取方案