Flask の起動時に Background で Thread を動かし、そこで値を更新して、HTTP Request でその値を返すようなコードを書いていました。
そのコードは、ローカルで flask run で実行すると期待通りに動くものの、uWSGI に deploy すると Background Thread で更新しているはずの値が取得できない、という問題が発生しました。そこで、調査用のコードを書いて uWSGI と flask run で実行し、どのような値が見えるか確認してみました。
Test Code
以下のコードを使って調べてみました。Flask でスレッド等の情報を出力する際に print を使うと HTTP の Response が返ってこなくなるので、JSON で返すようにしています。
- app.py on server
1from time import sleep
2import json
3import os
4import threading
5import traceback
6import sys
7
8from flask import Flask, jsonify
9
10i = 0
11app = Flask(__name__)
12
13def process():
14 while True:
15 try:
16 global i
17 i += 1
18 print("--------------- thread dump on background thread --------------")
19 for th, s in get_thread_dump():
20 print(f"pid: {os.getpid()}")
21 print(f"i = {i}")
22 print(f"{th} id={id(th)}")
23 print("".join(s.format()))
24 print()
25
26 except Exception as err:
27 print(f"err: {err}")
28
29 sleep(5)
30
31
32th = threading.Thread(target=process, name='test-thread', daemon=False)
33th.start()
34
35
36@app.route('/hello')
37def hello_world():
38 list = []
39 for th, frs in get_thread_dump():
40 l = [str(f) for f in frs]
41 list.append({
42 'pid': str(os.getpid()),
43 'counter': str(i),
44 'thread': str(th),
45 'thread-id': str(id(th)),
46 'frames': json.dumps(l)})
47
48 return jsonify({'message': list})
49
50
51def get_thread_dump():
52 ret = []
53 for th in threading.enumerate():
54 frames = sys._current_frames()
55 if frames.get(th.ident):
56 s = traceback.extract_stack(frames[th.ident])
57 else:
58 s = f"th: {th.ident} is not found in current frames"
59
60 ret.append((th, s))
61
62 return ret
63
64
65if __name__ == "__main__":
66 app.run(debug=True)- uwsgi.ini
[uwsgi]
master = true
http = 127.0.0.1:5000
wsgi-file = /root/works/app.py
callable = app
enable-threads = true
workers = 2
stats = 127.0.0.1:9191
pidfile=/root/works/app.pid- client.py on client
1import urllib.request
2import json
3
4with urllib.request.urlopen('http://localhost:5000/hello') as r:
5 j = r.read().decode('utf-8')
6 ps = json.loads(j)
7 print("--------------- thread dump on worker ---------------")
8 for p in ps.get('message'):
9 print(f"pid: {p.get('pid')}")
10 print(f"i = {p.get('counter')}")
11 print(f"{p.get('thread')} id={p.get('thread-id')}")
12 for f in json.loads(p.get('frames')):
13 print(f)
14
15 print()uWSGI
uWSGI prefork で動かした時に、Background Thread の中で thread dump を取得すると、以下のようになります。
--------------- thread dump on background thread --------------
pid: 1121
i = 4
<_MainThread(MainThread, started 140685885491072)> id=140685882011536
th: 140685885491072 is not found in current frames
pid: 1121
i = 4
<Thread(test-thread, started 140685867824896)> id=140685872997968
File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
self._bootstrap_inner()
File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.7/threading.py", line 870, in run
self._target(*self._args, **self._kwargs)
File "/root/works/app.py", line 19, in process
for th, s in get_thread_dump():
File "/root/works/app.py", line 56, in get_thread_dump
s = traceback.extract_stack(frames[th.ident])
--------------- thread dump on background thread --------------
pid: 1121
i = 5
<_MainThread(MainThread, started 140685885491072)> id=140685882011536
th: 140685885491072 is not found in current frames
pid: 1121
i = 5
<Thread(test-thread, started 140685867824896)> id=140685872997968
File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
self._bootstrap_inner()
File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.7/threading.py", line 870, in run
self._target(*self._args, **self._kwargs)
File "/root/works/app.py", line 19, in process
for th, s in get_thread_dump():
File "/root/works/app.py", line 56, in get_thread_dump
s = traceback.extract_stack(frames[th.ident])pid: 1121 は uWSGI の master プロセスです。
一方、uWSGI で動かした時、Flask の中で Thread dump を取得すると、以下のようになります。
--------------- thread dump on worker ---------------
pid: 1123
i = 1
<_MainThread(uWSGIWorker1Core0, started 140685885491072)> id=140685882011536
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 2463 in __call__>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 2446 in wsgi_app>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 1949 in full_dispatch_request>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 1935 in dispatch_request>
<FrameSummary file /root/works/app.py, line 39 in hello_world>
<FrameSummary file /root/works/app.py, line 56 in get_thread_dump>
pid: 1123
i = 1
<Thread(test-thread, started 140685867824896)> id=140685872997968
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 890 in _bootstrap>
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 926 in _bootstrap_inner>
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 870 in run>
<FrameSummary file /root/works/app.py, line 18 in process>pid: 1123 は uWSGI の worker プロセスです。
uWSGI の worker から見ると i の値は 1 から変化することはありません。i の初期値は 0 ですが、Background Thread 側で1度インクリメントしてから fork した為です。fork 後、master 側でカウンタの値を書き換えた際に Copy On Write でそれぞれでカウンタの値を保持するようになっています。
flask run
ローカルでは flask run で動かしていたので、その時の Thread やカウンタの見え方も確認してみました。Background Thread の中で thread dump を取得すると、以下のようになります。
--------------- thread dump on background thread --------------
pid: 1181
i = 4
<_MainThread(MainThread, started 140653762594624)> id=140653757725200
File "/usr/local/bin/flask", line 10, in <module>
sys.exit(main())
File "/usr/local/lib/python3.7/site-packages/flask/cli.py", line 966, in main
cli.main(prog_name="python -m flask" if as_module else None)
File "/usr/local/lib/python3.7/site-packages/flask/cli.py", line 586, in main
return super(FlaskGroup, self).main(*args, **kwargs)
File "/usr/local/lib/python3.7/site-packages/click/core.py", line 680, in main
rv = self.invoke(ctx)
File "/usr/local/lib/python3.7/site-packages/click/core.py", line 1027, in invoke
return _process_result(sub_ctx.command.invoke(sub_ctx))
File "/usr/local/lib/python3.7/site-packages/click/core.py", line 873, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/usr/local/lib/python3.7/site-packages/click/core.py", line 508, in invoke
return callback(*args, **kwargs)
File "/usr/local/lib/python3.7/site-packages/click/decorators.py", line 63, in new_func
return ctx.invoke(f, obj, *args[1:], **kwargs)
File "/usr/local/lib/python3.7/site-packages/click/core.py", line 508, in invoke
return callback(*args, **kwargs)
File "/usr/local/lib/python3.7/site-packages/flask/cli.py", line 860, in run_command
extra_files=extra_files,
File "/usr/local/lib/python3.7/site-packages/werkzeug/serving.py", line 1009, in run_simple
inner()
File "/usr/local/lib/python3.7/site-packages/werkzeug/serving.py", line 966, in inner
srv.serve_forever()
File "/usr/local/lib/python3.7/site-packages/werkzeug/serving.py", line 734, in serve_forever
HTTPServer.serve_forever(self)
File "/usr/local/lib/python3.7/socketserver.py", line 232, in serve_forever
ready = selector.select(poll_interval)
File "/usr/local/lib/python3.7/selectors.py", line 415, in select
fd_event_list = self._selector.poll(timeout)
pid: 1181
i = 4
<Thread(test-thread, started 140653735167744)> id=140653758109136
File "/usr/local/lib/python3.7/threading.py", line 890, in _bootstrap
self._bootstrap_inner()
File "/usr/local/lib/python3.7/threading.py", line 926, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.7/threading.py", line 870, in run
self._target(*self._args, **self._kwargs)
File "/root/works/app.py", line 19, in process
for th, s in get_thread_dump():
File "/root/works/app.py", line 56, in get_thread_dump
s = traceback.extract_stack(frames[th.ident])flask run で動かした時、Flask の中で Thread dump を取得すると、以下のようになります。
--------------- thread dump on worker ---------------
pid: 1181
i = 4
<_MainThread(MainThread, started 140653762594624)> id=140653757725200
<FrameSummary file /usr/local/bin/flask, line 10 in <module>>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/cli.py, line 966 in main>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/cli.py, line 586 in main>
<FrameSummary file /usr/local/lib/python3.7/site-packages/click/core.py, line 680 in main>
<FrameSummary file /usr/local/lib/python3.7/site-packages/click/core.py, line 1027 in invoke>
<FrameSummary file /usr/local/lib/python3.7/site-packages/click/core.py, line 873 in invoke>
<FrameSummary file /usr/local/lib/python3.7/site-packages/click/core.py, line 508 in invoke>
<FrameSummary file /usr/local/lib/python3.7/site-packages/click/decorators.py, line 63 in new_func>
<FrameSummary file /usr/local/lib/python3.7/site-packages/click/core.py, line 508 in invoke>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/cli.py, line 860 in run_command>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 1009 in run_simple>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 966 in inner>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 734 in serve_forever>
<FrameSummary file /usr/local/lib/python3.7/socketserver.py, line 232 in serve_forever>
<FrameSummary file /usr/local/lib/python3.7/selectors.py, line 415 in select>
pid: 1181
i = 4
<Thread(test-thread, started 140653735167744)> id=140653758109136
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 890 in _bootstrap>
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 926 in _bootstrap_inner>
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 870 in run>
<FrameSummary file /root/works/app.py, line 29 in process>
pid: 1181
i = 4
<Thread(Thread-1, started daemon 140653725640448)> id=140653725752720
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 890 in _bootstrap>
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 926 in _bootstrap_inner>
<FrameSummary file /usr/local/lib/python3.7/threading.py, line 870 in run>
<FrameSummary file /usr/local/lib/python3.7/socketserver.py, line 650 in process_request_thread>
<FrameSummary file /usr/local/lib/python3.7/socketserver.py, line 360 in finish_request>
<FrameSummary file /usr/local/lib/python3.7/socketserver.py, line 720 in __init__>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 326 in handle>
<FrameSummary file /usr/local/lib/python3.7/http/server.py, line 426 in handle>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 361 in handle_one_request>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 303 in run_wsgi>
<FrameSummary file /usr/local/lib/python3.7/site-packages/werkzeug/serving.py, line 291 in execute>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/cli.py, line 337 in __call__>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 2463 in __call__>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 2446 in wsgi_app>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 1949 in full_dispatch_request>
<FrameSummary file /usr/local/lib/python3.7/site-packages/flask/app.py, line 1935 in dispatch_request>
<FrameSummary file /root/works/app.py, line 39 in hello_world>
<FrameSummary file /root/works/app.py, line 56 in get_thread_dump>Flask の worker から見ると Background Thread でインクリメントした i の値が見えています。pid はどちらも 1181 になっています。
Conclusion
flask run は プロセスを Fork せず Thread だけでリクエストを処理しており、Background Thread で更新したカウンタを Flask から参照することができます。uWSGI は master プロセスを Fork して worker を作成しているので、master の Background Thread で更新したカウンタを worker の Flask から参照することができませんでした。
前記の調査用のコードはカウンタ(i)を使いましたが、実際はこの部分が別のライブラリで管理している変数だった為、すぐに原因を特定することはできませんでした。uWSGI に deploy したら思い通りに振る舞いにならなかった時、こういった箇所を疑ってみるのも一案だと思います。
調査用のコードを書いたりしてちょっと時間を使ってしまったので、自戒の念を込めてアップしました。