"inspect": Плагин для динамической отладки Lua в Apache APISIX

Зачем нужен плагин для динамической отладки Lua?

Apache APISIX содержит значительное количество кода на Lua. Есть ли способ проверить значения переменных в коде во время выполнения без изменения исходного кода?

Изменение исходного кода Lua для отладки имеет несколько недостатков:

• В производственных средах не рекомендуется и часто запрещено изменять исходный код
• Изменение исходного кода требует перезагрузки, что нарушает работу бизнес-процессов
• Может быть сложно изменить исходный код в контейнеризованных средах
• Временные изменения кода могут быть забыты при откате, что приводит к проблемам с поддержкой

Обычно нам нужно проверять значения переменных не только в начале или конце функций, но и при выполнении определенных условий, например, когда цикл достигает определенного числа итераций или когда выполняется конкретное условие. Кроме того, просто вывести значения переменных может быть недостаточно; иногда необходимо отправить соответствующую информацию во внешние системы. Более того, как сделать этот процесс динамическим и можно ли это сделать без негативного влияния на производительность программы?

Плагин для динамической отладки Lua, inspect, помогает выполнить вышеуказанные требования.

• Настраиваемая обработка точек останова
• Динамическая установка точек останова
• Можно установить несколько точек останова
• Точки останова могут быть настроены на срабатывание только один раз
• Влияние на производительность можно контролировать и удерживать в определенных пределах

Принцип работы плагина

Он полностью использует функцию Debug API Lua для реализации своих возможностей. В режиме интерпретатора каждый выполненный байткод может быть сопоставлен с конкретным файлом и номером строки. Чтобы установить точки останова, нам нужно только проверить, совпадает ли номер строки с ожидаемым значением, и выполнить заранее определенную функцию точки останова. Это позволяет нам обрабатывать контекстную информацию соответствующей строки, включая upvalue, локальные переменные и некоторые метаданные, такие как стек.

APISIX использует реализацию JIT Lua: LuaJIT, где многие горячие пути кода компилируются в машинный код для выполнения. Однако они не подвержены влиянию Debug API, поэтому нам нужно очистить кеш JIT перед включением точек останова. Ключевой момент заключается в том, что мы можем выбрать очистку кеша JIT только для конкретной функции Lua, уменьшая влияние на общую производительность. Когда программа выполняется, многие JIT-скомпилированные блоки кода будут называться trace в LuaJIT. Эти трассы связаны с функциями 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"

Плагин считывает определения точек останова из файла '/usr/local/apisix/plugin_inspect_hooks.lua' каждые 3 секунды по умолчанию. Для отладки вам нужно только редактировать этот файл.

Мы рекомендуем создать символическую ссылку на этот путь, чтобы было проще архивировать различные исторические версии файла точек останова.

Обратите внимание, что при изменении файла плагин очистит все предыдущие точки останова и включит все новые точки останова, определенные в файле точек останова. Эти точки останова будут действовать для всех рабочих процессов.

Обычно нет необходимости удалять файл, так как при определении точек останова можно указать, когда их отменять.

Удаление этого файла отменит все точки останова для всех рабочих процессов.

Логи начала и остановки точек останова будут записаны на уровне логов '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.

При вызове асинхронного API OpenResty он должен быть отправлен с задержкой с использованием timer, так как выполнение функций на точках останова является синхронным и блокирующим, оно не вернется в основную программу nginx для асинхронной обработки, поэтому необходимо использовать задержку.

Примеры использования

Определение маршрутов на основе содержимого тела запроса

Предположим, у нас есть требование: как мы можем настроить маршрут, который принимает только POST-запросы со строкой APISIX: 666 в теле запроса?

В конфигурации маршрута есть поле 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:

Значение переменной становится доступным в местах, обрабатываемых директивами 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
...

Давайте проверим переменную request_body в строке 515, которая является 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)

Логика этой функции обработки точки останова ясно указывает на возможность фильтрации. Если key watch — это /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 — это важная вспомогательная функция. С плагином inspect APISIX мы можем делать многое, например:

• Устранение неполадок и определение причин проблем
• Вывод некоторых заблокированных логов и получение различной информации по мере необходимости
• Изучение кода Lua через отладку

Пожалуйста, прочитайте связанную документацию для получения более подробной информации.