详解 APISIX Lua 动态调试插件 inspect

Posted 2023-04-14 apisix

作者罗锦华，API7.ai 技术专家/技术工程师，开源项目 pgcat，lua-resty-ffi，lua-resty-inspect 的作者。

原文链接

为什么需要 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 启用插件：

plugins:
...
  - inspect

plugin_attr:
  inspect:
    delay: 3
    hooks_file: "/usr/local/apisix/plugin_inspect_hooks.lua"

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

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

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

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

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

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

定义断点

require("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，则该断点继续生效

例子：

local dbg = require "apisix.inspect.dbg"

dbg.set_hook("limit-req.lua", 88, require("apisix.plugins.limit-req").access,
function(info)
    ngx.log(ngx.INFO, debug.traceback("foo traceback", 3))
    ngx.log(ngx.INFO, dbg.getname(info.finfo))
    ngx.log(ngx.INFO, "conf_key=", info.vals.conf_key)
    return true
end)

dbg.set_hook("t/lib/demo.lua", 31, require("t.lib.demo").hot2, function(info)
    if info.vals.i == 222 then
        ngx.timer.at(0, function(_, body)
            local httpc = require("resty.http").new()
            httpc:request_uri("http://127.0.0.1:9080/upstream1", 
                method = "POST",
                body = body,
            )
        end, ngx.var.request_uri .. "," .. info.vals.i)
        return true
    end
    return false
end)

--- more breakpoints ...

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

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

使用示例

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

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

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

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

curl http://127.0.0.1:9180/apisix/admin/routes/var_route \\
-H \'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1\' -X PUT -i -d \'

    "uri": "/anything",
    "methods": ["POST"],
    "vars": [["request_body", "~~", "APISIX: 666"]],
    "upstream": 
        "type": "roundrobin",
        "nodes": 
            "httpbin.org": 1
        
    
\'

然后我们尝试一下：

curl http://127.0.0.1:9080/anything
"error_msg":"404 Route Not Found"

curl -i http://127.0.0.1:9080/anything -X POST -d \'hello, APISIX: 666.\'
HTTP/1.1 404 Not Found
Date: Thu, 05 Jan 2023 03:53:35 GMT
Content-Type: text/plain; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Server: APISIX/3.0.0

"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

...
api_ctx.var.request_uri = api_ctx.var.uri .. api_ctx.var.is_args .. (api_ctx.var.args or "")

router.router_http.match(api_ctx)

local route = api_ctx.matched_route
if not route then
...

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

设置断点

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

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

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

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

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

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

再触发一次路由匹配：

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

查看日志：

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

果然，request_body 是空的！

解决方案

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

curl http://127.0.0.1:9180/apisix/admin/routes/var_route \\
-H \'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1\' -X PUT -i -d \'

    "uri": "/anything",
    "methods": ["POST"],
    "filter_func": "function(_) return require(\\"apisix.core\\").request.get_body():find(\\"APISIX: 666\\") end",
    "upstream": 
        "type": "roundrobin",
        "nodes": 
            "httpbin.org": 1
        
    
\'

验证一下：

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

  "args": ,
  "data": "",
  "files": ,
  "form": 
    "hello, APISIX: 666.": ""
  ,
  "headers": 
    "Accept": "*/*",
    "Content-Length": "19",
    "Content-Type": "application/x-www-form-urlencoded",
    "Host": "127.0.0.1",
    "User-Agent": "curl/7.68.0",
    "X-Amzn-Trace-Id": "Root=1-63b64dbd-0354b6ed19d7e3b67013592e",
    "X-Forwarded-Host": "127.0.0.1"
  ,
  "json": null,
  "method": "POST",
  "origin": "127.0.0.1, xxx",
  "url": "http://127.0.0.1/anything"

问题解决！

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

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

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

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

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

apisix/core/config_etcd.lua

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

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

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

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

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

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

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

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

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

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

结论

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

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

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

关于 API7.ai 与 APISIX

API7.ai 是一家提供 API 处理和分析的开源基础软件公司，于 2019 年开源了新一代云原生 API 网关 -- APISIX 并捐赠给 Apache 软件基金会。此后，API7.ai 一直积极投入支持 Apache APISIX 的开发、维护和社区运营。与千万贡献者、使用者、支持者一起做出世界级的开源项目，是 API7.ai 努力的目标。

记一次apisix编译报错：size of C type is unknown or too large at line 39, context: init_worker_by_lua*

问题描述

apisix(2.13版本)在启动时会报插件加载失败的错误，且每次加载失败的插件都不太一样；

定位思路

检查环境

看报错信息，感觉像是C类型未知，或者C类型过大

但是检查代码本身感觉没问题，hmac.lua代码如下：

local str_util = require "resty.string"
local to_hex = str_util.to_hex
local ffi = require "ffi"
local ffi_new = ffi.new
local ffi_str = ffi.string
local ffi_gc = ffi.gc
local ffi_typeof = ffi.typeof
local C = ffi.C
local setmetatable = setmetatable
local error = error


local _M =  _VERSION = '0.04' 

local mt =  __index = _M 


ffi.cdef[[
typedef struct engine_st ENGINE;
typedef struct evp_pkey_ctx_st EVP_PKEY_CTX;
typedef struct evp_md_ctx_st EVP_MD_CTX;
typedef struct evp_md_st EVP_MD;
typedef struct hmac_ctx_st HMAC_CTX;

//OpenSSL 1.0
void HMAC_CTX_init(HMAC_CTX *ctx);
void HMAC_CTX_cleanup(HMAC_CTX *ctx);

//OpenSSL 1.1
HMAC_CTX *HMAC_CTX_new(void);
void HMAC_CTX_free(HMAC_CTX *ctx);

int HMAC_Init_ex(HMAC_CTX *ctx, const void *key, int len, const EVP_MD *md, ENGINE *impl);
int HMAC_Update(HMAC_CTX *ctx, const unsigned char *data, size_t len);
int HMAC_Final(HMAC_CTX *ctx, unsigned char *md, unsigned int *len);

const EVP_MD *EVP_md5(void);
const EVP_MD *EVP_sha1(void);
const EVP_MD *EVP_sha256(void);
const EVP_MD *EVP_sha512(void);
]]

2、怀疑是不是内存不足导致的

查看CPU内存使用情况：

查看磁盘使用情况：

如上所示，CPU内存磁盘的使用率都不高，资源肯定够用的

检查报错插件的共同点

1、测试多次发现，报错的插件虽然会变，但是只在如下几个插件之间变化：

• hmac-auth
• jwt-auth
• rocketmq-logger
• google-cloud-logging
• aws-lambda

2、将以上插件暂时停用，发现apisix启动不再报错；

• 停用以上插件，修改config-default.yaml文件，将以上插件注释掉；
• 重启apisix，启动不再报错；

3、分析以上插件的共同点
查看以上插件的源码，发现最终都依赖了hmac.lua文件，还是要定位hmac.lua文件本身；

local hmac       = require("resty.hmac")

定位hmac.lua

定位到这里，知道是hmac.lua文件有问题，但是又不知道哪里出了问题。只能查看github，地址如下：
https://github.com/jkeys089/lua-resty-hmac

1、查看hmac.lua文件修改记录，发现在0.04版本之后，只有一次代码发生大的变动：https://github.com/jkeys089/lua-resty-hmac/pull/20/files

2、检查本次PR解决的问题，发现一个issue，解决的问题就是我报的错误：
https://github.com/jkeys089/lua-resty-hmac/issues/19

3、查看报错原因

this appears to be an issue with 1) when using openssl 1.0.x and 2) use with other libraries that explictly typedef EVP_MD_CTX to env_md_ctx_st and they are loaded before this library (from what i can see it’s the case for evp.lua from lua-resty-jwt and aes.lua from lua-resty-string)
一个可能是openssl版本问题；还有个可能是hmac.lua使用的EVP_MD_CTX结构体，在该库之前加载了；

解决方案

将hmac.lua最新版本的代码拷贝到/home/apisix-2.13.1/deps/share/lua/5.1/resty/目录下，替换掉老的hmac.lua，重新启动apisix，问题解决；