NGINX ctx と error_page に関するコアダンプの物語

本番環境でのコアダンプは、エンジニアにとって恐怖の対象です。特に、真夜中にクラッシュが発生した場合にはなおさらです。私自身も10年以上前にその経験をしました。夜間にのみ現れる「幽霊」のようなバグを特定するため、チーム全員が午後に帰宅して睡眠を取り、深夜0時に会社に戻り、クラッシュを待ちながら各サービスを一つずつチェックしました。暗い夜の中、オフィスビルには数台のワークステーションの明かりだけが灯り、データやログを表示するモニターをじっと見つめる――それは緊張感と興奮に満ちた体験でした。私たちは3晩かけてバグを特定し、解決しました。それは忘れられない経験でした。

しかし、私たちは再びこのような状況に直面することになるとは思いもしませんでした。ただ、今回は私たち自身のサービスではなく、クライアントのオンラインサービスでコアダンプが発生したのです。これは私たちがコントロールできる環境よりもさらに困難な状況でした：

• エラーはユーザーの本番環境でのみ発生し、ユーザー自身のステージング環境やテスト環境では再現できませんでした。
• ユーザーはオープンソースのApache APISIXの上にカスタムコードを実装しており、NDAを別途締結するまでそのコードは見ることができませんでした。
• デバッグログを追加することができませんでした。
• エラーは午前3時にのみ発生し、クライアントから追加のリソースを確保して即座に対応する必要がありました。

要するに、この問題は再現不可能で、完全なソースコードもなく、テスト環境もありませんでした。しかし、私たちはエラーを特定し、再現方法を見つけ、最終的には修正を提供しなければなりませんでした。 このプロセスの中で、多くの課題に直面し、そこから多くのことを学びました。ここでは、デバッグプロセス中に遭遇した興味深いポイントをいくつか紹介します。これが、NGINXやAPISIXのデバッグを行う際のガイドとなれば幸いです。

問題の説明

ユーザーがAPISIXを2.4.1バージョンから2.13.1バージョンにアップグレードした後、周期的にコアダンプが発生し、以下のエラーメッセージが表示されました：

コアダンプメッセージから、セグメンテーションフォルトが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}

メモリ内のデータに問題があることがわかります。

分析前のいくつかの考察

セグメンテーションフォルトは通常、以下の2つのシナリオで発生します：

1. メモリ内の無効なアドレスを読み書きする場合。例えば、配列のインデックスが範囲外にアクセスすると、即座にセグメンテーションフォルトが発生します。
2. 無効な書き込みを行い、有効なアドレスを変更する場合。この場合、即座にセグメンテーションフォルトは発生しませんが、プログラムの実行中にそのアドレスにアクセスしようとした際にセグメンテーションフォルトが発生します。例えば、ポインタの値が誤って変更された場合、後でそのポインタにアクセスするとセグメンテーションフォルトが発生する可能性があります。

最初のシナリオでは、コールスタックを確認することで問題を簡単に特定できます。

2番目のシナリオでは、エラーが最初に発生した場所が明確でないため、エラーを生成したコードとセグメンテーションフォルトを引き起こしたコードが同じ場所にない可能性があり、問題の特定が困難になります。 そのため、クラッシュに関連するより多くのコンテキスト情報を収集する必要があります。例えば：

• 現在のAPISIXの設定詳細。
• 現在のリクエストの処理段階。
• 現在のリクエストの詳細。
• 同時接続数。
• エラーログ。

これらの情報を通じて、コードをレビューし、問題を再現する方法を見つけようとしました。

分析

1. エラーのコンテキストチェック

慎重に分析した結果、エラーは通常午前3時から4時の間に発生し、以下のコアダンプエラーメッセージが表示されることがわかりました：

最終的に、エラーログがユーザーの操作に関連していることがわかりました。ある理由により、この時間帯にすべてのアップストリームメッセージがクリアされるため、問題がアップストリームのクリア/リセット操作に関連していると疑いました。そして、エラーが返された後に例外ブランチに入り、コアダンプが発生する可能性があると考えました。

2. Luaのコールスタックを取得

GDBはLuaのコールスタックをトレースできないため、どの呼び出しがエラーを生成したのかを特定できませんでした。そのため、最初にLuaのコールスタックを取得する必要がありました。コールスタックを取得する方法は2つあります：

1. lua-var-nginx-moduleライブラリにコードを追加して、コールスタックを出力する（print(debug.traceback(...))）。ただし、この方法では大量のエラーログが生成され、本番環境に悪影響を及ぼす可能性があります。
2. API7.aiがメンテナンスしているopenresty-gdb-utilsを使用する。このツールキットはGDBのDSLとPython拡張を使用して、GDBのLuaコールスタック分析能力を強化します。ただし、コンパイル時にデバッグシンボルを有効にする必要があります。APISIXではデフォルトで含まれています。

その後、以下のコールスタックを取得しました。

LuaとCのコールスタックを組み合わせると、コアダンプがPrometheusプラグインでngx.ctx.api_ctx.var.schemeを呼び出した際に発生したことがわかりました。しかし、クラッシュの原因はまだ不明だったため、さらに分析が必要でした。

3. キャッシュが問題を引き起こした

ngx.ctx.api_ctx.varから変数にアクセスする際にエラーが発生し、上記のlua-var-nginx-moduleで呼び出しが実行されました。効率を上げるために、現在のリクエストをキャッシュしていました。リクエストボディの値に異常があった際にエラーが発生したことを思い出し、キャッシュされたリクエストの有効性も疑わしいと考えました。この考えを検証するため、キャッシュされたメモリを使用するのをやめ、毎回リクエストを再取得するようにプログラムを変更しました。

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._requestをnilに変更
end

ユーザーはこの修正版で一晩中テストを行い、エラーは再発しませんでした。リクエストボディに問題があることが確認されました。

4. ngx.ctxのエラー

キャッシュされたリクエストボディはngx.ctxに保存されていました。そして、ngx.ctxを変更する唯一の場所はapisix/init.luaでした。

function _M.http_header_filter_phase()
    if ngx_var.ctx_ref ~= '' then
        -- テーブルリークを防ぐ
        local stash_ctx = fetch_ctx()

        -- 内部リダイレクトなので、ctxを適用する必要がある
        if ngx_var.from_error_page == "true" then
            ngx.ctx = stash_ctx          <================= ここ
        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を見つけることができます。そして、このインデックスはNGINXリクエスト構造体のctxメンバーに保存されています。内部リダイレクトが行われるたびに、NGINXはctxをクリアするため、インデックスが見つからなくなります。

この問題を解決するため、APISIXはテーブルを作成し、リダイレクト前に現在のngx.ctxを保存し、ngx.varを使用してこのテーブル内のngx.ctxのインデックスを記録します。復元が必要な場合、テーブルから直接ngx.ctxを取得できます。

上記のコードは、ユーザーがerror_pageディレクティブを設定し、内部リダイレクト後にエラーが発生した場合にのみトリガーされます。

そして、ユーザーがバージョンアップ後にerror_pageディレクティブを有効にしたこと、および前述のアップストリーム変更によるエラーが発生したことがわかりました。すべてがつながっているように見えました。エラーハンドリングプロセス中にngx.ctxがバグを引き起こしたのでしょうか？

5. なぜngx.ctxにバグがあるのか

この疑問を持って、ngx.ctxのバックアップに関連するコードを確認したところ、さらに奇妙な問題が見つかりました。set_upstreamが失敗した後、早期に終了するため、ngx.ctxの復元ステップを実行せず、ngx.ctxをバックアップすることも、復元プロセスに進むこともありませんでした。

これは明らかにバグです！ リダイレクト後にngx.ctxを復元する必要がありました。 そして、このプロセスでngx.ctxがどのように復元されるのでしょうか？そもそもngx.ctxはどこで間違っていたのでしょうか？今や不確定要素が多すぎて、さらにデータを収集する必要がありました。

議論の結果、本番環境に2つ目のログを追加し、内部リダイレクト後にエラーが発生した際にngx.ctxが復元プロセスを経ず、直接コアダンプを引き起こしていることがわかりました！

これは不可解な現象でした。なぜなら、リダイレクト後にngx.ctxが復元されない場合、ngx.ctxは空/nullになるはずです。そして、空の値をチェックするコードがあるため、プラグイン内のコアダンプコードがトリガーされるべきではありませんでした。

local function common_phase(phase_name)
    local api_ctx = ngx.ctx.api_ctx
    if not api_ctx then              <============ ここ
        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にダーティデータが含まれ、コアダンプが発生しました。この問題を解決するためには、リダイレクト後にngx.ctxを復元するだけで十分でした。このコミットの詳細な実装は記事の最後に参考として記載しています。

バグの修正を提供しましたが、まだバグの完全なロジックを理解できていませんでした。ユーザーがngx.ctxのロジックを変更していないため、オープンソース版でも再現できるはずです。ユーザーの本番環境とデプロイプロセスに影響を与えないようにするため、根本原因を引き続き調査することにしました。

7. 成功した再現

私たちが知っている限り、問題を再現することはできませんでした。分析の結果、以下の2つのポイントを確認することにしました：

• 内部リダイレクトに特別な処理ブランチがあるか？
• ngx.ctxに特別な処理ブランチがあるか？

1つ目のポイントについて、NGINXの各フィルタモジュールの処理中に、リクエストボディのctxメンバーに影響を与える例外ブランチがある可能性があります。ユーザーのモジュールをチェックしましたが、同様の問題は見つかりませんでした。

2つ目のポイントについて、調査の結果、SSLハンドシェイク中にngx.ctxが再利用される際に問題が発生することがわかりました。 HTTPステージでngx.ctxを取得できない場合、SSLステージから取得しようとします。SSLステージには独自のngx.ctxがあり、それがngx.ctxに問題を引き起こす可能性があります。

上記の発見に基づき、以下の条件を設計し、問題を再現することに成功しました：

1. ユーザーと同じAPISIXバージョン
2. SSL証明書を有効にする
3. 内部エラーを発生させてerror_pageをトリガーする（例えば、アップストリームがない状態でリクエストする）
4. 長い接続
5. Prometheusプラグイン（ユーザーの場合、プラグインでコアダンプが発生した）

私たちはついに藁をもつかむ思いで、推測と検証を通じてこのバグの完全なプロセスを解明しました。完全な再現ができれば、問題を解決するのはもはや難しくありません。最終的なプロセスについてはここでは詳しく説明しません。正確に再現できる問題については、皆さんも多くの経験をお持ちだと思います。

まとめ

この問題の根本原因：error_pageに入った後にngx.ctxが復元されないため、長い接続上のすべてのリクエストがSSLフェーズで同じngx.ctxを再利用し、最終的にngx.ctxにダーティデータが含まれ、コアダンプが発生しました。

その後、この問題に対する対応策も提案しました：内部リダイレクト後にngx.ctxが正常に復元されることを保証する。 具体的なPRはこちらを参照してください。

もしあなたのAPISIXがerror_pageなどの内部リダイレクト機能を使用している場合、できるだけ早く最新バージョンにアップグレードしてください。

プログラムの作成とデバッグは科学的に厳密な作業であり、曖昧さは許されません。問題を解決するためには、情報を収集し、すべての潜在的な手がかりを追跡し、コールスタックを分析し、エラーを再現するためのコンテキストを理解する必要があります。そして、最終的に問題を解決します。