FlaskアプリにおけるGunicornワーカーエラーの解決:実践的なトラブルシューティング体験
By hientd, at: 2024年11月3日22:20
Estimated Reading Time: __READING_TIME__ minutes


本番環境のサーバを管理していると、すべてが順調に動いていると思ったまさにその瞬間に、何かがうまくいかないことがあります。最近、私たちもまさにそのような事態に直面しました―Python/FlaskアプリケーションをGunicorn上で実行している際に発生した、実際の障害です。クライアントからアプリケーションの一時的な停止が断続的に報告され、すぐに問題を調査する必要があると認識しました。これは、私たちがどのように問題に取り組み、何を学び、今後同じ問題を回避するために取る簡単な手順について説明するものです。
初期設定
私たちのシステムは、クライアントからのリクエストを処理する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=''>
Call stack:
File "/home/ubuntu/sample-app/venv/bin/gunicorn", line 8, in
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=''>
Call stack:
File "/home/ubuntu/sample-app/venv/bin/gunicorn", line 8, in
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)
Message: 'Worker with pid %s was terminated due to signal %s'
Arguments: (26469, 9)
トラブルシューティングは次のように始めました。
-
プロセスの確認:まず、すべてのサーバプロセスが実行されていることを確認しました。このレベルではすべて正常に見えました―明らかなクラッシュやハングしているプロセスはありませんでした。
-
ログの確認:すべてのプロセスがスムーズに実行されているように見えたため、Supervisordによって管理されているログを確認しました。そこで、アプリケーションがランダムに終了するという繰り返しパターンが見つかりました。そして、エラーログに次の特定のエントリを見つけました。
RuntimeError: reentrant call inside <_io.BufferedWriter name='
'>
それに加えて、次のように繰り返し表示されました。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リポジトリを購読しておくと、重要な更新に関する情報を常に把握できます。これは、このような突然の問題を回避するための簡単な方法です。
結論
本番環境の問題のトラブルシューティングはストレスがたまりますが、段階的なアプローチを取ることで、ここでは本当に効果がありました。この経験は、依存関係を監視し、最新の状態に保つことの重要性を改めて認識させました。私たちの体験談が、同様の課題に取り組む―または完全に回避する―ためのいくつかの洞察を提供できれば幸いです。