前提
EC2(Linux)にNginx + Gunicorn + SupervisorでDjangoアプリケーションをデプロイしました。
supervisorでデーモン化ができているか確認したところ、
gunicornのプロセスが、CLOSE_WAITとESTABLISHEDを繰り返していることが分かりました。
CLOSEした場合、新たにプロセスが作成されるのは正しい挙動と思うのですが、CLOSEされている原因が不明な状況です。
(以下、固有のサービス名をXXXと置き換えています。)
実現したいこと
- supervisorでgunicornをデーモン化したい。
大元の目的としては、あるタイミングでDNS経由でサーバ内のコンテンツ(Webサイト)へ接続ができなくなったため、原因の確認を進めたところ発覚した次第です。
(この状況が直接原因か判断できませんが、supervisorを使用せず手動でgunicornを起動していた際は接続可能でした。)
発生している問題・エラーメッセージ
gunicornで指定しているポート(3000)を確認した結果、
次々に新たなプロセスIDが作成されていました。(この間特に操作等はなし。)
[ec2-user@ip-〜〜 etc]$ lsof -i -P | grep 3000 gunicorn 24962 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25058 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25058 ec2-user 9u IPv4 240904 0t0 TCP localhost:3000->localhost:59276 (CLOSE_WAIT) gunicorn 25146 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25146 ec2-user 9u IPv4 240922 0t0 TCP localhost:3000->localhost:59280 (CLOSE_WAIT) gunicorn 25147 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) [ec2-user@ip-〜〜 etc]$ lsof -i -P | grep 3000 gunicorn 24962 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25193 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25193 ec2-user 9u IPv4 241068 0t0 TCP localhost:3000->localhost:59292 (CLOSE_WAIT) gunicorn 25194 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25194 ec2-user 9u IPv4 241111 0t0 TCP localhost:3000->localhost:59298 (ESTABLISHED) gunicorn 25196 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) [ec2-user@ip-〜〜 etc]$ lsof -i -P | grep 3000 gunicorn 24962 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25199 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25199 ec2-user 9u IPv4 241243 0t0 TCP localhost:3000->localhost:59306 (CLOSE_WAIT) gunicorn 25200 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN) gunicorn 25200 ec2-user 9u IPv4 241260 0t0 TCP localhost:3000->localhost:59310 (CLOSE_WAIT) gunicorn 25201 ec2-user 5u IPv4 239863 0t0 TCP *:3000 (LISTEN)
この時のステータスは以下のような状況でした。
[ec2-user@ip-〜〜 etc]$ supervisorctl status XXX RUNNING pid 24962, uptime 0:05:32 XXX_celery RUNNING pid 23091, uptime 1:09:55
以下はログファイルの出力結果です。
__DEBUG MODE__ [2022-12-16 08:50:48 +0000] [25328] [INFO] Booting worker with pid: 25328 [2022-12-16 17:51:13 +0900] [25328] [DEBUG] GET /terms/ [2022-12-16 08:51:13 +0000] [24962] [CRITICAL] WORKER TIMEOUT (pid:25325) [2022-12-16 17:51:13 +0900] [25325] [INFO] Worker exiting (pid: 25325) __DEBUG MODE__ [2022-12-16 08:51:14 +0000] [25331] [INFO] Booting worker with pid: 25331 [2022-12-16 17:51:18 +0900] [25331] [DEBUG] GET /terms/ [2022-12-16 08:51:18 +0000] [24962] [CRITICAL] WORKER TIMEOUT (pid:25327) [2022-12-16 17:51:18 +0900] [25327] [INFO] Worker exiting (pid: 25327) __DEBUG MODE__ [2022-12-16 08:51:18 +0000] [25333] [INFO] Booting worker with pid: 25333 [2022-12-16 17:51:43 +0900] [25333] [DEBUG] GET /terms/ [2022-12-16 08:51:43 +0000] [24962] [CRITICAL] WORKER TIMEOUT (pid:25328) [2022-12-16 17:51:43 +0900] [25328] [INFO] Worker exiting (pid: 25328) __DEBUG MODE__ [2022-12-16 08:51:44 +0000] [25335] [INFO] Booting worker with pid: 25335 [2022-12-16 08:51:48 +0000] [24962] [CRITICAL] WORKER TIMEOUT (pid:25331) [2022-12-16 17:51:48 +0900] [25331] [INFO] Worker exiting (pid: 25331)
遡ると以下のログも出力されておりました。
[2022-12-16 07:03:22 +0000] [22283] [INFO] Starting gunicorn 20.0.4 [2022-12-16 07:03:22 +0000] [22283] [ERROR] Connection in use: ('0.0.0.0', 3000) [2022-12-16 07:03:22 +0000] [22283] [DEBUG] connection to ('0.0.0.0', 3000) failed: [Errno 98] Address already in use [2022-12-16 07:03:22 +0000] [22283] [ERROR] Retrying in 1 second. [2022-12-16 07:03:23 +0000] [22283] [ERROR] Connection in use: ('0.0.0.0', 3000) [2022-12-16 07:03:23 +0000] [22283] [DEBUG] connection to ('0.0.0.0', 3000) failed: [Errno 98] Address already in use [2022-12-16 07:03:23 +0000] [22283] [ERROR] Retrying in 1 second. [2022-12-16 07:03:24 +0000] [22283] [ERROR] Connection in use: ('0.0.0.0', 3000) [2022-12-16 07:03:24 +0000] [22283] [DEBUG] connection to ('0.0.0.0', 3000) failed: [Errno 98] Address already in use [2022-12-16 07:03:24 +0000] [22283] [ERROR] Retrying in 1 second. [2022-12-16 07:03:25 +0000] [22283] [ERROR] Connection in use: ('0.0.0.0', 3000) [2022-12-16 07:03:25 +0000] [22283] [DEBUG] connection to ('0.0.0.0', 3000) failed: [Errno 98] Address already in use [2022-12-16 07:03:25 +0000] [22283] [ERROR] Retrying in 1 second. [2022-12-16 07:03:26 +0000] [22283] [ERROR] Connection in use: ('0.0.0.0', 3000) [2022-12-16 07:03:26 +0000] [22283] [DEBUG] connection to ('0.0.0.0', 3000) failed: [Errno 98] Address already in use [2022-12-16 07:03:26 +0000] [22283] [ERROR] Retrying in 1 second. [2022-12-16 07:03:27 +0000] [22283] [ERROR] Can't connect to ('0.0.0.0', 3000) [2022-12-16 07:03:29 +0000] [22286] [DEBUG] Current configuration: config: None bind: ['0.0.0.0:3000'] backlog: 2048 workers: 3 worker_class: sync threads: 1 worker_connections: 1000 max_requests: 0 max_requests_jitter: 0 timeout: 30 graceful_timeout: 30 keepalive: 2 limit_request_line: 4094 limit_request_fields: 100 limit_request_field_size: 8190 reload: False reload_engine: auto reload_extra_files: [] spew: False check_config: False preload_app: False sendfile: None reuse_port: False chdir: /var/www/XXX/src daemon: False raw_env: [] pidfile: None worker_tmp_dir: None user: 1000 group: 1000 umask: 0 initgroups: False tmp_upload_dir: None secure_scheme_headers: {'X-FORWARDED-PROTOCOL': 'ssl', 'X-FORWARDED-PROTO': 'https', 'X-FORWARDED-SSL': 'on'} forwarded_allow_ips: ['127.0.0.1'] accesslog: None disable_redirect_access_to_syslog: False access_log_format: %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" errorlog: - loglevel: debug capture_output: False logger_class: gunicorn.glogging.Logger logconfig: None logconfig_dict: {} syslog_addr: udp://localhost:514 syslog: False syslog_prefix: None syslog_facility: user enable_stdio_inheritance: False statsd_host: None dogstatsd_tags: statsd_prefix: proc_name: None default_proc_name: XXX.wsgi pythonpath: None paste: None on_starting: <function OnStarting.on_starting at 0x7fc1885bc040> on_reload: <function OnReload.on_reload at 0x7fc1885bc160> when_ready: <function WhenReady.when_ready at 0x7fc1885bc280> pre_fork: <function Prefork.pre_fork at 0x7fc1885bc3a0> post_fork: <function Postfork.post_fork at 0x7fc1885bc4c0> post_worker_init: <function PostWorkerInit.post_worker_init at 0x7fc1885bc5e0> worker_int: <function WorkerInt.worker_int at 0x7fc1885bc700> worker_abort: <function WorkerAbort.worker_abort at 0x7fc1885bc820> pre_exec: <function PreExec.pre_exec at 0x7fc1885bc940> pre_request: <function PreRequest.pre_request at 0x7fc1885bca60> post_request: <function PostRequest.post_request at 0x7fc1885bcaf0> child_exit: <function ChildExit.child_exit at 0x7fc1885bcc10> worker_exit: <function WorkerExit.worker_exit at 0x7fc1885bcd30> nworkers_changed: <function NumWorkersChanged.nworkers_changed at 0x7fc1885bce50> on_exit: <function OnExit.on_exit at 0x7fc1885bcf70> proxy_protocol: False proxy_allow_ips: ['127.0.0.1'] keyfile: None certfile: None ssl_version: 2 cert_reqs: 0 ca_certs: None suppress_ragged_eofs: True do_handshake_on_connect: False ciphers: None raw_paste_global_conf: [] strip_header_spaces: False [2022-12-16 07:03:29 +0000] [22286] [INFO] Starting gunicorn 20.0.4 [2022-12-16 07:03:29 +0000] [22286] [ERROR] Connection in use: ('0.0.0.0', 3000) [2022-12-16 07:03:29 +0000] [22286] [DEBUG] connection to ('0.0.0.0', 3000) failed: [Errno 98] Address already in use [2022-12-16 07:03:29 +0000] [22286] [ERROR] Retrying in 1 second.
該当のソースコード
XXX.confファイルの内容です。
[program:XXX] directory=/var/www/XXX/src/ command=gunicorn --workers=3 XXX.wsgi --log-level=debug --bind=0.0.0.0:3000 numprocs=1 autostart=true autorestart=true user=ec2-user redirect_stderr=true stdout_logfile=/var/log/XXX/ XXX.log priority=995
試したこと
ここに問題に対して試したことを記載してください。
- supervisorの再起動、再読み込み(supervisorctl restart all、supervisorctl reread)
- プロセスの強制終了(kill -9 [プロセスID])
補足情報(FW/ツールのバージョンなど)
他に必要な情報があれば追加でアップロードするようにいたします。
知識不足のため誤認などありましたらご指摘ください。
何卒お力添えいただけますと幸いです。よろしくお願いいたします。
0 コメント