2021.02.11  

【nginx 502 Bad gateway】Docker-compose + nginx + uwsgiのログ解析

Nginx    


ブログリリース前から断続的に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週間以上に渡る問題が解決。すっきり。

コメント
現在コメントはありません。
コメントする
コメント入力

名前 (※ 必須)

メールアドレス (※ 必須 画面には表示されません)

送信