"inspect": Apache APISIX Lua 动态调试插件

JinHua Luo

January 29, 2023

Technology

Lua動的デバッグプラグインが必要な理由

Apache APISIXには大量のLuaコードが含まれています。ソースコードを変更せずに、実行時にコード内の変数の値を検査する方法はあるでしょうか？

Luaのソースコードをデバッグのために変更することにはいくつかの欠点があります：

  • 本番環境ではソースコードの変更は許可されていないことが多く、また許可すべきではありません
  • ソースコードを変更するとリロードが必要になり、ビジネスプロセスの動作が妨げられます
  • コンテナ化された環境ではソースコードの変更が難しい場合があります
  • 一時的に生成されたコードはロールバック時に省略されやすく、メンテナンス上の問題を引き起こします

通常、変数の値を検査する必要があるのは、関数の開始時や終了時だけでなく、特定の条件が満たされたとき、例えばループがある回数に達したときや特定の条件が真になったときです。また、単に変数の値を出力するだけでは不十分な場合もあり、関連情報を外部システムに送信する必要があることもあります。さらに、このプロセスを動的にする方法や、プログラムのパフォーマンスに悪影響を与えずにこれを行う方法はあるでしょうか？

Lua動的デバッグプラグイン、inspectは、上記の要件を満たすのに役立ちます。

  • カスタマイズ可能なブレークポイント処理
  • 動的なブレークポイント設定
  • 複数のブレークポイントを設定可能
  • ブレークポイントを一度だけトリガーするように設定可能
  • パフォーマンスへの影響を制御し、特定の範囲内に保つことが可能

プラグインの動作原理

このプラグインは、LuaのDebug API機能を活用してその機能を実装しています。インタプリタモードでは、実行される各バイトコードは特定のファイルと行番号にマッピングされます。ブレークポイントを設定するためには、行番号が期待される値と等しいかどうかを確認し、事前に定義したブレークポイント関数を実行するだけで済みます。これにより、対応する行のコンテキスト情報（upvalue、ローカル変数、スタックなどのメタデータ）を処理することができます。

APISIXはLuaのJIT実装であるLuaJITを使用しており、多くのホットコードパスは機械語にコンパイルされて実行されます。しかし、これらはDebug APIの影響を受けないため、ブレークポイントを有効にする前にJITキャッシュをクリアする必要があります。重要なのは、特定のLua関数のJITキャッシュのみをクリアすることを選択できるため、グローバルなパフォーマンスへの影響を最小限に抑えることができる点です。プログラムが実行されると、多くのJITコンパイルされたコードブロックがLuaJITでtraceとして命名されます。これらのトレースはLua関数に関連付けられており、単一のLua関数には複数のトレースが含まれる場合があります。これらは関数内の異なるホットパスを参照しています。

グローバル関数やモジュールレベルの関数については、それらの関数オブジェクトを指定してJITキャッシュをクリアすることができます。しかし、行番号が匿名関数などの他の関数タイプに対応している場合、グローバルに関数オブジェクトを取得することはできません。そのような場合、すべてのJITキャッシュをクリアするしかありません。デバッグ中に新しいトレースは生成されませんが、クリアされていない既存のトレースは引き続き実行されます。十分に制御できれば、プログラムのパフォーマンスに影響はありません。なぜなら、長時間実行されているオンラインシステムでは通常新しいトレースは生成されないからです。デバッグが終了し、すべてのブレークポイントが解除されると、システムは通常のJITモードに戻り、クリアされたJITキャッシュはホットスポットに再入したときに再生成されます。

インストールと設定

このプラグインはデフォルトで有効になっています。

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、トレースをクリアする関数の名前。nilの場合、luajit vm内のすべてのトレースがクリアされます。
  • filter_func、ブレークポイントを処理するカスタムLua関数
    • 入力パラメータは以下の内容を含むtableです：
      • finfo: debug.getinfo(level, "nSlf")の戻り値
      • uv: upvaluesのハッシュテーブル
      • vals: ローカル変数のハッシュテーブル
    • 関数の戻り値がtrueの場合、ブレークポイントは自動的に解除されます。それ以外の場合、ブレークポイントは引き続き有効です。

例：

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)
--- さらにブレークポイント ...

demoブレークポイントは、いくつかの情報を整理して外部サーバーに送信することに注意してください。また、使用されているresty.httpライブラリはcosocketに基づく非同期ライブラリです。

OpenRestyの非同期APIを呼び出すときは、timerを使用して遅延させて送信する必要があります。なぜなら、ブレークポイントで実行される関数は同期処理でありブロッキングされるため、nginxのメインプログラムに戻って非同期処理を行うことができないからです。そのため、遅延させる必要があります。

使用例

リクエストボディの内容に基づいてルートを決定する

次の要件があるとします：リクエストボディに文字列APISIX: 666が含まれるPOSTリクエストのみを受け入れるルートをどのように設定できますか？

ルート設定にはvarsフィールドがあり、nginx変数の値をチェックしてルートがマッチするかどうかを判断するために使用できます。nginxが提供する$request_body変数にはリクエストボディの値が含まれているため、この変数を使用して要件を実装できます。

ルートを設定してみましょう：

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のこの変数のドキュメントを見てみましょう：

この変数の値は、リクエストボディがメモリバッファに読み込まれたときに、proxy_pass、fastcgi_pass、uwsgi_pass、scgi_passディレクティブによって処理される場所で利用可能になります。

つまり、この変数を使用する前にリクエストボディを読み取る必要があります。

ルートをマッチングするとき、この変数は空でしょうか？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行目の変数request_bodyを確認しましょう。これはrouter.router_http.match(api_ctx)です。

ブレークポイントの設定

ファイル/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は空です！

解決策

リクエストボディを読み取る必要があることがわかっているので、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レベルを設定してリロードすることはしません。これには2つの欠点があります：

  • ログが多すぎてパフォーマンスに影響し、確認が難しくなります
  • リロードすると永続的な接続が切断され、オンライントラフィックに影響します

通常、特定のポイントのログを確認するだけで十分です。例えば、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()ですが、etcd watchからの増分データをINFOレベルで出力します。

そこで、inspectプラグインを使用して表示してみましょう。ルートリソースの変更のみを表示します。

/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の3番目のパラメータをnilに設定するしかありません。これにはすべてのトレースをクリアする副作用があります。

上記の例では、シンボリックリンクを作成しているので、編集後にファイルを保存するだけで済みます。ブレークポイントは数秒後に有効になります。ログを確認して確認できます。

ログを確認することで、必要な情報を取得できます。これは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コードを学ぶ

詳細については、関連ドキュメントを参照してください。

Tags:
APISIX Basics
API Gateway Concept
Plugin