クラッシュから根本原因まで:OpenResty XRay が Nginx メモリ破壊問題を明確に分析する方法
Nginx ワーカープロセスの頻繁なクラッシュは、運用担当者と開発者が直面する厄介な問題の一つです。特にクラッシュがメモリ破壊(Memory Corruption)によって引き起こされる場合、問題の根本原因は多くの場合、幾重にも隠れており、追跡が困難です。本稿では、実際に発生した Nginx のメモリ破壊によるクラッシュの事例を詳細に振り返り、OpenResty XRay を活用して糸を紐解くように、Nginx の接続プール管理メカニズムに違反する二次開発によって引き起こされた深層的な Bug を正確に特定する方法をご紹介します。これにより、同様の問題を解決するための効果的な診断アプローチをご提供します。
Nginx クラッシュで運用チームが徹夜する事例
お客様のオンラインサービスで Nginx ワーカープロセスが頻繁にクラッシュし、サービスの安定性に深刻な影響を及ぼしていました。このようなメモリエラーによるクラッシュ問題は、通常特定が困難です。表面上のクラッシュスタックからは、エラーの発生場所が問題の根本原因ではないことが多く、真の「第一現場」はすでに破壊されています。従来のログ分析やコード検証の手法では、このようなシナリオでは対応できません。問題を迅速かつ正確に特定するために、OpenResty XRay のライブレコーディング機能を活用して、本番環境の Nginx ワーカープロセスをオンライン記録しました。記録ファイルを再生して分析することで、最終的に問題の全容を解明することができました。
OpenResty XRay でメモリ破壊の「第一現場」を正確に捉える方法
OpenResty XRay の専門家が記録ファイルを分析し、お客様の問題の根本原因を特定しました。以下では、その核心的な分析プロセスをご紹介いたします。
初期分析:クラッシュポイントの特定
まず、プログラムを実行してクラッシュを再現させ、GDB を使用してクラッシュ時のスタックトレース(Backtrace)を確認いたしました。
> 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
から来ており、ここで c
は ngx_connection_t
型の接続オブジェクトです。私たちは c
または 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
の修正コールスタックを確認します。
end 1,471,308> rc
プログラムの実行を続けると、ウォッチポイントはすぐに複数回トリガーされ、重要な操作シーケンスが明らかになりました:
最初のトリガー:
c->data
が変更される。ngx_http_lua_socket_resolve_retval_handler
関数内で、c->data
に新しい値が割り当てられます。この値はngx_http_request_t
オブジェクトではなくngx_http_lua_socket_tcp_upstream_t
オブジェクトであるため、c->data
をngx_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>)
第二回目のトリガー:メモリの再利用。 プログラムは
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>)
第三回目のトリガー:接続の解放。 プログラムは
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 のライフサイクル管理を意図せず破壊したか
問題の根源は、クライアントの二次開発コードがNginx本来の厳密な接続ライフサイクル管理メカニズムを破壊したことにあります。具体的には、ngx_http_process_request_headers
という関数の処理中に、「解放してすぐに再利用」同じ接続オブジェクトの衝突が発生しました。
呼び出しチェーンは以下の通りです:
ngx_http_process_request_headers
->ngx_http_process_request
-> … ->ngx_http_close_connection
:接続が閉じられ、c->destroyed
が 1 に設定されます。ngx_http_process_request_headers
->ngx_http_process_request
-> … ->ngx_get_connection
:二次開発のロジックにより、ここで新しい接続が要求され、ちょうど解放されたメモリが再利用され、c->destroyed
がクリアされます。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 をお選びいただくことは、コア ビジネスの安定性に対する専門性の高いコミットメントを得ることと同義です。常に最先端の動的トレーシング技術を駆使して、貴社ビジネスのあらゆる重要な瞬間をしっかりとお守りいたします。
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 XRay(マイクロサービスおよび分散トラフィックに最適化された多機能
翻訳
英語版の原文と日本語訳版(本文)をご用意しております。読者の皆様による他の言語への翻訳版も歓迎いたします。全文翻訳で省略がなければ、採用を検討させていただきます。心より感謝申し上げます!