FlaskアプリのGunicornワーカーエラーを解決した方法:実体験に基づくトラブルシューティング
By hientd, at: 2024年11月3日22:20
Estimated Reading Time: __READING_TIME__ minutes


GunicornワーカーエラーをFlaskアプリで修正する方法:実際のトラブルシューティングの旅
本番サーバーを管理していると、すべてが順調に実行されていると思っていても、何かがうまくいかない瞬間が必ずあります。最近、まさにそのような状況に直面しました—Gunicorn上で実行されているPython/Flaskアプリで発生した実際の問題です。クライアントからアプリの一時的なダウンタイムが報告され、すぐに問題を調査する必要があることに気づきました。これは、私たちがどのように問題に取り組み、何を学び、同じ問題を回避するために今後どのような簡単な手順を踏むのかについて説明したものです。
初期設定
私たちのセットアップには、クライアントリクエストを処理する2つのサーバーを持つロードバランサーがあります。通常はロードバランサーがトラフィックを円滑に維持しますが、クライアントはオン/オフの可用性問題に遭遇し始めました。
[2024-11-03 13:25:42 +0000] [26747] [INFO] Booting worker with pid: 26747
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
self.flush()
File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
self.stream.flush()
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>
Call stack:
File "/home/ubuntu/sample-app/venv/bin/gunicorn", line 8, in <module>
sys.exit(run())
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 231, in run
super().run()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 72, in run
Arbiter(self).run()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 211, in run
self.manage_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
self.spawn_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 623, in spawn_workers
time.sleep(0.1 * random.random())
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 242, in handle_chld
self.reap_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 533, in reap_workers
os.WTERMSIG(status)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 261, in warning
self.error_log.warning(msg, *args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1320, in warning
self._log(WARNING, msg, args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1444, in _log
self.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1454, in handle
self.callHandlers(record)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/newrelic/hooks/logger_logging.py", line 87, in wrap_callHandlers
return wrapped(*args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1516, in callHandlers
hdlr.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 865, in handle
self.emit(record)
File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
self.flush()
File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
self.stream.flush()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 242, in handle_chld
self.reap_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 533, in reap_workers
os.WTERMSIG(status)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 261, in warning
self.error_log.warning(msg, *args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1320, in warning
self._log(WARNING, msg, args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1444, in _log
self.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1454, in handle
self.callHandlers(record)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/newrelic/hooks/logger_logging.py", line 87, in wrap_callHandlers
return wrapped(*args, **kwargs)
Message: 'Worker with pid %s was terminated due to signal %s'
Arguments: (26469, 9)
[2024-11-03 13:25:42 +0000] [26748] [INFO] Booting worker with pid: 26748
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
self.flush()
File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
self.stream.flush()
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>
Call stack:
File "/home/ubuntu/sample-app/venv/bin/gunicorn", line 8, in <module>
sys.exit(run())
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 231, in run
super().run()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/app/base.py", line 72, in run
Arbiter(self).run()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 211, in run
self.manage_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
self.spawn_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 623, in spawn_workers
time.sleep(0.1 * random.random())
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 242, in handle_chld
self.reap_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 533, in reap_workers
os.WTERMSIG(status)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 261, in warning
self.error_log.warning(msg, *args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1320, in warning
self._log(WARNING, msg, args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1444, in _log
self.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1454, in handle
self.callHandlers(record)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/newrelic/hooks/logger_logging.py", line 87, in wrap_callHandlers
return wrapped(*args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1516, in callHandlers
hdlr.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 865, in handle
self.emit(record)
File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
self.flush()
File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
self.stream.flush()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 242, in handle_chld
self.reap_workers()
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/arbiter.py", line 533, in reap_workers
os.WTERMSIG(status)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/gunicorn/glogging.py", line 261, in warning
self.error_log.warning(msg, *args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1320, in warning
self._log(WARNING, msg, args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1444, in _log
self.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1454, in handle
self.callHandlers(record)
File "/home/ubuntu/sample-app/venv/lib/python3.6/site-packages/newrelic/hooks/logger_logging.py", line 87, in wrap_callHandlers
return wrapped(*args, **kwargs)
Message: 'Worker with pid %s was terminated due to signal %s'
Arguments: (26469, 9)</module></stderr></module></stderr>
トラブルシューティングを開始した方法は次のとおりです。
-
プロセスの検証:まず、すべてのサーバープロセスをチェックして、実行されていることを確認しました。このレベルではすべて正常に見えました—明らかなクラッシュやハングしているプロセスはありませんでした。
-
ログの確認:すべてのプロセスがスムーズに実行されているように見えたため、Supervisordによって管理されているログに移動しました。そこで、アプリがランダムに終了するという繰り返しのパターンが見られました。そして、エラーログには、これらの特定のエントリが見つかりました。
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'> </stderr>
それに加えて、次のようなメッセージが繰り返し表示されました。Worker with pid %s was terminated due to signal %s
「reentrant」エラーとワーカーの終了の組み合わせから、メモリの問題、Gunicornの競合、ログエラーが混在しているように見えました。しかし、さらに情報が必要でした。
詳細な調査:エラーの調査
これらの手がかりから、オンラインで"reentrant call inside <_io.BufferedWriter>"
や"Gunicorn RuntimeError”
などの用語を検索し始めました。幸いなことに、同じ問題に遭遇した他のユーザーからのGitHubでの議論を見つけました。参照した重要な議論をいくつか紹介します。
これらを読み進めていくと、1つの問題が明らかになりました。Gunicornのバージョンが古くなっていました—20.0.1。最新のリリースは23.0.0であり、ログとプロセスの管理に関する修正が含まれており、これらの問題に直接対処していました。そこで、アップグレードを試してみることにしました。
ソリューションのテスト
-
最初のアップグレード:すぐに最新のリリースにジャンプするのではなく、21.2.0にアップグレードしました。慎重に行いたかったので、アプリを綿密に監視しました。数時間後、安定性が見られました—ランダムな終了はなくなりましたが、すべてが期待通りに動作していました。
-
最新のバージョンへの移行:自信が持てたら、23.0.0、つまり最新のGunicornバージョン(Pythonのバージョンアップも必要です - より困難ですが、その価値はあります)にアップグレードしました。それ以降、アプリは単一のreentrantエラーもなく安定しています。クライアントによるアプリへのアクセスは正常に戻り、アップグレードによって問題が解決されたことは明らかでした。
学んだこと
この経験から、いくつかの教訓が得られました。
-
ログは最初の手がかりです:常にプロセスの実行を確認し、ログを徹底的に確認することから始めましょう。ログには重要なヒントが含まれていることがよくあります。
-
同様の問題を検索する:奇妙なエラーが表示された場合、他の人がすでに直面している可能性があります。GitHubで特定の用語を検索すると、役立つ議論や、場合によっては正確な解決策を見つけることができます。
-
アップグレードはゆっくりと行う:最新のバージョンにジャンプするのではなく、段階的にアップグレードしてテストすることが賢明です。21.2.0で即座に改善が見られ、その段階的なアプローチにより、23.0.0に移行する前に安定性を確保できました。
-
Gunicornなどの依存するライブラリのGitHubリポジトリを購読すると、重要な更新に関する情報を常に把握できます。これは、このような突然の事態を回避するための簡単な方法です。
結論
本番環境の問題のトラブルシューティングはストレスがたまりますが、段階的なアプローチをとったことがここで功を奏しました。この経験は、依存関係の監視と最新の状態に保つことの重要性を改めて認識させました。私たちの事例が、同様の課題に対処したり、完全に回避したりするのに役立つヒントになれば幸いです。