supervisorを使用してgunicornをデーモン化したい

前提

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]$ supervisorctl status
XXX                            RUNNING   pid 24962, uptime 0:05:32
XXX_celery                     RUNNING   pid 23091, uptime 1:09:55

~~以下はログファイルの出力結果です。~~
取得したログの時間帯に誤りがあったため削除しました。後述の追記に正しいものを記載しております。
なお、デーモン起動時まで遡ると以下のログも出力されておりました。

[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_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]）

追記

いただいた質問に対する追記となります。

supervisor経由で起動するケース

ターミナル上の出力結果は上記の通りで、ブラウザからELBのDNSでアクセスすると、502 Bad Gatewayとなります。

gunicornで直接起動するケース

今回のsupervisorの設定を触るまでは、下記のコマンドを実行するとELBのDNSでアクセスできていたのですが、只今実行するとタイムアウトエラー（ブラウザ上は504 Gateway Time-out）となりました。確認不足で申し訳ありません。

[ec2-user@ip-~~ src]$ gunicorn  XXX.wsgi --log-level=debug --bind=0.0.0.0:3000

結果

[2022-12-19 01:14:26 +0000] [24300] [INFO] Starting gunicorn 20.0.4
[2022-12-19 01:14:26 +0000] [24300] [DEBUG] Arbiter booted
[2022-12-19 01:14:26 +0000] [24300] [INFO] Listening at: http://0.0.0.0:3000 (24300)
[2022-12-19 01:14:26 +0000] [24300] [INFO] Using worker: sync
[2022-12-19 01:14:26 +0000] [24343] [INFO] Booting worker with pid: 24343
[2022-12-19 01:14:26 +0000] [24300] [DEBUG] 1 workers
__DEBUG MODE__
[2022-12-19 10:14:45 +0900] [24343] [DEBUG] GET /terms/
[2022-12-19 01:15:16 +0000] [24300] [CRITICAL] WORKER TIMEOUT (pid:24343)
[2022-12-19 10:15:16 +0900] [24343] [INFO] Worker exiting (pid: 24343)
[2022-12-19 01:15:16 +0000] [24344] [INFO] Booting worker with pid: 24344

Listen Portの状況

supervisor起動前

[ec2-user@ip-~~ src]$ supervisorctl status
XXX                            STOPPED   Dec 19 01:08 AM
XXX_celery                     STOPPED   Dec 19 01:08 AM
[ec2-user@ip-~~ src]$ lsof -i -P | grep 3000

supervisor起動後
（lsof -i -P | grep 3000の実行は約1分間隔。）

[ec2-user@ip-~~ src]$ supervisorctl start all
XXX: started
XXX_celery: started
[ec2-user@ip-~~ src]$ supervisorctl status
XXX                            RUNNING   pid 24573, uptime 0:00:06
XXX_celery                     RUNNING   pid 24574, uptime 0:00:06
[ec2-user@ip-~~ src]$ lsof -i -P | grep 3000
gunicorn  24573 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24577 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24578 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24579 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24579 ec2-user    9u  IPv4 667418      0t0  TCP localhost:3000->localhost:41650 (ESTABLISHED)
[ec2-user@ip-~~ src]$ lsof -i -P | grep 3000
gunicorn  24573 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24577 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24577 ec2-user    9u  IPv4 667588      0t0  TCP localhost:3000->localhost:41658 (CLOSE_WAIT)
gunicorn  24625 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24625 ec2-user    9u  IPv4 667627      0t0  TCP localhost:3000->localhost:41662 (ESTABLISHED)
gunicorn  24627 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
[ec2-user@ip-~~ src]$ lsof -i -P | grep 3000
gunicorn  24573 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24627 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24627 ec2-user    9u  IPv4 667855      0t0  TCP localhost:3000->localhost:41666 (CLOSE_WAIT)
gunicorn  24641 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)
gunicorn  24641 ec2-user    9u  IPv4 667872      0t0  TCP localhost:3000->localhost:41670 (CLOSE_WAIT)
gunicorn  24642 ec2-user    5u  IPv4 667345      0t0  TCP *:3000 (LISTEN)

デーモン起動時からのログ
ブラウザ経由でのアクセスを行ったタイミングのログですが、下記のようなタイムアウト以外のログは出力がなく明確に対応づけて記載することができず申し訳ありません。

__DEBUG MODE__
[2022-12-19 01:39:10 +0000] [24573] [INFO] Starting gunicorn 20.0.4
[2022-12-19 01:39:10 +0000] [24573] [DEBUG] Arbiter booted
[2022-12-19 01:39:10 +0000] [24573] [INFO] Listening at: http://0.0.0.0:3000 (24573)
[2022-12-19 01:39:10 +0000] [24573] [INFO] Using worker: sync
[2022-12-19 01:39:10 +0000] [24577] [INFO] Booting worker with pid: 24577
[2022-12-19 01:39:10 +0000] [24578] [INFO] Booting worker with pid: 24578
[2022-12-19 01:39:10 +0000] [24579] [INFO] Booting worker with pid: 24579
[2022-12-19 01:39:10 +0000] [24573] [DEBUG] 3 workers
[2022-12-19 10:39:16 +0900] [24579] [DEBUG] GET /terms/
[2022-12-19 10:39:20 +0900] [24578] [DEBUG] GET /terms/
[2022-12-19 10:39:46 +0900] [24577] [DEBUG] GET /terms/
[2022-12-19 01:39:46 +0000] [24573] [CRITICAL] WORKER TIMEOUT (pid:24579)
[2022-12-19 10:39:46 +0900] [24579] [INFO] Worker exiting (pid: 24579)
__DEBUG MODE__
[2022-12-19 01:39:47 +0000] [24625] [INFO] Booting worker with pid: 24625
[2022-12-19 10:39:50 +0900] [24625] [DEBUG] GET /terms/
[2022-12-19 01:39:51 +0000] [24573] [CRITICAL] WORKER TIMEOUT (pid:24578)
[2022-12-19 10:39:51 +0900] [24578] [INFO] Worker exiting (pid: 24578)
__DEBUG MODE__
[2022-12-19 01:39:51 +0000] [24627] [INFO] Booting worker with pid: 24627
[2022-12-19 10:40:16 +0900] [24627] [DEBUG] GET /terms/
[2022-12-19 01:40:17 +0000] [24573] [CRITICAL] WORKER TIMEOUT (pid:24577)
[2022-12-19 10:40:17 +0900] [24577] [INFO] Worker exiting (pid: 24577)
__DEBUG MODE__
[2022-12-19 01:40:18 +0000] [24641] [INFO] Booting worker with pid: 24641
[2022-12-19 10:40:20 +0900] [24641] [DEBUG] GET /terms/
[2022-12-19 01:40:21 +0000] [24573] [CRITICAL] WORKER TIMEOUT (pid:24625)
[2022-12-19 10:40:21 +0900] [24625] [INFO] Worker exiting (pid: 24625)

補足情報（FW/ツールのバージョンなど）

他に必要な情報があれば追加でアップロードいたします。
知識不足のため誤認などありましたらご指摘ください。
何卒お力添えいただけますと幸いです。よろしくお願いいたします。

knuser1

2022/12/17 07:17

回答ではないのですが、、、添付されている複数のログの時間帯が統一されていないようにも思いますので、デーモンの起動時や、クライアントからのリクエスト時（エラーが返却される？）において、振る舞いとログを対応付けて確認することは可能でしょうか？ > （この状況が直接原因か判断できませんが、supervisorを使用せず手動でgunicornを起動していた際は接続可能でした。）こちらも、評価環境などで、gunicornで直接起動するケースと、supervisor経由で起動するケースを比較することは可能なものでしょうか？ > プロセスの強制終了（kill -9 [プロセスID]） `Address already in use`というメッセージも散見されますので、Listen Portの状況（「lsof -i -P | grep 3000」）を、デーモン起動前と起動後で比較するなども選択肢かと思いますが、どうでしょうか？

chcrng

2022/12/19 02:39

ご指摘ありがとうございます。不足あるかと思うのですが追記しておりますので、お手数でなければご確認いただけますと幸いです。 gunicornの直接起動について、現状直接起動でもアクセスできない点については認識していなかったため合わせて確認したいと思います。記載に誤りがあり申し訳ありません。一部のログについては、文字数の関係で割愛しておりますが、繰り返し他のプロセスIDのタイムアウトが表示される状況です。何卒よろしくお願いいたします。

knuser1

2022/12/23 22:45

補足ありがとうございます。時間が空いてしまいすいません、手元で再現できていないのですが、 > [2022-12-19 01:15:16 +0000] [24300] [CRITICAL] WORKER TIMEOUT (pid:24343) gunicorn起動時にWORKER TIMEOUTというログが記録されていると思うのですが、WORKERが応答できているかどうか、の観点で切り分けする余地があるでしょうか？ - https://github.com/benoitc/gunicorn/issues/1801 例えば、上記に色々議論があるようですが、一つは--timeoutオプションの指定で振る舞いが変化するか、どうかなど。

chcrng

2023/01/05 07:21

お忙しいところ引き続きご回答いただきありがとうございます。こちらの回答が遅れ申し訳ございません。本件ですが、gunicornの直接起動でもアクセスできなかった点について確認を進めていたところ、ソースそのものに問題があったことが判明しました。それを踏まえると、今回のエラーはAWSのヘルスチェックが関係しているのでは？と考えております。（ログに出力されているGET /terms/はヘルスチェックのパス） AWSに関しての知識不足もあり断定できるほどの確証はないのですが、ソースを修正しエラーが出ない状態にすると、今回のgunicornが勝手に再起動する件も解消されました。お忙しい中ご協力いただきましたのに、質問内容より前段階のミスが原因となっており申し訳ございませんでした。ご指摘のおかげで気づくことが出来ましたので大変感謝しております。

行動規範の内容に同意します

回答1件

自己解決

本件の発生前に、アップしたサイトのソース自体に問題があったことが判明。
これを修正すると、gunicornの再起動が発生しなくなった。
AWS（ターゲットグループ）のヘルスチェックで使用するパスがログに出力されていたことから、
サイトのエラーとヘルスチェックの関係でプロセスの再起動が起きていたものかと推測。

投稿2023/01/05 07:23

chcrng

総合スコア5