最も厄介な Nginx のクラッシュでは、core dump 分析だけでは行き詰まります。worker プロセスがメモリ破壊(Memory Corruption)で落ちた時点で「第一現場」はすでに上書きされており、クラッシュスタックが指すのは「無実の」コードだからです。 解決策は、稼働中の worker プロセスを記録し、そのリプレイを逆方向にデバッグすること——クラッシュ地点から、メモリを破壊した命令まで一歩ずつ遡ります。本稿では、OpenResty XRay がまさにこの手法で、Nginx の接続プール管理メカニズムに違反する二次開発が持ち込んだ use-after-free バグまでワーカープロセスのクラッシュを追跡した実例をご紹介します。

事例の背景:ログでは説明できない Nginx ワーカープロセスの頻繁なクラッシュ

お客様のオンラインサービスで Nginx ワーカープロセスが頻繁にクラッシュし、サービスの安定性に深刻な影響を及ぼしていました。このようなメモリエラーによるクラッシュ問題は、通常特定が困難です。表面上のクラッシュスタックからは、エラーの発生場所が問題の根本原因ではないことが多く、真の「第一現場」はすでに破壊されています。従来のログ分析やコード検証の手法では、このようなシナリオでは対応できません。また、静的な core ファイルに対する自動 core dump 解析でも、見えるのはクラッシュ時の最終状態だけで、それ以前にメモリが破壊された瞬間は捉えられません。問題を迅速かつ正確に特定するために、OpenResty XRay のライブレコーディング機能を活用して、本番環境の Nginx ワーカープロセスをオンライン記録しました。記録ファイルを再生して分析することで、最終的に問題の全容を解明することができました。

記録ファイルの分析:クラッシュを「第一現場」まで巻き戻して再生する

OpenResty XRay の専門家が記録ファイルを分析し、お客様の問題の根本原因を特定しました。以下では、その核心的な分析プロセスをご紹介いたします。

クラッシュポイントの特定:ngx_http_run_posted_requests でのセグメンテーション違反

まず、プログラムを実行してクラッシュを再現させ、GDB を使用してクラッシュ時のスタックトレース(Backtrace)を確認いたしました。(以下のバックトレースが関数名やソース行まで解決できているのは、デバッグシンボルが揃っているためです。バイナリが strip されシンボルが欠落している場合は、OpenResty XRay が先に欠落したデバッグシンボルを自動的に再構築できます。)

> c
> bt
#0  0x00000000004ccd1a in ngx_http_run_posted_requests (c=0x7f5fc3a010f8) at src/http/ngx_http_request.c:3152
#1  0x00000000004d047b in ngx_http_process_request_headers (rev=rev@entry=0x7f5fbfc010e0) at src/http/ngx_http_request.c:2021
#2  0x00000000004d10fd in ngx_http_process_request_line (rev=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1473
#3  0x00000000004b2d89 in ngx_epoll_process_events (cycle=0x7f60a3888b90, timer=<optimized out>, flags=<optimized out>)
...
#9  0x0000000000482c0e in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:436

崩壊は ngx_http_run_posted_requests 関数の3152行目で発生しました。対応するコードは if (pr == NULL) であり、pr の値は前の行の pr = r->main->posted_requests; から取得されています。これは、r->main にアクセスする際にセグメンテーション違反が発生したことを示しています。

  3114  void
  3115  ngx_http_run_posted_requests(ngx_connection_t *c)
  3116  {
  3117      ngx_http_request_t         *r;
  3118      ngx_http_posted_request_t  *pr;
  3119      for ( ;; ) {
  3120          if (c->destroyed) {
  3121              return;
  3122          }
  3123          r = c->data;
  3124          pr = r->main->posted_requests;
  3125          if (pr == NULL) {
  3126              return;
  3127          }
  3128          r->main->posted_requests = pr->next;
  3129          r = pr->request;
  3130          ngx_http_set_log_request(c->log, r);
  3131          ngx_log_debug2(NGX_LOG_DEBUG_HTTP, c->log, 0,
  3132                         "http posted request: \"%V?%V\"", &r->uri, &r->args);
  3133          r->write_event_handler(r);
  3134      }
  3135  }

r->main を出力してみたところ、無効なアドレスであることが判明しました:

end 1,471,308> print r->main
$14 = (ngx_http_request_t *) 0xffffffff2e616e69
end 1,471,308> print r->main->posted_requests
Cannot access memory at address 0xffffffff2e6173b1

これは r ポインタまたはそのメンバー main が既に破損していることを証明しています。コード内の r の値は r = c->data から来ており、ここで cngx_connection_t 型の接続オブジェクトです。私たちは c または c->data が何らかの段階で誤って変更されたのではないかと疑っています。

ハードウェアウォッチポイントで逆方向にたどる:c->data を変更したのは誰か?

c->data がいつ、何によって変更されたかを特定するために、そのメモリアドレスにハードウェアウォッチポイント(Hardware Watchpoint)を設定しました。

end 1,471,308> print &c->data
$8 = (void **) 0x7f5fc3a010f8
end 1,471,308> watch *(void **)0x7f5fc3a010f8
Hardware watchpoint 7: *(void **)0x7f5fc3a010f8

ハードウェアウォッチポイントを設定した後、rc(reverse-continue)コマンドを実行してプロセスを逆方向に実行し、c->data の変化プロセスを確認します。 各ブレークポイントが発生するたびに bt を実行して、c->data の修正コールスタックを確認します。これは、OpenResty XRay が Lua レベルのバックトレースにも適用しているタイムトラベルデバッグと同じ仕組みです。

end 1,471,308> rc

プログラムの実行を続けると、ウォッチポイントはすぐに複数回トリガーされ、重要な操作シーケンスが明らかになりました:

  1. 最初のトリガー:c->data が変更される。 ngx_http_lua_socket_resolve_retval_handler 関数内で、c->data に新しい値が割り当てられます。この値は ngx_http_request_t オブジェクトではなく ngx_http_lua_socket_tcp_upstream_t オブジェクトであるため、c->datangx_http_request_t として扱うと誤ったメモリアドレスにアクセスすることになります。したがって、rc コマンドを実行して、この c->data の変化プロセスを引き続き確認します。

    99% 1,471,080> bt
    #0  ngx_http_lua_socket_resolve_retval_handler (r=0x7f60a3838050, u=0x40c1ab88, L=0x40c1ab00)
        at addons/lua-nginx-module/src/ngx_http_lua_socket_tcp.c:1176
    #1  0x000000000058b3b9 in ngx_http_lua_socket_tcp_connect (L=0x40c1ab00) at addons/lua-nginx-module/src/ngx_http_lua_socket_tcp.c:744
    #2  0x0000000000647817 in lj_BC_FUNCC ()
    #3  0x0000000000573c95 in ngx_http_lua_run_thread (L=L@entry=0x41afc378, r=r@entry=0x7f60a3838050, ctx=ctx@entry=0x7f60a3917e68, 
        nrets=nrets@entry=0) at addons/lua-nginx-module/src/ngx_http_lua_util.c:1073
    #4  0x0000000000578acc in ngx_http_lua_rewrite_by_chunk (L=0x41afc378, r=0x7f60a3838050)
        at addons/lua-nginx-module/src/ngx_http_lua_rewriteby.c:338
    #5  0x0000000000578ddd in ngx_http_lua_rewrite_handler (r=0x7f60a3838050) at addons/lua-nginx-module/src/ngx_http_lua_rewriteby.c:167
    #6  0x00000000004c7763 in ngx_http_core_rewrite_phase (r=0x7f60a3838050, ph=0x7f60a2f50768) at src/http/ngx_http_core_module.c:1123
    #7  0x00000000004c2305 in ngx_http_core_run_phases (r=r@entry=0x7f60a3838050) at src/http/ngx_http_core_module.c:1069
    #8  0x00000000004c23ea in ngx_http_handler (r=r@entry=0x7f60a3838050) at src/http/ngx_http_core_module.c:1052
    #9  0x00000000004cfca1 in ngx_http_process_request (r=r@entry=0x7f60a3841050) at src/http/ngx_http_request.c:2780
    #10 0x00000000004d06f7 in ngx_http_process_request_headers (rev=rev@entry=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1995
    #11 0x00000000004d10fd in ngx_http_process_request_line (rev=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1473
    #12 0x00000000004b2d89 in ngx_epoll_process_events (cycle=0x7f60a3888b90, timer=<optimized out>, flags=<optimized out>)
    
  2. 第二回目のトリガー:メモリの再利用。 プログラムは ngx_event_connect_peer -> ngx_get_connection という呼び出しチェーンで再び観察点をトリガーしました。ngx_get_connection は Nginx の接続プールから新しい接続オブジェクトを取得し、新しい接続を初期化する際に、ngx_memzero によってこのメモリ(destroyed フラグを含む)がゼロクリアされます。rc コマンドを続行して c->data の変化過程を観察します。

    #0  0x0000000000494e1c in memset (__len=360, __ch=0, __dest=0x7f5fc3a010f8) at /usr/include/bits/string3.h:84
    #1  ngx_get_connection (s=s@entry=14, log=0x7f60a31c12c0) at src/core/ngx_connection.c:1190
    #2  0x00000000004a8e26 in ngx_event_connect_peer (pc=pc@entry=0x40c1abc8) at src/event/ngx_event_connect.c:53
    #3  0x0000000000587cb3 in ngx_http_lua_socket_resolve_retval_handler (r=0x7f60a3838050, u=0x40c1ab88, L=0x40c1ab00)
        at addons/lua-nginx-module/src/ngx_http_lua_socket_tcp.c:1131
    #4  0x000000000058b3b9 in ngx_http_lua_socket_tcp_connect (L=0x40c1ab00) at addons/lua-nginx-module/src/ngx_http_lua_socket_tcp.c:744
    #5  0x0000000000647817 in lj_BC_FUNCC ()
    #6  0x0000000000573c95 in ngx_http_lua_run_thread (L=L@entry=0x41afc378, r=r@entry=0x7f60a3838050, ctx=ctx@entry=0x7f60a3917e68, 
        nrets=nrets@entry=0) at addons/lua-nginx-module/src/ngx_http_lua_util.c:1073
    #7  0x0000000000578acc in ngx_http_lua_rewrite_by_chunk (L=0x41afc378, r=0x7f60a3838050)
        at addons/lua-nginx-module/src/ngx_http_lua_rewriteby.c:338
    #8  0x0000000000578ddd in ngx_http_lua_rewrite_handler (r=0x7f60a3838050) at addons/lua-nginx-module/src/ngx_http_lua_rewriteby.c:167
    #9  0x00000000004c7763 in ngx_http_core_rewrite_phase (r=0x7f60a3838050, ph=0x7f60a2f50768) at src/http/ngx_http_core_module.c:1123
    #10 0x00000000004c2305 in ngx_http_core_run_phases (r=r@entry=0x7f60a3838050) at src/http/ngx_http_core_module.c:1069
    #11 0x00000000004c23ea in ngx_http_handler (r=r@entry=0x7f60a3838050) at src/http/ngx_http_core_module.c:1052
    #12 0x00000000004cfca1 in ngx_http_process_request (r=r@entry=0x7f60a3841050) at src/http/ngx_http_request.c:2780
    #13 0x00000000004d06f7 in ngx_http_process_request_headers (rev=rev@entry=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1995
    #14 0x00000000004d10fd in ngx_http_process_request_line (rev=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1473
    #15 0x00000000004b2d89 in ngx_epoll_process_events (cycle=0x7f60a3888b90, timer=<optimized out>, flags=<optimized out>)
    
  3. 第三回目のトリガー:接続の解放。 プログラムは ngx_http_close_connection -> ngx_free_connection という呼び出しチェーンで観察点をトリガーしました。これは、c が指す接続が正常に閉じられ、解放されたことを示しています。閉じる前に、c->destroyed フラグが1に設定されます。

    #0  0x000000000049511b in ngx_free_connection (c=c@entry=0x7f5fc3a010f8) at src/core/ngx_connection.c:1220
    #1  0x0000000000495551 in ngx_close_connection (c=c@entry=0x7f5fc3a010f8) at src/core/ngx_connection.c:1292
    #2  0x00000000004cbf0d in ngx_http_close_connection (c=0x7f5fc3a010f8) at src/http/ngx_http_request.c:4575
    #3  0x00000000004c8be8 in ngx_http_core_content_phase (r=0x7f60a3841050, ph=0x7f60a2f509c0) at src/http/ngx_http_core_module.c:1388
    #4  0x00000000004c2305 in ngx_http_core_run_phases (r=r@entry=0x7f60a3841050) at src/http/ngx_http_core_module.c:1069
    #5  0x00000000004c23ea in ngx_http_handler (r=r@entry=0x7f60a3841050) at src/http/ngx_http_core_module.c:1052
    #6  0x00000000004cfc69 in ngx_http_process_request (r=r@entry=0x7f60a3841050) at src/http/ngx_http_request.c:2764
    #7  0x00000000004d06f7 in ngx_http_process_request_headers (rev=rev@entry=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1995
    #8  0x00000000004d10fd in ngx_http_process_request_line (rev=0x7f5fbfc010e0) at src/http/ngx_http_request.c:1473
    #9  0x00000000004b2d89 in ngx_epoll_process_events (cycle=0x7f60a3888b90, timer=<optimized out>, flags=<optimized out>)
    

この時、全体のイベントの連鎖はすでに明確です:ngx_http_process_request_headers 関数の処理フローの中で、現在の接続 c はまず閉じられ、その destroyed フラグは 1 に設定されます。しかし、クライアントの二次開発によって Nginx フレームワークが変更されたため、後続のコードがすぐに新しい接続を要求し、Nginx のメモリプールがちょうど解放されたメモリブロックを割り当ててしまいました。これにより、元の c ポインタが指していたメモリが再初期化され、destroyed フラグが 0 に戻ります。

ngx_http_process_request_headers のロジックが続くと、最後に ngx_http_run_posted_requests(c) が呼び出される際、if (c->destroyed) のチェックはフラグがクリアされたため無効になります。関数は続行し、c->data(つまり r)にアクセスしようとしますが、この時の c->data はすでに新しい接続に属する値であり、その内容とコンテキストは完全に一致しなくなり、最終的に不正なメモリにアクセスしてクラッシュを引き起こします。

根本原因:Nginx 接続ライフサイクルにおける Use-After-Free(解放後使用)

問題の根源は、クライアントの二次開発コードがNginx本来の厳密な接続ライフサイクル管理メカニズムを破壊したことにあります。具体的には、ngx_http_process_request_headers という関数の処理中に、「解放してすぐに再利用」同じ接続オブジェクトの衝突が発生しました。

呼び出しチェーンは以下の通りです:

  1. ngx_http_process_request_headers -> ngx_http_process_request -> … -> ngx_http_close_connection:接続が閉じられ、c->destroyedが 1 に設定されます。
  2. ngx_http_process_request_headers -> ngx_http_process_request -> … -> ngx_get_connection:二次開発のロジックにより、ここで新しい接続が要求され、ちょうど解放されたメモリが再利用され、c->destroyed がクリアされます。
  3. ngx_http_process_request_headers -> ngx_http_run_posted_requests(c)c->destroyed のチェックが無効になり、汚染された c->data が使用され、プログラムがクラッシュします。

なぜ OpenResty XRay が貴社にとって唯一無二の選択肢となるのでしょうか?

絶えず変化するオンライン ビジネスにおいて、一度のサービス崩壊はユーザー離脱や収益損失に直結する可能性がございます。今回の事例で明らかになった二次開発の不備によるメモリ踏みつぶし(Memory Overrun)問題は、システムの深部に潜む「見えない刺客」とも言えます。その挙動は非常に巧妙で破壊力が大きく、優秀な開発チームであっても原因追跡に数週間を費やす場合があり、それでもなお対処に苦慮されることが少なくありません。

従来のログ分析やコードレビューなどの手法では、「第一現場」がすでに破壊されている複雑な問題に直面した際、太刀打ちできないことが多くございます。まさにここに OpenResty XRay の価値がございます。私どもがご提供するのは単なるツールではなく、将来を見据えたインテリジェントな診断ソリューション一式でございます。

  • 手間のかかる探索作業をなくし、問題の核心へ直行
    従来のトラブルシューティングはまさに「大海の中で針を探す」が如く、時間とコストを大幅に消耗し、しかも成果が不確実でした。OpenResty XRay は強力な自動化根本原因解析機能により、複数レイヤにわたる問題を素早く可視化し、クラッシュを引き起こした瞬時のメモリ操作を正確に特定いたします。そこから「接続の汚染」から「プログラムの崩壊」に至るまでの完全な因果関係を明確に把握でき、貴社チームの数週間にわたる作業を、わずか数分の正確な分析に短縮いたします。

  • 「火消し役」から「アーキテクト」へ、チームの潜在力を解放
    貴重な開発リソースを、終わりのない「火消し」業務から解き放ちませんか。OpenResty XRay は深く隠れたバグ(Bug)を迅速に特定・解決することで、貴社チームがビジネス革新やアーキテクチャの最適化といった、より価値創造につながる業務に専念できる環境を実現いたします。

  • コア ビジネスを守り抜き、重大な損失を回避
    あらゆる安定性の課題は、ビジネスの中核的競争力を試される場面となり得ます。OpenResty XRay はまさに企業レベルの安定性確保を可能にするソリューションです。深く専門的なインサイトにより潜在リスクを早期に発見・排除し、コア ビジネスを 7x24 時間体制で安定稼働させ、基盤技術の欠陥によって生じる計り知れないビジネス上の影響やブランドの毀損を未然に防ぎます。

OpenResty XRay をお選びいただくことは、コア ビジネスの安定性に対する専門性の高いコミットメントを得ることと同義です。常に最先端の動的トレーシング技術を駆使して、貴社ビジネスのあらゆる重要な瞬間をしっかりとお守りいたします。

よくある質問(FAQ)

Nginx ワーカープロセスが signal 11 で終了したとはどういう意味ですか?

Signal 11 は SIGSEGV(セグメンテーション違反)のことで、ワーカープロセスがアクセスしてはならないメモリに触れたため、カーネルによって強制終了されたことを意味します。本事例では、メモリが解放され別の接続に再利用された接続オブジェクトを介して r->main を参照した際に、ngx_http_run_posted_requests 関数内でセグメンテーション違反が発生しました。

メモリ破壊の後、なぜクラッシュスタックは「無実の」コードを指すのですか?

プロセスが停止する時点では、「第一現場」はすでに上書きされているためです。クラッシュスタックが示すのは、汚染されたポインタが最終的に使用された場所(本事例では ngx_http_run_posted_requests)だけであり、それを汚染した以前のコードではありません。汚染からクラッシュまでの間に、そのメモリは解放・再割り当て・書き換えを経ており、エラーが出たスタックフレームは被害者にすぎません。

記録の再生は、静的な core dump の解析と何が違いますか?

Core dump はプロセスの最終状態のスナップショットであり、クラッシュポイントは調べられても、そこに至る履歴は見えません。一方、実行中のワーカーの記録は再生して逆方向に実行できます。汚染されたアドレスにハードウェアウォッチポイントを設定して reverse-continue すると、そのアドレスを変更した命令ごとに再生が停止し、第一現場まで遡ることができます。

Nginx ワーカープロセスの use-after-free クラッシュは何が原因ですか?

接続オブジェクトが Nginx の接続プールに解放された後も、コードがそれを使い続けることが原因です。本事例では、二次開発コードが接続を閉じて(c->destroyed を 1 に設定)、直後に新しい接続を要求しました。プールが同じメモリブロックを割り当て、ngx_memzerodestroyed フラグをクリアしたため、無効なポインタが Nginx の安全チェックをすり抜け、他の接続のデータを参照してしまいました。

OpenResty XRay について

OpenResty XRay動的トレース製品であり、実行中のアプリケーションを自動的に分析して、パフォーマンスの問題、動作の問題、セキュリティの脆弱性を解決し、実行可能な提案を提供いたします。基盤となる実装において、OpenResty XRay は弊社の Y 言語によって駆動され、Stap+、eBPF+、GDB、ODB など、様々な環境下で複数の異なるランタイムをサポートしております。

著者について

章亦春(Zhang Yichun)は、オープンソースの OpenResty® プロジェクトの創始者であり、OpenResty Inc. の CEO および創業者です。

章亦春(GitHub ID: agentzh)は中国江蘇省生まれで、現在は米国ベイエリアに在住しております。彼は中国における初期のオープンソース技術と文化の提唱者およびリーダーの一人であり、Cloudflare、Yahoo!、Alibaba など、国際的に有名なハイテク企業に勤務した経験があります。「エッジコンピューティング」、「動的トレーシング」、「機械プログラミング」 の先駆者であり、22 年以上のプログラミング経験と 16 年以上のオープンソース経験を持っております。世界中で 4000 万以上のドメイン名を持つユーザーを抱えるオープンソースプロジェクトのリーダーとして、彼は OpenResty® オープンソースプロジェクトをベースに、米国シリコンバレーの中心部にハイテク企業 OpenResty Inc. を設立いたしました。同社の主力製品である OpenResty XRay動的トレーシング技術を利用した非侵襲的な障害分析および排除ツール)と OpenResty Edge(マイクロサービスおよび分散トラフィックに最適化された多機能ゲートウェイソフトウェア)は、世界中の多くの上場企業および大企業から高い評価を得ております。OpenResty 以外にも、章亦春は Linux カーネル、Nginx、LuaJITGDBSystemTapLLVM、Perl など、複数のオープンソースプロジェクトに累計 100 万行以上のコードを寄与し、60 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

英語版の原文と日本語訳版(本文)をご用意しております。読者の皆様による他の言語への翻訳版も歓迎いたします。全文翻訳で省略がなければ、採用を検討させていただきます。心より感謝申し上げます!