詳解 APISIX Lua 動態除錯插件 inspect-有解無憂

作者羅蕉訓，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 努力的目標，

轉載請註明出處，本文鏈接：https://www.uj5u.com/ruanti/550164.html

標籤：其他

上一篇：詳解 APISIX Lua 動態除錯插件 inspect

下一篇：03裝飾者模式