История о Coredump, связанная с NGINX ctx и error_page

Coredumps в производственной среде пугают инженеров, особенно когда сбои происходят посреди ночи. Я сам столкнулся с этим более десяти лет назад. Пытаясь найти этот "призрачный" баг, который появлялся только ночью, вся команда уходила домой спать днем и возвращалась в офис в 12 ночи, чтобы дождаться сбоя и проверить каждую службу по очереди. Представьте себе темную ночь и офисное здание, где горит только несколько рабочих станций, наблюдая за постоянно пульсирующим монитором с данными и логами — это был напряженный и захватывающий опыт. Мы провели три ночи, прежде чем нашли баг и устранили его, что стало незабываемым опытом.

Мы и не подозревали, что столкнемся с этим снова. Только на этот раз это была не наша собственная служба, а онлайн-сервис клиента, который столкнулся с coredump. Это было сложнее, чем наша собственная контролируемая среда:

• Ошибка возникала только в производственной среде пользователя, и пользователь не мог воспроизвести ошибку даже в своей предпродукционной и тестовой средах.
• У пользователя был собственный код поверх открытого исходного кода Apache APISIX, который не был виден до подписания отдельного NDA.
• Нельзя было добавить отладочные логи.
• Ошибка возникала только в 3 часа ночи, что требовало дополнительных ресурсов от клиента для немедленного устранения.

Короче говоря, эту проблему невозможно было воспроизвести, не было полного исходного кода и среды для тестирования. Однако нам нужно было найти ошибку, найти способ воспроизвести ее и в конечном итоге предоставить исправление. В процессе мы столкнулись с множеством трудностей и многому научились. Здесь мы публикуем некоторые интересные моменты, с которыми столкнулись во время отладки. Надеюсь, они помогут при отладке NGINX и APISIX.

Описание проблемы

После того, как пользователь обновил APISIX с версии 2.4.1 до версии 2.13.1, начали циклически происходить coredumps с следующим сообщением об ошибке:

Из сообщения coredump видно, что ошибка сегментации происходит в lua-var-nginx-module. Вот соответствующие данные (частично) в памяти:

#0  0x00000000005714d4 in ngx_http_lua_var_ffi_scheme (r=0x570d700, scheme=0x7fd2c241a760)
    at /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c:152
152        /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c: No such file or directory.
(gdb) print *r
$1 = {signature = 0, connection = 0x0, ctx = 0x15, main_conf = 0x5adf690, srv_conf = 0x0, loc_conf = 0x0, read_event_handler = 0xe, write_event_handler = 0x5adf697,
  cache = 0x2, upstream = 0x589c15, upstream_states = 0x0, pool = 0x0, header_in = 0xffffffffffffffff}

Мы видим, что данные в памяти имеют проблему.

Некоторые мысли перед анализом

Ошибка сегментации обычно возникает в двух сценариях:

1. Чтение/запись по недопустимому адресу в памяти, например, доступ к индексу массива за пределами границ, ошибка сегментации возникает немедленно.
2. Выполнение недопустимой записи, но изменение допустимого адреса, поэтому ошибка сегментации не возникает немедленно. Во время выполнения программы происходит попытка доступа к данным по ошибочному адресу, что вызывает ошибку сегментации. Например, когда значение указателя изменяется ошибочно, позже, когда мы обращаемся к этому указателю, это может вызвать ошибку сегментации.

Для первого сценария проблему легко локализовать, если проверить стек вызовов.

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

• Текущие детали конфигурации APISIX.
• Этап обработки текущего запроса.
• Детали текущего запроса.
• Количество одновременных соединений.
• Лог ошибок.

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

Анализ

1. Проверка контекста ошибок

После тщательного анализа мы обнаружили, что ошибка обычно возникает между 3 и 4 часами утра, с следующим сообщением coredump:

В конечном итоге мы поняли, что лог ошибок связан с действиями пользователя. По определенным причинам все сообщения upstream очищались в это время. Поэтому мы предположили, что проблема связана с операциями очистки/сброса upstream, и coredump может быть вызван переходом в исключительную ветвь после возврата ошибки.

2. Получение стека вызовов Lua

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

1. В библиотеке lua-var-nginx-module добавить код для вывода стека вызовов (print(debug.traceback(...)). Недостаток в том, что это создаст много логов ошибок, что негативно скажется на производственной среде.
2. Использовать openresty-gdb-utils, поддерживаемый API7.ai, этот инструментарий использует DSL GDB и расширение Python для улучшения способности GDB анализировать стек вызовов Lua. Обратите внимание, вам нужно будет включить символы отладки во время компиляции. По умолчанию они включены в APISIX.

Затем мы получили следующий стек вызовов.

Объединив оба стека вызовов Lua и C, мы смогли обнаружить, что coredump произошел из-за того, что пользователь вызвал ngx.ctx.api_ctx.var.scheme в плагине Prometheus. Однако причина сбоя все еще была неясна, нам нужно было провести дальнейший анализ.

3. Кэш вызвал проблему

Ошибка возникла при доступе к переменной из ngx.ctx.api_ctx.var, что вызвало вызов в lua-var-nginx-module, описанный выше. Для повышения эффективности он кэшировал текущий запрос. Мы помнили, что ошибка возникала, когда значение тела запроса имело исключение, поэтому действительность кэшированного запроса также была под вопросом. Чтобы проверить эту мысль, мы остановили программу от использования кэшированной памяти, но каждый раз заново получали запрос.

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._request change to nil
end

Пользователь протестировал эту измененную версию всю ночь, и ошибка больше не возникала; мы подтвердили, что проблема была в теле запроса.

4. Ошибка в ngx.ctx

Кэшированное тело запроса сохранялось в ngx.ctx, и единственное место, где изменялся ngx.ctx, находилось в apisix/init.lua.

function _M.http_header_filter_phase()
    if ngx_var.ctx_ref ~= '' then
        -- prevent for the table leak
        local stash_ctx = fetch_ctx()

        -- internal redirect, so we should apply the ctx
        if ngx_var.from_error_page == "true" then
            ngx.ctx = stash_ctx          <================= HERE
        end
    end

    core.response.set_header("Server", ver_header)

    local up_status = get_var("upstream_status")
    if up_status then
        set_resp_upstream_status(up_status)
    end

Почему нам нужно было восстанавливать ngx.ctx здесь? Потому что ngx.ctx хранится в реестре Lua, и соответствующий ngx.ctx можно найти через индекс реестра. И этот индекс хранился в члене ctx структуры запроса NGINX. Каждый раз, когда происходило внутреннее перенаправление, NGINX очищал ctx, и поэтому индекс не мог быть найден.

Чтобы решить эту проблему, APISIX создал таблицу, которая сохраняла текущий ngx.ctx перед перенаправлением, а затем использовала ngx.var для записи индекса ngx.ctx в этой таблице, и всякий раз, когда его нужно было восстановить, мы могли получить ngx.ctx напрямую из таблицы.

Код на приведенном выше рисунке срабатывал только тогда, когда пользователь настраивал инструкции error_page, и после ошибки после внутренних перенаправлений.

И мы точно знали, что пользователь включил инструкцию error_page после обновления версии, в сочетании с ошибкой, возникшей из-за изменения upstream, описанного выше. Все вещи, казалось, были связаны. Было ли это на самом деле ngx.ctx, который создал баг во время обработки ошибки?

5. Почему ngx.ctx имеет баг

С этим вопросом мы проверили код, связанный с резервным копированием ngx.ctx, и обнаружили более странные проблемы. После неудачи в set_upstream, он никогда не выполнял шаг восстановления ngx.ctx, потому что он завершался раньше, он не создавал резервную копию ngx.ctx, и он не переходил к процессу восстановления.

Это явно был баг! Ну, это потому, что ngx.ctx нужно было восстановить после перенаправления. И как этот процесс восстанавливал ngx.ctx? Где именно ngx.ctx пошел не так? Теперь было слишком много неопределенностей, нам нужно было собрать больше данных.

После обсуждения мы добавили второй лог в производственной среде, и обнаружили, что, когда ошибка возникала после внутреннего перенаправления, ngx.ctx не проходил процесс восстановления, а вызывал coredump напрямую!

Это было озадачивающее явление, потому что если ngx.ctx не восстанавливался после перенаправления, ngx.ctx был бы пустым/null. И был код, который проверял пустые значения; он не должен был вызывать код coredump в плагине.

local function common_phase(phase_name)
    local api_ctx = ngx.ctx.api_ctx
    if not api_ctx then              <============ HERE
        return
    end

    plugin.run_global_rules(api_ctx, api_ctx.global_rules, phase_name)

Так было ли это внутреннее перенаправление error_page, которое вызвало проблему с ngx.ctx?

6. Предварительный вывод

После анализа и проверки мы получили базовое понимание ошибочного процесса.

set_upstream завершился неудачей и перенаправил на этап обработки ошибки error_page, и ожидаемый пустой ngx.ctx имел неожиданное значение. И из-за бага APISIX, он не восстанавливал ngx.ctx перед перенаправлением, что приводило к тому, что ngx.ctx имел грязные данные при доступе, вызывая coredump. Чтобы решить эту проблему, нам нужно было только восстановить ngx.ctx после перенаправления; подробная реализация этого коммита приведена в конце статьи для справки.

Хотя мы предоставили исправление для бага, мы все еще не могли понять полную логику бага. Поскольку пользователь не изменял логику ngx.ctx, открытая версия должна была быть способна воспроизвести. Чтобы не продолжать влиять на производственную среду и процесс развертывания пользователя, мы решили продолжить расследование корневой причины.

7. Успешное воспроизведение

Из того, что мы знали, мы не могли воспроизвести проблему. После анализа мы решили проверить два следующих места:

• Были ли у внутреннего перенаправления специальные ветви для обработки?
• Были ли у ngx.ctx специальные ветви для обработки?

Для первого пункта, во время обработки каждого модуля фильтра NGINX, у него могут быть некоторые исключительные ветви, которые влияют на члены ctx тела запроса, тем самым влияя на ngx.ctx. Мы проверили модули пользователя, скомпилированные в NGINX, на наличие потенциальных исключительных ветвей, но не нашли подобных проблем.

Для второго пункта, после расследования мы обнаружили, что во время SSL-рукопожатия ngx.ctx имеет проблему с повторным использованием. Если этап HTTP не мог получить ngx.ctx, он пытался получить его из этапа SSL. Этап SSL имеет свой собственный ngx.ctx, и это могло вызвать проблемы для ngx.ctx.

На основе вышеуказанных открытий мы разработали следующие условия и смогли успешно воспроизвести проблему:

1. Та же версия APISIX, что и у пользователя.
2. Включить SSL-сертификат.
3. Создать внутреннюю ошибку, которая вызывает error_page (например, запрос upstream, когда его нет).
4. Долгое соединение.
5. Плагин Prometheus (coredump произошел в плагине для пользователя).

Мы наконец сделали кирпичи без соломы. Через догадки и проверки мы наконец выяснили полный процесс этого бага. Как только есть полное воспроизведение, решить проблему уже не сложно, и окончательный процесс здесь подробно описываться не будет. Я уверен, что у всех есть достаточно опыта в проблемах, которые можно точно воспроизвести.

Итог

Корневая причина этой проблемы: потому что ngx.ctx не восстанавливается после входа в error_page, все запросы на долгом соединении повторно используют тот же ngx.ctx на этапе SSL. В конечном итоге это приводит к тому, что ngx.ctx имеет грязные данные, и возникает coredump.

В дальнейшем мы также предложили соответствующее решение этой проблемы: убедиться, что ngx.ctx может быть восстановлен нормально после внутреннего перенаправления. Пожалуйста, обратитесь к конкретному PR.

Если ваш APISIX использует функции, связанные с внутренним перенаправлением, такие как error_page, пожалуйста, обновитесь до последней версии как можно скорее.

Написание программ и отладка — это научно строгие задачи, и здесь нет места для двусмысленности. Чтобы решить проблему, нам нужно собрать информацию, отслеживать все потенциальные подсказки, анализировать стек вызовов, а затем выяснить контекст, чтобы воспроизвести ошибку. В конечном итоге проблема решена.