uvicorn: Sporatic errors with nginx connection pipelining

There seems to be some weird issue with pipelining and or connection reuse and nginx. I have nginx sitting in front of my uvicorn/starlette app, and on patch/post requests I occasionally get 502’s from nginx (about 30-40% of the time). The nginx logs say:

upstream prematurely closed connection while reading response header from upstream

all over the place

and my app logs say:

WARNING: Invalid HTTP request received.
WARNING: Invalid HTTP request received.

with not much more information.

I forced connection reuse to not work by adding the default header Connection: close, which forces nginx to kill the connection. Performance drops significantly, but at least I don’t get 502’s.

uvicorn.run(app, host='0.0.0.0', port=8445, headers=[('Server', 'custom'), ('Connection', 'close')], proxy_headers=True)

potentially relevant: the 502 doesn’t seem to ever happen on a GET

About this issue

Original URL
State: closed
Created 5 years ago
Reactions: 14
Comments: 67 (23 by maintainers)

Most upvoted comments

I did some tcpdump’ing and found that uvicorn does not send the tcp-FIN packet to nginx and so nginx assumes the connection is still useable. nginx then sends the next http request to the open socket but uvicorn replies with a tcp-FIN packet and logs the invalid request error message. So uvicorn did not have an open connection??? Even though it did not send the FIN…

Workarounds:

Setting keep-alive to 0 fixes this while uvicorn then sends a tcp-FIN after each request. gunicorn -k uvicorn.workers.UvicornWorker -c /gunicorn_conf.py main:app --keep-alive=0
Also switching to the H11 worker fixes the issue because this also closes the connection after each request. gunicorn -k uvicorn.workers.UvicornH11Worker -c /gunicorn_conf.py main:app

But I prefer to have reuse of connection available and working. Still investigating how to get that working.

MilovdZee on Sep 9, 2019

If people impacted could look at their logs (if running 0.13.2 🍏 ) and tell us if they see something about a potentially malformed request that would help

note to self, reproduction steps, hopefully what we see here

run nginx with: docker run --rm --name nginx_uvicorn -p 80:80 -v /tmp/uvicorn.sock:/tmp/uvicorn.sock -v $PWD/nginx.conf:/etc/nginx/nginx.conf:ro nginx with quite a minimal nginx.conf

events {
}

http {
  server {
    listen 80;
    location / {
      proxy_pass http://uvicorn;
    }
  }
  upstream uvicorn {
    server unix:/tmp/uvicorn.sock fail_timeout=0;
  }
}

run uvicorn : uvicorn app:app --uds /tmp/uvicorn.sock
send incorrect request with curl -i 'http://localhost/?x=y z'

client result:

- ❯ curl -i 'http://localhost/?x=y z'
HTTP/1.1 502 Bad Gateway
Server: nginx/1.19.1
Date: Mon, 28 Dec 2020 19:27:46 GMT
Content-Type: text/html
Content-Length: 157
Connection: keep-alive

<html>
<head><title>502 Bad Gateway</title></head>
<body>
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.19.1</center>
</body>
</html>

nginx result:

2020/12/28 19:27:46 [error] 29#29: *4 upstream prematurely closed connection while reading response header from upstream, client: 172.17.0.1, server: , request: "GET /?x=y z HTTP/1.1", upstream: "http://unix:/tmp/uvicorn.sock:/?x=y z", host: "localhost"
172.17.0.1 - - [28/Dec/2020:19:27:46 +0000] "GET /?x=y z HTTP/1.1" 502 157 "-" "curl/7.64.0"

uvicorn result:

WARNING:  Invalid HTTP request received.
Traceback (most recent call last):
  File "/home/lotso/PycharmProjects/uvicorn/uvicorn/protocols/http/httptools_impl.py", line 165, in data_received
    self.parser.feed_data(data)
  File "httptools/parser/parser.pyx", line 193, in httptools.parser.parser.HttpParser.feed_data
httptools.parser.errors.HttpParserError: invalid constant string

euri10 on Dec 28, 2020

Encountering the same issue with a similar configuration, however, I also noticed in the deployment instructions there is mention of a --proxy-headers flag that should be set, but it appears I can’t do that while also using Gunicorn?

Are there other steps I can take to address this issue?

Additional details: GET, DELETE and PUT work correctly. POST and PATCH fail (exactly) half the time.

Headers:

"x-request-id": "f70bbcc408f3a1347dbd6d377e97e13d",
"x-real-ip": "xxx.xxx.xxx",
"x-forwarded-for": "xxx.xxx.xxx",
"x-forwarded-host": "sample.domain",
"x-forwarded-port": "443",
"x-forwarded-proto": "https",
"x-original-uri": "/ping?test=true",
"x-scheme": "https",
"x-request-start": "t=1564505305.680",

Here is a link to the docker image we are using for the deployment as well.

Removed GUnicorn and tried running just uvicorn for testing and I’m still facing the same issue:

DEBUG: ('147.191.218.178', 0) - ASGI [20] Sent {'type': 'http.request', 'body': '<17 bytes>', 'more_body': False}
DEBUG: ('147.191.218.178', 0) - ASGI [20] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('147.191.218.178', 0) - "POST /ping?test=true HTTP/1.1" 200
DEBUG: ('147.191.218.178', 0) - ASGI [20] Received {'type': 'http.response.body', 'body': '<552 bytes>'}
DEBUG: ('147.191.218.178', 0) - ASGI [20] Completed
WARNING: Invalid HTTP request received.
DEBUG: ('10.42.4.0', 53902) - Disconnected
DEBUG: ('xxx.xxx.xx.xxx', 36620) - Connected
DEBUG: ('xxx.xxx.xx.xxx', 36620) - ASGI [21] Started
DEBUG: ('xxx.xxx.xx.xxx', 36620) - ASGI [21] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('xxx.xxx.xx.xxx', 36620) - "GET /about HTTP/1.1" 200
DEBUG: ('xxx.xxx.xx.xxx', 36620) - ASGI [21] Received {'type': 'http.response.body', 'body': '<80 bytes>'}
DEBUG: ('xxx.xxx.xx.xxx', 36620) - ASGI [21] Completed
DEBUG: ('xxx.xxx.xx.xxx', 36620) - Disconnected
DEBUG: ('xxx.xxx.xx.xxx', 36626) - Connected
DEBUG: ('xxx.xxx.xx.xxx', 36626) - ASGI [22] Started
DEBUG: ('xxx.xxx.xx.xxx', 36626) - ASGI [22] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('xxx.xxx.xx.xxx', 36626) - "GET /about HTTP/1.1" 200
DEBUG: ('xxx.xxx.xx.xxx', 36626) - ASGI [22] Received {'type': 'http.response.body', 'body': '<80 bytes>'}
DEBUG: ('xxx.xxx.xx.xxx', 36626) - ASGI [22] Completed
DEBUG: ('xxx.xxx.xx.xxx', 36626) - Disconnected

matthax on Jul 30, 2019

ok I’m closing this long-standing issue, we think https://github.com/encode/uvicorn/pull/1263 fixed it, and since then we received no complains so 😃

euri10 on Jun 14, 2022

After shortening URLs I have not encountered this issue again, so I can confirm that at the very least my issue was URL-length related (not hitting any limits, but seems likely that on_url gets called multiple times).

@saulbein What did you use to shorten the url?

I simply put the URL parameter in the body of the request, nothing fancy.

saulbein on Feb 17, 2022

Hey all! Uvicorn 0.13.2 has been released. Feel free to try it out and report any enhanced tracebacks you can see from these errors. 😃 Thank you!

I was looking at old PR tonight @florimondmanca… it seems like https://github.com/encode/uvicorn/pull/205 is relevant here, we dont answer a 400 in case of an invalid request like gunicorn or hypercorn and apparently at the reverse-proxy level it turns into a 502, might be worth resurrecting that PR ?

euri10 on Dec 27, 2020

Hey everyone,

I think what might help move this forward would be having Uvicorn log some more information other than a rather unhelpful Invalid HTTP request received message.

I filed #886 that would turn those messages into much more helpful full traceback dumps:

WARNING:  Invalid HTTP request received.
Traceback (most recent call last):
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/protocols/http/httptools_impl.py", line 165, in data_received
    self.parser.feed_data(data)
  File "httptools/parser/parser.pyx", line 193, in httptools.parser.parser.HttpParser.feed_data
httptools.parser.errors.HttpParserInvalidMethodError: invalid HTTP method

Upon approval we can merge and release in a patch release, then you’d be able to try that version out in production and see what the actual error / cause is. Maybe that’ll be that “fragmented URL TCP packets” error from #778, maybe that’ll be something else, or a combination… We’ll see. 😃

florimondmanca on Dec 12, 2020

We have been having some of the errors described in this thread – intermittent WARNING: Invalid HTTP request received. from uvicorn immediately followed by a H13 Connection closed without response from Heroku.

Disabling Keep-Alive or switching to h11 both seems to mitigate the issue.

The solution we came up with is in PR https://github.com/encode/uvicorn/pull/778.

You can try this out with pip install -e 'git+git@github.com:eduflow/uvicorn.git@on_url-called-multiple-times#egg=uvicorn'

malthejorgensen on Sep 16, 2020

I tried everything: timeout tuning of gunicorn, using --keep-alive=0 for uvicorn.workers.UvicornWorker, using UvicornH11Worker, but still 2-3 percent requests get 502 on nginx

nobody reported back on explicitly setting proxy_http_version to 1.1

I updated our setup to use HTTP1.1, and it had no effect.

I figured out the root cause was actually true timeouts in our container, following requests weren’t making it to uvicorn logs because the container had actually halted execution. So my situation was not actually related to this issue.

oflannabhra on Aug 7, 2020

I think you quite literally just need an NGINX instance set up with a reverse proxy to reproduce. Send POST/PUT/PATCH to get the error.

If you’re not able to reproduce it like that let me know and I’ll set you up a Dockerfile with a minimal example.

matthax on Nov 22, 2019