ブログリリース前から断続的にnginxで502エラーが出ていた。
以前の調査で、出現頻度はだいぶ減ったものの、まだ気になるレベルでエラーが発生していたため、この機会に本格的に調査することにした。
以前の調査記事はこちら。参考までに。
【nginx 502エラー】nginx.confのパラメータを調べてみた
まずはnginxのログを見てみよう
とはいうものの、私の使用しているnginxはDocker-compose中にあるので、ログを見る方法が普通とは異なる。
image: nginx:1.11 のようにイメージをそのまま使用してコンテナを作成していると、access.logやerror.logはコンテナ内に出力されず、標準出力、標準エラーに出力されるようだ。
コンテナ内のログは以下のようなイメージで設定されていた。
lrwxrwxrwx 1 root root 11 Dec 29 03:31 access.log -> /dev/stdout
lrwxrwxrwx 1 root root 11 Dec 29 03:31 error.log -> /dev/stderr
最初ここで嵌って「ログがない！」となっていました...
コンテナ内で標準出力、標準エラーに出力されたログは以下のコマンドで確認することができる。
docker-composeでは以下のコマンドで各コンテナに出力されるログを確認することができる。
docker-compose logs [サービス]
サービス名を確認するには docker-compose images コマンドを使用する。
「Container」欄の名前がサービス名。
docker-compose images
Container Repository Tag Image Id Size
----------------------------------------------------------------------------
DBServer-django mysql 5.7 a70d36bc331a 448.7 MB
WebAPServer-django django_server_python latest 8e5cb4a7df29 984.3 MB
nginx nginx latest bc9a0695f571 132.9 MB
docker-compose logsを使用してnginxのログを確認する。
# docker-compose logs nginx | grep -1 502
nginx_1 | 2021/02/11 01:58:42 [error] 7#7: *1 upstream prematurely closed connection while reading response header from upstream, client: 202.17.150.112, server: hoge.com, request: "GET /detail/14/ HTTP/1.1", upstream: "uwsgi://172.19.0.3:8001", host: "hoge.com", referrer: "https://hoge.com/"
nginx_1 | 202.17.150.112 - - [11/Feb/2021:01:58:42 +0000] "GET /detail/14/ HTTP/1.1" 502 568 "https://hoge.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.96 Safari/537.36" "-"
upstream => uwsgi がなにやら悪さをているらしいので、今度はuwsgiのログを確認する。
uwsgiのログ確認
著者の場合、uwsgiのログについては docker-compose.yml で出力先を指定している。
python:
build: ./python
command: uwsgi --socket :8001 --module project3.wsgi --py-autoreload 1 --logto /tmp/uwsgi.log
volumes:
- ./src:/code
- ./src/blog/static:/static
- ./python/log:/tmp
これの設定でコンテナの外にある./python/logにuwsgiのログが出力される。
それではログを見てみよう。
# tail ./python/log/uwsgi.log
/usr/local/lib/libpython3.9.so.1.0(PyBytes_AsString+0x4) [0x7f233c525194]
uwsgi(uwsgi_python_autoreloader_thread+0x16e) [0x55fd6769802e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3) [0x7f233d137fa3]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f233c3164cf]
*** end of backtrace ***
DAMN ! worker 1 (pid: 39) died, killed by signal 11 :( trying respawn ...
Respawned uWSGI worker 1 (new pid: 41)
Python auto-reloader enabled
DAMN ! worker 1 (pid: 39) died, killed by signal 11 ...と言われている。
原因が分かる
海外の掲示板を覗いてみると、2018年にpythonとuwsgiのバージョン互換性がうんぬんという話が挙がっており、pythonのバージョンをダウングレードすると問題解消したよ、という話がでていた。
2018年の話なら今2021年だし、バージョンアップで問題解決されてるんじゃないの？
pythonは最新版(3.9.1)をインストールしているし、原因はuwsgiか？
とりあえずrequirements.txtを確認。
Django==3.1.5
uwsgi==2.0.17
uwsgiの最新バージョンは現在2.0.19なので、これが原因のような気がする。
requirements.txtを以下のように修正し、docker-compose up -d --buildしたところ502エラーがでなくなった。
Django==3.1.5
uwsgi==2.0.19
設定値ではなく、バージョンが問題になってくるとトラブルシューティングの難易度が上がるなぁ。
でもこれで1週間以上に渡る問題が解決。すっきり。
