POST to Flask from espduino timing out

Question

I'm playing with an esp8266 providing WiFi to an Arduino with this library. I have it set up properly to POST to Pushover as well as requestbin, and between the debug output and the interface from these tools, I can verify that the request data is being POSTed properly, and the esp8266 / arduino unit's response status code properly shows 200.

I wanted to test the reliability of the setup, so I figured I'd turn to Flask. I put in a for loop to POST 100 requests from the espduino to a Flask app running at 0.0.0.0:5000. The POST contains a test string (trying to roughly gauge simple data integrity, make sure the string comes through uncorrupted) as well as the number of the loop that is being sent (e.g. 0 on the first loop ... 99 on the last). Flask keeps track of these requests and updates its output to show which requests came through properly and which did not.

The setup is working great except for one thing: the module is timing out after each request. Each POST appears to work, Flask updates the output appropriately, but the espduino takes its full 5 seconds (default timeout) for each request and says it got a response code of 0.

So to reiterate the situation: my espduino setup properly POSTs and gets a 200 response from requestb.in and pushover.net, but with my local Flask server POSTs and then times out.

WHYT:

• Make sure all form data is read by Flask -> no difference
• Serve with gunicorn instead of the built-in Flask server -> no difference
• Change response content type explicitly to "text/html" -> no difference
• Change response content type to "application/json" -> no difference
• Add ; charset=utf-8 to content type -> no difference
• Change Flask api endpoint from index / to /api -> no difference
• Change port -> no difference
• Verify Firewall is off (OS X 10.10.5 hosting the Flask app) -> no difference
• nc -l 5000 and check the incoming post from the module (looks good)
• Post from Postman and curl to the Flask app to inspect response (and compare with responses from Requestb.in / sites that work)
• Removed special chars from the test_string
• Change WSGIRequestHandler.protocol_version to HTTP/1.1 -> no difference

I've spent a couple days working on this and not made much progress. The biggest breakthrough I had today was that I can successfully post and get 200 responses if I put my gunicorn / Flask setup behind nginx, with no changes to the espduino code, so I'm sure there's something that Flask is or isn't doing (I was concerned it might be the espduino's processing of an IP address vs domain name, but I think this rules that out).

Summary of the setups I've tried:

• POST to requestb.in -> POST works, 200 response, no timeout
• POST to pushover.net -> POST works, 200 response, no timeout
• POST to local Flask server -> POST works, no response, times out
• GET to local Flask server -> no response, times out (have not tested if GETs data)
• POST to local gunicorn serving Flask app -> POST works, no response, times out
• POST to local nginx serving gunicorn / Flask -> POST works, 200 response, no timeout
• POST to local gunicorn serving httpbin -> no response, times out
• POST to local cherrypy server -> no response, times out

Current code:

from flask import Flask, request, make_response
from datetime import datetime

app = Flask(__name__)

ESPDUINO_IP = 'XXX.XXX.XXX.XXX'
INCOMING_TEST_STRING = 'This is my espduino test string!'
incoming_requests = []

with open('results.txt', 'w') as f:
    f.write("Test run start: {}\n".format(datetime.now()))

@app.route('/api', methods=['GET', 'POST'])
def count_requests():
    if request.method == 'POST':
        form = request.form
        incoming_ip = request.remote_addr
        if incoming_ip == ESPDUINO_IP and form['test_string'] == INCOMING_TEST_STRING:
            test_num = int(form['test_num'])
            incoming_requests.append(test_num)
            msg = "All is peachy!"
            with open('results.txt', 'a') as f:
                f.write("{:02d}: {}\n".format(test_num, datetime.now()))
    else:
        msg = "Hey, you're not the espduino!<br>"
        msg += str(len(incoming_requests)) + " requests so far.<br>"
        missing = set(range(100)) - set(incoming_requests)
        msg += "Missing: {}<br>".format(', '.join(map(str, missing)) if missing else "None!")
        msg += '<br>'.join(map(str, incoming_requests))

    resp = make_response('{"this": "that"}')
    resp.headers['Content-Type'] = "application/json"
    return resp
    # return "<html><body>{}</body></html>".format(msg)

if __name__ == '__main__':
    app.run(host='0.0.0.0', debug=True)

Here's what the POST from the espduino looks like:

$ nc -l 5000
POST /api HTTP/1.1
Host: XXX.XXX.XXX.XXX
Content-Length: 55
Connection: close
Content-Type: application/x-www-form-urlencoded
User-Agent: ESPDRUINO@tuanpm

test_string=This is my espduino test string!&test_num=0

As compared to curl -X POST -d 'test_string=This is my espduino test string!&test_num=0' localhost:5000/api:

$ nc -l 5000
POST /api HTTP/1.1
Host: localhost:5000
User-Agent: curl/7.43.0
Accept: */*
Content-Length: 55
Content-Type: application/x-www-form-urlencoded

test_string=This is my espduino test string!&test_num=0

Would love to hear any ideas on what may be going on. I'm wondering if this might be a WSGI problem?

Update Aug 31, 2015:

I still haven't figured this out, but it's definitely not a problem specific to Flask. As I noted above, I've also replicated the timeout with CherryPy, as well as with python3 -m http.server --bind 0.0.0.0 5000 (and changing the espduino code to GET /), as well as with ruby -run -e httpd. I still don't understand why nginx, requestbin, etc. serve it with no problems.

In response to @Miguel's comment about the HOST header not having the port, I'm working on forking and building the firmware to change this, but in the meantime I hard-coded the client host and port into a little HTTP server script with no luck.

from http.server import BaseHTTPRequestHandler, HTTPServer

class MyServer(BaseHTTPRequestHandler):
    # protocol_version = 'HTTP/1.1'
    # close_connection = True
    def _set_headers(self):
        self.send_response(200)
        self.send_header('Content-type', 'text/html')
        self.end_headers()

    def do_GET(self):
        self._set_headers()
        self.wfile.write(b"<html><body><h1>hi!</h1></body></html>")

    def do_HEAD(self):
        self._set_headers()

    def do_POST(self):
        self.client_address = ("192.168.0.4", 5000)
        self._set_headers()
        self.wfile.write(b"<html><body><h1>POST!</h1></body></html>")
        # import pdb; pdb.set_trace()

def run(server_class=HTTPServer, handler_class=MyServer, port=5000):
    server_address = ('0.0.0.0', port)
    httpd = server_class(server_address, handler_class)
    print('Starting httpd...')
    httpd.serve_forever()

if __name__ == "__main__":
    run()

Looking through tcpdump to see if I can find any difference between the working (nginx) and nonworking network data. Haven't found anything so far, but I'm also new to the tool.

Update Sep 08, 2015

Still haven't figured this out, but it looks like the tcpdump is significantly different between the nginx and Python servers. Here is an example POST and response -- I have replaced the IPs with ESPDUINO_IP and OSX_IP for clarity, and cleaned up the surrounding ACK calls and such. I need to look into why the Python response is getting interrupted by that odd line -- I examined 10+ consecutive POST / Response pairs, and every one of the Python responses was interrupted like that (in exactly the same place), and none of the nginx responses were, so I wonder if that might be the problem. (Also, as you can see, during this round of testing I had changed the response body to text instead of JSON -- no change in results.)

nginx (works)

POST /api HTTP/1.1
Host: OSX_IP
Content-Length: 29
Connection: close
Content-Type: application/x-www-form-urlencoded; charset=utf-8
User-Agent: espduino@n8henrie

test_string=simple&test_num=0


09:16:04.079291 IP OSX_IP.commplex-main > ESPDUINO_IP.49146: Flags [P.], seq 1:183, ack 211, win 65535, length 182

HTTP/1.1 200 OK
Server: nginx/1.8.0
Date: Mon, 31 Aug 2015 15:16:04 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 26
Connection: close

<html><body></body></html>

Flask (times out)

POST /api HTTP/1.1
Host: OSX_IP
Content-Length: 29
Connection: close
Content-Type: application/x-www-form-urlencoded; charset=utf-8
User-Agent: espduino@n8henrie

test_string=simple&test_num=3

09:00:19.424086 IP OSX_IP.commplex-main > ESPDUINO_IP.48931: Flags [P.], seq 1:18, ack 211, win 65535, length 17

HTTP/1.0 200 OK

09:00:36.382125 IP OSX_IP.commplex-main > ESPDUINO_IP.48931: Flags [FP.], seq 18:181, ack 211, win 65535, length 163
E....F@.@..,...e.......#...k..S.P.......Content-Type: text/html; charset=utf-8
Content-Length: 26
Server: Werkzeug/0.10.4 Python/3.4.3
Date: Mon, 31 Aug 2015 15:00:36 GMT

<html><body></body></html>

It looks to me like Python is breaking the response into two halves for some reason, e.g. one part of length 17 and another of length 163, as compared to nginx's single response of length 182.

Update Sep 10, 2015

Interestingly, everything works as expected if I run it through mitmproxy -- even directly to the Flask app without nginx or gunicorn. As soon as I remove mitmproxy, it's back to the timeouts as per above.

Answer 1

Still haven't fixed the problem, but I think I may have figured out what's causing it. Not a Flask problem after all.

Unfortunately this seems to be a bug with the esp_bridge library whose firmware espduino uses in the esp8266. Pardon the likely incorrect terminology, but from what I can tell for some reason it doesn't seem to be joining TCP packets. The servers that produce an HTTP response that is split into separate TCP packets (e.g. Flask) are failing, while tcpdump can verify that nginx and mitmproxy are joining the split TCP packets and returning a response in a single packet, which is why they are working.

https://github.com/tuanpmt/esp_bridge/issues/10

Update 20160128

I revisited this issue today and found a workaround. While the ideal solution would be to fix esp_bridge to reassemble multi-packet reponses, as long as the response is quite small one can force Flask to write the responses in a single packet.

from werkzeug.serving import WSGIRequestHandler

# Your Flask code here...

if __name__ == "__main__":
    WSGIRequestHandler.wbufsize = -1
    app.run()