Python の faulthandler を uwsgi で指定する

Python で実装した Web アプリケーションを uwsgi 上で動作させて運用しているときのお役立ち Tips 的なやつ。

仕事で uwsgi を運用しているのだけど、先日 uwsgi の worker がずっと busy な状態になっているプロセスが常駐していたので調査した。 strace でプロセスの状態を追うと read() で止まっていてその前後は読めない状態だった。その時は read() で待たされていることが原因だったので read() している fd を特定して、どういったことが原因で待たされているのか調査することで解決した。

けれども、もう少しスマートに解決したいという欲求はあって、 Python の faulthandler [1]なる機能を教えてもらったので調べてみた。

faulthandler を使うと指定したシグナル (SIGSEGV, SIGFPE, SIGABRT, SIGBUS, SIGILL) を受信したときにスタックトレースを標準エラー出力に出力してプロセスを終了する。簡単な WSGI アプリケーションを書いて、環境変数から faulthandler を設定してみた。

#!/usr/bin/env python3.4
from werkzeug import run_simple


def app(environ, start_response):
    start_response('200 OK', [('Content-Type', 'text/plain; charset=utf-8')])
    yield b'Hello World!\n'

run_simple('127.0.0.1', 5000, app)

# exec
docker@3b813e88ee88:~$ python3 -V
Python 3.4.2
docker@3b813e88ee88:~$ PYTHONFAULTHANDLER=1 python3 ./wsgi.py &
[1] 39
docker@3b813e88ee88:~$  * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
docker@3b813e88ee88:~$ curl 127.0.0.1:5000
127.0.0.1 - - [05/Jul/2016 07:28:39] "GET / HTTP/1.1" 200 -
Hello World!
# send SIGSEGV
docker@3b813e88ee88:~$ kill -s SEGV $(pidof python3)
Fatal Python error: Segmentation fault

Current thread 0x00007f7b6d866700 (most recent call first):
  File "/usr/lib/python3.4/socketserver.py", line 154docker@d733ec43cf93:~$  in _eintr_retry
  File "/usr/lib/python3.4/socketserver.py", line 236 in serve_forever
  File "/home/docker/.local/lib/python3.4/site-packages/werkzeug/serving.py", line 499 in serve_forever
  File "/home/docker/.local/lib/python3.4/site-packages/werkzeug/serving.py", line 659 in inner
  File "/home/docker/.local/lib/python3.4/site-packages/werkzeug/serving.py", line 694 in run_simple
  File "./wsgi.py", line 9 in <module>

  [1]+  Segmentation fault      PYTHONFAULTHANDLER=1 python3 ./wsgi.py

標準エラー出力にスタックトレースの出力を確認できた。

あとは uwsgi を使ってアプリケーションを動かして確認するのだけど気をつけないといけないところがあって、 py-call-osafterfork [2] を有効にしないと uwsgi worker にシグナルを送信してもアプリケーションに伝達されないので注意。

# exec
# 今回 uwsgi は emperor モードで実行
# env: PYTHONFAULTHANDLER=1 を vassal の設定ファイルで指定
root@fb755eb211cb:/# uwsgi -y /etc/uwsgi/emperor.yaml
# send SIGSEGV
root@fb755eb211cb:/# ps auxf
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root       127  0.0  0.0  20256  3284 ?        Ss   08:38   0:00 /bin/bash
root       148  0.0  0.0  17496  2144 ?        R+   08:39   0:00  \_ ps auxf
root        10  0.0  0.0  20256  3264 ?        Ss   08:31   0:00 /bin/bash
root       144  0.0  0.0  48236  4664 ?        S+   08:39   0:00  \_ uwsgi -y /etc/uwsgi/emperor.yaml
root       145  0.9  0.1  66480 11172 ?        S+   08:39   0:00      \_ uWSGI master
docker     146  0.0  0.1  68692 10476 ?        S+   08:39   0:00          \_ uWSGI worker 1
docker     147  0.0  0.1  68692 10476 ?        S+   08:39   0:00          \_ uWSGI worker 2
docker       1  0.0  0.0  20252  3224 ?        Ss+  08:31   0:00 /bin/bash

# worker(cheaper) に SIGSEGV を送る
docker@fb755eb211cb:~$ kill -s SEGV 146
Fatal Python error: Segmentation fault

Current thread 0x00007fa047204780 (most recent call first):
!!! uWSGI process 146 got Segmentation Fault !!!
*** backtrace of 146 ***
uWSGI worker 1(uwsgi_backtrace+0x30) [0x4635f0]
uWSGI worker 1(uwsgi_segfault+0x21) [0x4639b1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0) [0x7fa046de58d0]
/lib/x86_64-linux-gnu/libpthread.so.0(raise+0x2b) [0x7fa046de579b]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0) [0x7fa046de58d0]
/lib/x86_64-linux-gnu/libc.so.6(epoll_wait+0x13) [0x7fa044f8ae33]
uWSGI worker 1(event_queue_wait+0x33) [0x456ed3]
uWSGI worker 1(wsgi_req_accept+0xd2) [0x4175f2]
uWSGI worker 1(simple_loop_run+0xb6) [0x45f7a6]
uWSGI worker 1(uwsgi_ignition+0x208) [0x463c78]
uWSGI worker 1(uwsgi_worker_run+0x25d) [0x466fbd]
uWSGI worker 1(uwsgi_run+0x3ae) [0x4674de]
uWSGI worker 1(_start+0) [0x41698e]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7fa044ec3b45]
uWSGI worker 1() [0x4169b7]
*** end of backtrace ***
DAMN ! worker 1 (pid: 146) died, killed by signal 11 :( trying respawn ...
Respawned uWSGI worker 1 (new pid: 150)
...