"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)
--- more breakpoints ...

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는 비어 있습니다!

해결 방법

요청 본문을 읽어야 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 수준을 직접 설정한 후 재로딩하지 않습니다. 이는 두 가지 단점이 있습니다:

  • 너무 많은 로그가 생성되어 성능에 영향을 미치고 확인이 어려워집니다.
  • 재로딩으로 인해 지속적인 연결이 끊어져 온라인 트래픽에 영향을 미칩니다.

일반적으로 특정 지점의 로그만 확인하면 됩니다. 예를 들어, 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의 세 번째 매개변수를 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