"inspect": Plugin de Depuração Dinâmica Lua do Apache APISIX

Por que precisamos do Plugin de Depuração Dinâmica Lua?

O Apache APISIX contém uma quantidade significativa de código Lua. Existe uma maneira de inspecionar os valores das variáveis no código em tempo de execução sem modificar o código-fonte?

Modificar o código-fonte Lua para depuração tem várias desvantagens:

Ambientes de produção não devem e muitas vezes não permitem a modificação do código-fonte
Modificar o código-fonte exige recarregamento, o que interrompe o funcionamento dos processos de negócios
Pode ser desafiador modificar o código-fonte em ambientes conteinerizados
Códigos gerados temporariamente são propensos a serem omitidos para rollback, levando a problemas de manutenção

Geralmente, precisamos inspecionar os valores das variáveis, não apenas quando as funções começam ou terminam, mas também quando condições específicas são atendidas, como quando um loop atinge um certo número de iterações ou quando uma condição específica é verdadeira. Além disso, nem sempre é suficiente simplesmente imprimir os valores das variáveis; pode ser necessário enviar informações relevantes para sistemas externos. Além disso, como tornar esse processo dinâmico e como fazê-lo sem impactar negativamente o desempenho do programa?

O plugin de depuração dinâmica Lua, inspect, ajuda a atender a esses requisitos.

Manipulação de pontos de interrupção personalizáveis
Configuração dinâmica de pontos de interrupção
Vários pontos de interrupção podem ser definidos
Pontos de interrupção podem ser configurados para disparar apenas uma vez
O impacto no desempenho pode ser controlado e mantido dentro de um escopo específico

Princípio de funcionamento do plugin

Ele utiliza totalmente a função Debug API do Lua para implementar seus recursos. Durante o modo de interpretação, cada bytecode executado pode ser mapeado para um arquivo específico e um número de linha. Para definir pontos de interrupção, só precisamos verificar se o número da linha é igual ao valor esperado e executar a função de ponto de interrupção que já definimos. Isso nos permite processar as informações de contexto da linha correspondente, incluindo upvalue, variáveis locais e alguns metadados, como a pilha.

O APISIX usa a implementação JIT do Lua: LuaJIT, onde muitos caminhos de código quente são compilados em código de máquina para execução. No entanto, esses não são afetados pela Debug API, então precisamos limpar o cache JIT antes de ativar os pontos de interrupção. A chave é que podemos escolher limpar apenas o cache JIT de uma função Lua específica, reduzindo o impacto no desempenho global. Quando um programa é executado, muitos blocos de código compilados JIT serão nomeados trace no LuaJIT. Esses traces estão associados a funções Lua, e uma única função Lua pode incluir vários traces, referindo-se a diferentes caminhos quentes dentro da função.

Podemos especificar seus objetos de função e limpar seu cache JIT para funções globais e de nível de módulo. No entanto, se o número da linha corresponder a outros tipos de função, como funções anônimas, não podemos obter o objeto da função globalmente. Nesses casos, só podemos limpar todo o cache JIT. Novos traces não podem ser gerados durante a depuração, mas os traces existentes não limpos continuam a ser executados. Desde que tenhamos controle suficiente, o desempenho do programa não será afetado, pois um sistema online que está em execução há muito tempo geralmente não gera novos traces. Uma vez que a depuração termina e todos os pontos de interrupção são revogados, o sistema retorna ao modo JIT normal, e o cache JIT limpo será regenerado assim que reentrar no ponto quente.

Instalação e configuração

Este plugin é habilitado por padrão.

Configure conf/confg.yaml corretamente para habilitar este plugin:

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

O plugin lê as definições de pontos de interrupção do arquivo '/usr/local/apisix/plugin_inspect_hooks.lua' a cada 3 segundos por padrão. Para depurar, você só precisa editar este arquivo.

Recomendamos criar um link simbólico para este caminho para que seja mais fácil arquivar diferentes versões históricas do arquivo de pontos de interrupção.

Observe que quando o arquivo é modificado, o plugin limpará todos os pontos de interrupção anteriores e habilitará todos os novos pontos de interrupção definidos no arquivo de pontos de interrupção. Esses pontos de interrupção serão efetivos em todos os processos de trabalho.

Geralmente, não é necessário excluir o arquivo, pois ao definir pontos de interrupção, você pode especificar quando revogá-los.

Excluir este arquivo cancelará todos os pontos de interrupção para todos os processos de trabalho.

Os logs de início e parada dos pontos de interrupção serão registrados no nível de log 'WARN'.

Definir pontos de interrupção

require("apisix.inspect.dbg").set_hook(file, line, func, filter_func)

file, o nome do arquivo, que pode ser qualquer nome de arquivo ou caminho não ambíguo.
line, o número da linha no arquivo, observe que os pontos de interrupção estão intimamente ligados aos números de linha, então se o código mudar, o número da linha também deve mudar.
func, o nome da função cujo trace deve ser limpo. Se for nil, então todos os traces na luajit vm serão limpos.
filter_func, uma função Lua personalizada que manipula o ponto de interrupção
- O parâmetro de entrada é chamado table que inclui o seguinte:
  - finfo: o valor de retorno de debug.getinfo(level, "nSlf")
  - uv: tabela hash de upvalues
  - vals: tabela hash de variáveis locais
- Se o valor de retorno da função for true, então o ponto de interrupção será automaticamente revogado. Caso contrário, o ponto de interrupção continuará efetivo.

Por exemplo:

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)
--- mais pontos de interrupção ...

Observe que o ponto de interrupção demo organiza algumas informações e as envia para um servidor externo. Além disso, a biblioteca resty.http usada é uma biblioteca assíncrona baseada em cosocket.

Sempre que chamar a API assíncrona do OpenResty, ela deve ser enviada com um atraso usando timer, pois a execução de funções em pontos de interrupção é síncrona e bloqueante, não retornando ao programa principal do nginx para processamento assíncrono, então precisa ser atrasada.

Casos de uso

Determinar rotas com base no conteúdo do corpo da solicitação

Digamos que temos um requisito: como podemos configurar uma rota que só aceita solicitações POST com a string APISIX: 666 no corpo da solicitação?

Na configuração da rota, há um campo vars, que pode ser usado para verificar o valor das variáveis nginx para determinar se a rota deve ser correspondida. A variável $request_body fornecida pelo nginx contém o valor do corpo da solicitação, então podemos usar essa variável para implementar nosso requisito.

Vamos tentar configurar as rotas:

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
        }
    }
}'

Então podemos tentar isso:

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"}

Estranho, por que não podemos corresponder a esta rota?

Vamos então dar uma olhada na documentação para esta variável no nginx:

O valor da variável é disponibilizado em locais processados pelas diretivas proxy_pass, fastcgi_pass, uwsgi_pass e scgi_pass quando o corpo da solicitação foi lido para um buffer de memória.

Em outras palavras, precisamos primeiro ler o corpo da solicitação antes de usar esta variável.

Ao corresponder a rota, esta variável estará vazia? Podemos usar o plugin inspect para verificar isso.

Encontramos a linha de código que corresponde à rota:

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
...

Vamos verificar a variável request_body na linha 515, que é router.router_http.match(api_ctx).

Configurar pontos de interrupção

Edite o arquivo /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)

Crie um link simbólico para o caminho do arquivo de pontos de interrupção:

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

Verifique os logs para confirmar que o ponto de interrupção está efetivo.

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

Reativar a correspondência de rotas:

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

Verifique os logs:

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"

Claro, request_body está vazio!

Solução

Como sabemos que precisamos ler o corpo da solicitação para usar a variável request_body, então não podemos usar vars para isso. Em vez disso, podemos usar o campo filter_func na rota para atender nosso requisito.

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
        }
    }
}'

Vamos verificar:

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"
}

Problema resolvido!

Imprimir alguns logs que foram bloqueados pelo nível de log.

Em geral, não habilitamos logs de nível INFO em um ambiente de produção, mas às vezes precisamos verificar algumas informações detalhadas. Como podemos fazer isso?

Geralmente, não definimos diretamente o nível INFO e depois recarregamos, pois isso tem duas desvantagens:

Muitos logs, o que afeta o desempenho e aumenta a dificuldade de verificação
O recarregamento faz com que as conexões persistentes sejam desconectadas, afetando o tráfego online

Normalmente, só precisamos verificar os logs de um ponto específico; por exemplo, todos sabemos que o APISIX usa etcd como um banco de dados de distribuição de configuração, então podemos ver quando a configuração da rota é atualizada incrementalmente para o plano de dados? Quais dados específicos foram atualizados?

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

A função Lua para sincronização incremental é sync_data(), mas ela imprime os dados incrementais do watch do etcd no nível INFO.

Então vamos tentar usar o plugin inspect para exibir. Mostraremos apenas as alterações dos recursos de rotas.

Edite /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)

A lógica desta função de processamento de ponto de interrupção indica claramente a capacidade de filtragem. Se a key do watch for /routes, e err estiver vazio, ele imprimirá os dados retornados pelo etcd apenas uma vez, então cancelará o ponto de interrupção.

Observe que sync_data() é uma função local, então não pode ser referenciada diretamente. Nesse caso, só podemos definir o terceiro parâmetro de set_hook como nil, o que tem o efeito colateral de limpar todos os traces.

No exemplo acima, criamos um link simbólico, então só precisamos salvar os arquivos após a edição. Os pontos de interrupção serão habilitados após alguns segundos; você pode verificar o log para confirmar.

Ao verificar o log, podemos obter as informações necessárias, que são impressas no nível de log WARN. Ele também mostra o momento em que obtemos os dados incrementais do etcd no plano de dados.

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

Conclusão

A depuração dinâmica Lua é uma função auxiliar importante. Com o plugin inspect do APISIX, podemos fazer muitas coisas, como:

Solucionar problemas e identificar a causa de problemas
Imprimir alguns logs bloqueados e recuperar várias informações conforme necessário
Aprender código Lua depurando

Por favor, leia estas documentações relacionadas para mais detalhes.