Uma História de Coredump Sobre NGINX ctx e error_page

Coredumps no ambiente de produção são assustadores para os engenheiros, especialmente quando as falhas ocorrem no meio da noite. Eu mesmo vivenciei isso há mais de uma década. Tentando localizar esse bug "fantasma" que só aparecia à noite, toda a equipe foi para casa dormir à tarde e voltou para a empresa à meia-noite para esperar pela falha e verificar cada serviço um por um. Imagine uma noite escura e um prédio de escritórios com apenas algumas estações de trabalho iluminadas, observando o monitor que batia constantemente em busca de dados e logs – uma experiência intensa e emocionante. Ficamos por três noites até localizar o bug e resolvê-lo, uma experiência inesquecível.

Mal sabíamos que passaríamos por isso novamente. Só que desta vez não era nosso próprio serviço, mas o serviço online do cliente que teve um coredump. Isso foi mais desafiador do que nosso próprio ambiente controlável:

• O erro só ocorria no ambiente de produção do usuário, e o usuário não conseguia reproduzir o erro nem em seu ambiente de pré-produção nem no ambiente de teste.
• O usuário tinha código personalizado sobre o Apache APISIX de código aberto, que não era visível até que o NDA fosse assinado separadamente.
• Não era possível adicionar logs de depuração.
• O erro só ocorria às 3h da manhã, exigindo recursos adicionais do cliente para ser tratado imediatamente.

Resumindo, esse problema não podia ser reproduzido, não havia código-fonte completo e nenhum ambiente para testar. No entanto, tivemos que localizar o erro, encontrar uma maneira de reproduzi-lo e fornecer uma correção. Durante o processo, enfrentamos muitos desafios e aprendemos muito com eles. Aqui, estamos compartilhando alguns pontos interessantes encontrados durante o processo de depuração. Espero que eles forneçam alguma orientação quando as pessoas estiverem depurando NGINX e APISIX.

Descrição do Problema

Após o usuário atualizar o APISIX da versão 2.4.1 para a 2.13.1, coredumps ocorreram ciclicamente, com a seguinte mensagem de erro:

A partir da mensagem de coredump, pudemos ver que a falha de segmentação ocorre no lua-var-nginx-module. E aqui estão os dados correspondentes (parciais) na memória:

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

Podemos ver que os dados na memória têm um problema.

Alguns Pensamentos Antes da Análise

Falhas de segmentação geralmente ocorrem em dois cenários:

1. Leitura/escrita em um endereço inválido na memória, como acessar um índice de array fora dos limites, a falha de segmentação ocorre imediatamente.
2. Fazer uma escrita inválida, mas modificar um endereço válido, então não gera uma falha de segmentação imediatamente. Durante a execução do programa, ele tenta acessar dados no endereço defeituoso e gera uma falha de segmentação. Por exemplo, quando o valor de um ponteiro é modificado erroneamente, mais tarde, quando acessamos esse ponteiro, ele pode disparar uma falha de segmentação.

Para o primeiro cenário, o problema pode ser facilmente localizado se verificarmos a pilha de chamadas.

Para o segundo cenário, como não está claro onde o erro ocorre em primeiro lugar, o código que gerou o erro e o código que disparou a falha de segmentação podem não estar no mesmo local, até mesmo completamente não relacionados, tornando difícil a localização. Só poderíamos coletar mais informações de contexto envolvendo a falha, como:

• Detalhes da configuração atual do APISIX.
• O estágio de processamento da solicitação atual.
• Os detalhes da solicitação atual.
• O número de conexões simultâneas.
• O log de erros.

Através dessas informações, tentaríamos encontrar o bug revisando o código e encontrando uma maneira de reproduzir o problema.

Análise

1. Verificação do Contexto dos Erros

Após uma análise cuidadosa, descobrimos que o erro geralmente ocorria entre 3h e 4h da manhã, com a seguinte mensagem de erro de coredump:

Eventualmente, percebemos que o log de erro estava associado a operações do usuário. Por certas razões, todas as mensagens upstream seriam limpas nesse momento. Então, suspeitamos que o problema estava associado a operações de limpeza/redefinição upstream, e o coredump poderia ser causado por entrar em um ramo de exceção após o retorno do erro.

2. Obtenção da Pilha de Chamadas do Lua

Como o GDB não consegue rastrear a pilha de chamadas do Lua, não conseguimos localizar qual chamada produziu o erro. Então, a primeira coisa que precisávamos fazer era obter a pilha de chamadas do Lua; tínhamos dois métodos para obter as pilhas de chamadas:

1. No módulo lua-var-nginx-module, adicionar código para imprimir a pilha de chamadas (print(debug.traceback(...)). A desvantagem é que isso geraria muitos logs de erro, impactando negativamente o ambiente de produção.
2. Usar o openresty-gdb-utils mantido pela API7.ai, este kit de ferramentas usa a DSL do GDB e a extensão python para melhorar a capacidade do gdb de analisar a pilha de chamadas do Lua. Observe, você precisará ativar o símbolo de depuração no tempo de compilação. Ele é incluído por padrão no APISIX.

Então, obtivemos a seguinte pilha de chamadas.

Combinando as pilhas de chamadas do Lua e do C, pudemos descobrir que o coredump ocorreu porque o usuário chamou ngx.ctx.api_ctx.var.scheme no plugin Prometheus. No entanto, a razão da falha ainda não estava clara, precisávamos analisar mais a fundo.

3. O Cache Causou o Problema

O erro ocorreu ao acessar uma variável de ngx.ctx.api_ctx.var que executou uma chamada no lua-var-nginx-module descrito acima. Para aumentar a eficiência, ele armazenou em cache a solicitação atual. Lembramos que o erro ocorreu quando o valor do corpo da solicitação tinha uma exceção, então a validade da solicitação em cache também era questionável. Para verificar essa ideia, impedimos que o programa pegasse a memória em cache, mas reobtivemos a solicitação a cada vez.

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._request alterado para nil
end

O usuário testou com esta versão modificada por uma noite inteira, e o erro não ocorreu novamente; verificamos que o corpo da solicitação tinha um problema.

4. O Erro no ngx.ctx

O corpo da solicitação em cache foi salvo no ngx.ctx, e o único lugar que modificou o ngx.ctx foi em 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          <================= AQUI
        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

Por que precisávamos recuperar o ngx.ctx aqui? Porque o ngx.ctx é armazenado no registro Lua, o ngx.ctx correspondente pode ser encontrado através do índice do registro. E o índice foi armazenado no membro ctx da estrutura de solicitação do NGINX. Toda vez que um redirecionamento interno era feito, o NGINX limpava o ctx, e assim o índice não podia ser encontrado.

Para resolver esse problema, o APISIX criou uma tabela, a tabela salvou o ngx.ctx atual antes de redirecionar, e então usou ngx.var para registrar o índice do ngx.ctx nessa tabela, sempre que precisasse ser restaurado, poderíamos obter o ngx.ctx diretamente da tabela.

O código na figura acima só era acionado quando o usuário configurou instruções error_page, e após um erro ocorrer após redirecionamentos internos.

E sabíamos exatamente que o usuário ativou a instrução error_page após a atualização da versão, combinado com o erro que ocorreu a partir da mudança upstream que descrevemos acima. Todas as coisas pareciam estar conectadas. Será que foi realmente o ngx.ctx que criou o bug durante o processo de tratamento de erros?

5. Por que o ngx.ctx Tem um Bug

Com a pergunta, verificamos o código relacionado ao backup do ngx.ctx, e encontramos problemas mais estranhos. Após falhar no set_upstream, ele nunca passaria pela etapa de recuperação do ngx.ctx, porque saía cedo, não fazia backup do ngx.ctx, e também não ia para o processo de recuperação.

Isso era obviamente um bug! Bem, isso porque o ngx.ctx precisava ser recuperado após o redirecionamento. E como esse processo recuperava o ngx.ctx? Onde o ngx.ctx deu errado em primeiro lugar? Agora havia muitas incertezas, precisávamos coletar mais dados.

Após discutir, adicionamos um segundo log na produção, e descobrimos que, quando o erro ocorria após um redirecionamento interno, o ngx.ctx não passava pelo processo de recuperação, em vez disso, causava coredump diretamente!

Esse era um fenômeno perplexo, porque se o ngx.ctx não fosse recuperado após o redirecionamento, o ngx.ctx estaria vazio/nulo. E havia código que verificava valores vazios; ele não deveria disparar o código de coredump no plugin.

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

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

Então, foi esse redirecionamento interno error_page que fez com que o ngx.ctx tivesse um problema?

6. Conclusão Inicial

Após analisar e verificar, obtivemos uma compreensão básica do processo errôneo.

O set_upstream falhou e redirecionou para o estágio de tratamento de erros do error_page, e o ngx.ctx esperado vazio tinha um valor inesperado. E devido ao bug do APISIX, ele não recuperou o ngx.ctx antes de redirecionar, fazendo com que o ngx.ctx tivesse dados sujos ao acessar, causando assim o coredump. Para resolver esse problema, só precisaríamos recuperar o ngx.ctx após o redirecionamento; a implementação detalhada desse commit é fornecida no final do artigo para referência.

Embora tenhamos fornecido uma correção para o bug, ainda não conseguimos entender a lógica completa do bug. Como o usuário não modificou a lógica do ngx.ctx, a versão de código aberto deveria ser capaz de reproduzir. Para não continuar afetando o ambiente de produção e o processo de implantação do usuário, decidimos continuar investigando a causa raiz.

7. Reprodução Bem-Sucedida

Do que sabíamos, não conseguíamos reproduzir o problema. Após análise, decidimos verificar dois dos seguintes lugares:

• O redirecionamento interno tinha ramificações especiais de processamento?
• O ngx.ctx tinha ramificações especiais de processamento?

Para o primeiro ponto, durante o processamento de cada módulo de filtro do NGINX, ele pode ter algumas ramificações de exceção que afetaram os membros ctx do corpo da solicitação, afetando assim o ngx.ctx. Verificamos os módulos do usuário compilados no NGINX em busca de ramificações de exceção potenciais, mas não encontramos problemas semelhantes.

Para o segundo ponto, após investigação, descobrimos que durante o handshake SSL, o ngx.ctx tem um problema de reutilização. Se o estágio HTTP não conseguisse obter o ngx.ctx, ele tentaria obtê-lo do estágio SSL. O estágio SSL tem seu próprio ngx.ctx, e isso pode causar problemas para o ngx.ctx.

Com base nas descobertas acima, projetamos as seguintes condições e conseguimos reproduzir o problema com sucesso:

1. Mesma versão do APISIX que a do usuário
2. Ativar o certificado SSL
3. Criar um erro interno que aciona o error_page (como solicitar upstream quando não há nenhum)
4. Conexão longa
5. Plugin Prometheus (o coredump ocorreu no plugin para o usuário)

Finalmente, fizemos tijolos sem palha. Através de conjecturas e verificações, finalmente descobrimos o processo completo desse bug. Uma vez que há uma reprodução completa, não é mais difícil resolver o problema, e o processo final não será descrito em detalhes aqui. Acredito que todos têm muitas experiências em problemas que podem ser reproduzidos com precisão.

Resumo

A causa raiz desse problema: porque o ngx.ctx não foi restaurado após entrar no error_page, todas as solicitações na conexão longa reutilizaram o mesmo ngx.ctx na fase SSL. Eventualmente, causando que o ngx.ctx tivesse dados sujos e um coredump foi gerado.

No acompanhamento, também propusemos uma solução correspondente para esse problema: garantir que o ngx.ctx possa ser restaurado normalmente após o redirecionamento interno. Por favor, consulte o PR específico.

Se o seu APISIX usa funções que envolvem redirecionamento interno, como error_page, atualize para a versão mais recente o mais rápido possível.

Escrever programas e depurar são tarefas cientificamente rigorosas e não há espaço para ambiguidades. Para resolver um problema, precisamos coletar informações, rastrear todas as pistas potenciais, analisar a pilha de chamadas e, em seguida, descobrir o contexto para reproduzir o erro. Finalmente, o problema é resolvido.