詳解 APISIX Lua 動態除錯外掛 inspect

API7_技術團隊發表於2023-02-17
作者羅錦華,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 努力的目標。

相關文章