uwsgi を使用していたら、Response の body が空になったお話

#はじめに
何が起きたかというと、クライアント側で response の StatusCode + body を見て処理の分岐をおこなっていたのですが、今回 body が空になるという予期せぬ事態におかしな挙動となってしまった時のお話。

#雲を掴むような調査
この問題、事の発端がクライアントの誤作動という事もあり、クライアントから原因を追っていたので調査は難航しました。
ただ、原因を追っていくうちに段階で response の body がない事がわかり、そこから最終的に nginx, uwsgi, django のどれかが犯人だと絞りながら調査を行い、どんどん犯人を追い詰めて行きました。
が、しかし。。。再現させたと思ったら急に再現しなくなったりの繰り返しで、全然原因が掴めずにいました。
いったいどこで body が紛失しているのか...
まるで、雲を掴むようなモヤモヤした状態でした。

まずは読むべきだった best practices and issues

Things to know (best practices and “issues”) READ IT !!!
これを読むべきでした。
この中に下記のような1文がありました。

If an HTTP request has a body (like a POST request generated by a form), 
you have to read (consume) it in your application. 
If you do not do this, the communication socket with your webserver may be clobbered. 
If you are lazy you can use the post-buffering option that will automatically read data for you. 
For Rack applications this is automatically enabled.

google 先生に翻訳してもらうと下記のようになります。

HTTPリクエストに（フォームによって生成されたPOSTリクエストのような）本文がある場合、
あなたのアプリケーションでそれを読む（消費する）必要があります。 これをしないと、
Webサーバーとの通信ソケットが詰まる可能性があります。
あなたが怠け者である場合は、自動的にデータを読み込むポストバッファリングオプションを使用することができます。
ラックアプリケーションの場合、これは自動的に有効になります。

ようは、本文があるようなPOSTリクエストの場合は、かならず body を read する必要がありますよーって言っています。
じゃないとソケットが詰まるよーって言ってますね。

#再現させてみる
原因が django 側で body を read していないことだとわかったので、docker などで uwsgi + django 構成を組み、再現させてみます。

処理の用意

django で最小構成を作成して、下記のような body を見ないで response を返す処理を入れます。

middleware.py

class TestMiddleware(object):

    def process_request(self, request):
        return HttpResponse('testbody', status=200)

    def process_response(self, request, response):
        return response

そしたら、次にリクエストを投げるスクリプトを用意します。
このスクリプトはだんだんと body サイズが大きくなる request を POST で投げ続ける処理になります。

test_request.py

import ujson
import requests


def task(p):
    n = p
    payload = ujson.dumps({'data': "text1",'box': ["text2", "N" * n]})
    try:
        response = requests.post(
            'http://localhost:80',
            data=payload
        )
        print(response, response.text)
        return False
    except Exception as e:
        print(e)
        return True


def loops(n=50):
    while n < 2000:
        n += 1
        if task(n * 50):
            break


loops()

実行結果

実行してみると下記のように IncompleteRead が必ず起きます。
これで再現ができました。

$ python test_request.py
testbody
testbody
testbody
testbody
testbody
testbody
IncompleteRead(0 bytes read)
$

修正してみる

では、Things to know (best practices and “issues”) READ IT !!! にあったように、body を read すると解消されるのかテストしてみます。
修正の方法は簡単で、先ほどの middleware の処理の中で body を read する処理を追加するだけです。

middleware.py

class TestMiddleware(object):

    def process_request(self, request):
        # ↓ body を read する処理を追加
        request.body

        return HttpResponse('testbody', status=200)

    def process_response(self, request, response):
        return response

では、この状態で先ほどのリクエストを投げる処理を実行します。

$ python test_request2.py
<Response [200]>
<Response [200]>
<Response [200]>
<Response [200]>
<Response [200]>
<Response [200]>
<Response [200]>
<Response [200]>
....
<Response [200]>
<Response [200]>
$

なんということでしょう。
見事に問題は解消されました。
POST の場合は body を read しなきゃいけないよ！というのは本当でした。

post-buffering option

issues には post-buffering option を使用しても良いよ！って書いているので、こちらも試してみました。

uwsgi -c "/usr/local/bin/uwsgi --socket :5000 --wsgi-file /app/myapp/wsgi.py --master --processes 4 --threads 2 --chdir /app --post-buffering 8192

この状態で、またリクエストを投げてみます。
もちろん、この時 middleware 内の body.read はコメントアウトしています。

実行結果は body.read を入れた時と同じように問題は起きませんでした。

$ python test_request2.py
<Response [200]>
<Response [200]>
<Response [200]>
<Response [200]>
....
<Response [200]>
<Response [200]>
$

時間を測って見る

しかし、post-buffering を使うと遅くなると思うので、local で10000リクエストを投げた時間を計測してみました。

結果は下記のようになりました。

回	use post-bufferring	not post-bufferring
1回目	190.501587868[sec]	170.532873869[sec]
2回目	168.798082113[sec]	158.778969049[sec]
3回目	169.777878046[sec]	166.270867825[sec]

ちょっと 10000 回程度だと微妙ですが、平均的に post-bufferring を使用するとやはり遅くなるようです。
ただ、local の実測などであくまで目安程度で。

教訓

下記は今回の教訓です。

送られてきたデータはチェックする

よくよく考えたら、body をチェックしていないということは body が壊れていてもわからないという状況になってしまうので、サーバー側もクライアント側も共通して送られてきたデータは必ずチェックするというのは必要だなと感じました。

今回の場合 HEADER の content-length にはちゃんと size が記載されているにも関わらず body が空という状況で、明らかに response が壊れていましたが、それを想定した実装がなされていないことが大きな問題に繋がったと思います。

困ったら issues などを見る

今回、解決に繋がった Things to know (best practices and “issues”) READ IT !!! など、一度目を通すべき。
今回のように実は仕様だったとか、周知のバグだったなんてことがあるので。

#まとめ
今回は POST の場合もヘッダー情報だけをみて、body を見ることなく、response を返していたことが原因でした。
わかってしまえば大したこと無いような内容ですが、例えば Authorization ヘッダを見てそのままエラーを返すなど、やっている人も割と多いのではないでしょうか？

問題が起きてしまうと調査も面倒な内容なので、心当たりがある方はぜひ一度確認してみてはいかがでしょうか。

##正直いうと...
なぜ request の body を read しないと ソケット が詰まって今回のように response に影響するのかその仕組みがよくわかっていません。
uwsgi の中の話なので、そういうものだと割り切ればそうなのですが、誰か詳しい方がいれば教えていただけるとうれしいです。
この記事を読んでくれる人がいたらですが。笑