【Django】502 Bad Gateway(nginx)エラーの原因が「モデルのインポートエラー」である場合とはどんなケースなのか

概要

• 追加実装していたプログラムを起動させたら、nginxの502エラーが出てきました。あれ、ウェブサーバーでなにか問題あったのか？と思い少し時間を浪費したのですが、結論、Djangoのimport文で余計なモデルを記述していたことが原因であることが分かりました。なぜインポートエラーが502エラーとなったのか、その原因を追求してみました。

前提

• ディレクトリ構造は以下の通り

app
├── auth_account
│   ├── models.py
│   ├── views.py
│   ├── urls.py
│   ├── middleware.py
│   └── etc...
├── app
│   ├── settings.py
│   └── etc...
├── home
│   ├── views.py
│   ├── urls.py
│   ├── etc...
│   └── templates/pages
│       ├── base.html
│       └── home.html
└── sample
│   ├── views.py
│   ├── urls.py
│   └── templates/sample
│       ├── base.html
│       └── sample.html
└── sample2 etc...

原因の追求

• ウェブサーバーエラーなのでロードバランサーやネットワークの問題はありそうですが、ちょっと前まで正常に起動していたものであり、ソースコードを編集したら突如502エラーになったので、ネットワーク周りの可能性は低そうでした。
• dockerコンテナで起動していたので、まずはdockerのログを見ます。Docker Desktopを使っていればそこから確認することも可能ですし、ターミナルでも以下コマンドで確認可能です。

docker logs <container_id>

• ログは以下の通りでした。

2023-05-18 08:55:26,603 INFO exited: app (exit status 1; not expected)
2023-05-18 08:55:27,612 INFO spawned: 'app' with pid 94
2023-05-18 08:55:28,393 INFO exited: app (exit status 1; not expected)
2023-05-18 08:55:29,409 INFO spawned: 'app' with pid 99
2023-05-18 08:55:30,209 INFO exited: app (exit status 1; not expected)
2023-05-18 08:55:32,224 INFO spawned: 'app' with pid 104
2023-05-18 08:55:32,940 INFO exited: app (exit status 1; not expected)
2023-05-18 08:55:35,965 INFO spawned: 'app' with pid 109
2023-05-18 08:55:36,748 INFO exited: app (exit status 1; not expected)
2023-05-18 08:55:37,751 INFO gave up: app entered FATAL state, too many start retries too quickly

• ログを見る限り Djangoコンテナの管理プロセスが起動後にすぐに終了、と繰り返しているようです。リトライが試みられましたが、複数回の試行後に最終的に失敗していることが分かります。
• うーん、、、ということで、nginxのエラーなので、nginxのログを観に行きます。ログは通常以下にあります。

アクセスログ: /var/log/nginx/access.log
エラーログ: /var/log/nginx/error.log

• どちらも見てみますが、、、中身は空っぽ。あれれ。
• Djangoのログも一応見るか、と思い見てみるものの、DEBUGがいくつか記載されているだけで、こちらも特にエラーメッセージの記述はなし。ぬぬぬ？

| DEBUG | asyncio - Using selector: EpollSelector

• gunicornを利用していたので、/usr/share/nginx/html/app/logs/gunicorn_supervisor.logを確認してみます。すると、ログに以下の記載がありました。

Traceback (most recent call last):
# 省略
  File "/usr/local/lib/python3.6/site-packages/django/core/wsgi.py", line 13, in get_wsgi_application
    return WSGIHandler()
  File "/usr/local/lib/python3.6/site-packages/django/core/handlers/wsgi.py", line 127, in __init__
    self.load_middleware()
  File "/usr/local/lib/python3.6/site-packages/django/core/handlers/base.py", line 35, in load_middleware
    middleware = import_string(middleware_path)
  File "/usr/local/lib/python3.6/site-packages/django/utils/module_loading.py", line 17, in import_string
    module = import_module(module_path)
  File "/usr/local/lib/python3.6/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "/usr/share/nginx/html/app/auth_account/middleware.py", line 2, in <module>
    from home.models import NoneGroup
ImportError: cannot import name 'NoneGroup'

• エラーの正体が分かりました。models.pyで定義していなかったモデルをmiddleware.pyのimport文に記述していたのが原因だったのです。
• ちなみに、import文に記載していた以前のモデル名を消し忘れていただけで、DjangoのORM（Object-Relational Mapping）を使ってモデルからレコードを取得したりはしていませんでした。

なぜインポートエラーが502エラーを返したのか？

• 502エラーは、通常、Webサーバー（Nginx、Apache等）から返されるエラーコードであり、Webアプリケーションに関連しているわけではありません。こういうDjango側のインポートエラーって502 Bad Gatewayエラーになるんだっけか！？って思って、試しにviews.pyでインポートエラーを発生させてみました。ただし、上記のようなエラーは起きません。代わりに以下の画面になります。そうこれこれ、これがDjangoで見慣れているインポートエラーの画面です。

• ではなぜ上記ではインポートエラーが502 Bad Gatewayになったかというと、記載していたのがmiddleware.pyだったからですね。Djangoのミドルウェアというのは、リクエストとレスポンスの処理フローに介入し、カスタムの処理を追加するために使用されます。
• views.py内でのインポートエラーは、Djangoアプリケーション自体のエラーとして扱われます。Djangoアプリケーションの起動時に発生するエラーなので、Djangoのログに出力されていました（一応雨gunicornのログも確認したら、こちらにもインポートエラーの記載はある）。
• 一方、middleware.py内でのインポートエラーは、WebサーバーがDjangoアプリケーションとの通信でエラーを検知し、502エラーとして返すことがあります。そのため、Djangoのログには何も出力されておらず、gunicornのログにのみ検知されて出力されていたと考えるべきでしょう。
• ということで、ミドルウェアのモジュールを利用している場合は、502エラーがモデルのインポートエラーである場合もある、ということを学んだエラー対応でした。解決解決。