Handle exception when receive request with custom method

[XCanG]

Checklist

• The bug is reproducible against the latest release or master.
• There are no similar issues or pull requests to fix it yet.

Describe the bug

I'm developing fastapi application which is using starlette and run with uvicorn.

Currently I developing locally on my PC which I've done for a long time, so I frequently get some external random requests from the internet from random IPs.

While it is fine if I get some request that lead to some php endpoint and server log it and show nice 404 error in the logs, sometimes I get weird custom requests that break uvicorn and it throw errors, it look like this in the console:

The main issue in /uvicorn/protocols/http/httptools_impl.py:

uvicorn/uvicorn/protocols/http/httptools_impl.py

Lines 131 to 138 in a9ea657

	try:
	self.parser.feed_data(data)
	except httptools.HttpParserError as exc:
	msg = "Invalid HTTP request received."
	self.logger.warning(msg, exc_info=exc)
	self.transport.close()
	except httptools.HttpParserUpgrade:
	self.handle_upgrade()

Steps to reproduce the bug

• Use curl to make custom request, the custom method is -X flag where you in theory should use GET/POST/... but instead in my case I get some weird methods, that make uvicorn to throw exception

curl -X MUX -i -H "Custom-Header: Test" http://127.0.0.1/

Expected behavior

I should get minimal and useful log, this may be need to pass on underlying libraries (to handle it there) or being able to control behavior from them. Right now when you get this as it shows you don't understand what is happening, who is sending to you (IP) and what (what method?).

Actual behavior

Logs get full of this exception spam, it essentially work as DDoS for a server. I have to patch library manually to be able to fix this.

Debugging material

I attach screenshot above, there is also example from one request:

WARNING:  Invalid HTTP request received.
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/uvicorn/protocols/http/httptools_impl.py", line 131, in data_received
    self.parser.feed_data(data)
  File "httptools/parser/parser.pyx", line 212, in httptools.parser.parser.HttpParser.feed_data
httptools.parser.errors.HttpParserInvalidMethodError: Invalid method encountered

First line is come, probably from fastapi and other are exception.

Environment

• Windows, WSL, Docker
• Running uvicorn 0.15.0 with CPython 3.8.6 on Windows
• Running fastapi application like that: uvicorn main:app --host 0.0.0.0 --port 80

Additional context

This is similar issues:

• Catch HttpParserInvalidMethodError exception #75
• https://stackoverflow.com/questions/65878595/invalid-http-method-in-traceback-uvicorn
• https://stackoverflow.com/questions/69961123/host-fastapi-backend-api-and-react-app-frontend-locally
• unable to quiet tracebacks regarding illegal request lines #1364

[raphaelauv]

thanks @XCanG , I can also reproduce with uvicorn[standard]==0.16.0

[euri10]

not sure we should handle this differently, the request cant be parsed, open to ideas though, I kind of remember @florimondmanca made this change to try to pinpoint a long-standing nginx issue but I may be remember badly.

[alamorre]

I'm getting the same issue on Chango Channels

channels==3.0.4
...
Django==3.2.11
...
uvicorn==0.17.1
...

[XCanG]

What at least should be done is better writing exception message, because without it, it looks confusing. After that you may decide another approach.

I did some monkey-patch by including protocol information in exception:

        try:
            self.parser.feed_data(data)
        except httptools.HttpParserError as exc:
            msg = f"Invalid HTTP request received. | {data}"
            self.logger.warning(msg, exc_info=exc)
            self.transport.close()
        except httptools.HttpParserUpgrade:
            self.handle_upgrade()

Adding that data really helps as you now see in the logs what exactly is happening.

[tomchristie]

Needs to be resolved in both h11 and httptools. (See #1364)

[kevr]

not sure we should handle this differently, the request cant be parsed, open to ideas though, I kind of remember @florimondmanca made this change to try to pinpoint a long-standing nginx issue but I may be remember badly.

I personally would just figure out a way to allow users to control logging of the traceback, or remove the traceback completely and replace it with a more descriptive but concise one-line error about what's going on.

Edit: Another thought is to pass the error through to the application in some way, so that we can provide real http responses about it in our ASGI applications.

[euri10]

ok I digged a little and the traceback was introduced in #886 as part of trying to solve #344 to get a better sense of what was happening.

Now with #1263 merged, if that solves #344 (still need confirmation) then the change is obsolete

I think we could revert #886, should we do that you'd have this log, would that be ok ?

INFO:     Started server process [154345]
INFO:     Waiting for application startup.
INFO:     ASGI 'lifespan' protocol appears unsupported.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
WARNING:  Invalid HTTP request received.
^CINFO:     Shutting down
INFO:     Finished server process [154345]

[XCanG]

@euri10 That would be better, but can you also put info about what was requested? Like the type of request.

[euri10]

interestingly gunicorn returns a 200 !

❯ curl -X MUX -i -H "Custom-Header: Test" http://localhost:8000
HTTP/1.1 200 OK
Server: gunicorn
Date: Thu, 17 Feb 2022 08:44:41 GMT
Connection: close
Content-type: text/plain
Content-Length: 14

Hello, World!

def app(environ, start_response):
    """Simplest possible application object"""
    data = b'Hello, World!\n'
    status = '200 OK'
    response_headers = [
        ('Content-type', 'text/plain'),
        ('Content-Length', str(len(data)))
    ]
    start_response(status, response_headers)
    return iter([data])

[kevr]

interestingly gunicorn returns a 200 !

❯ curl -X MUX -i -H "Custom-Header: Test" http://localhost:8000
HTTP/1.1 200 OK
Server: gunicorn
Date: Thu, 17 Feb 2022 08:44:41 GMT
Connection: close
Content-type: text/plain
Content-Length: 14

Hello, World!

def app(environ, start_response):
    """Simplest possible application object"""
    data = b'Hello, World!\n'
    status = '200 OK'
    response_headers = [
        ('Content-type', 'text/plain'),
        ('Content-Length', str(len(data)))
    ]
    start_response(status, response_headers)
    return iter([data])

It depends. Not all instances of this error return a 200. For h11, we get a 502 response; see the aforementioned issue speaking about h11: Needs to be resolved in both h11 and httptools. (See https://github.com/encode/uvicorn/issues/1364)

[staubina]

I am also seeing this issue with 0.17.5. Is there a fix or workaround for this issue? I see a lot of recommendations and I have attempted many of them, but I still see the HttpParserInvalidMethodError error locally and in production.

[StuckInLoop]

what is the best way to alleviate this issue right now? this isn't a critical issue right?

[euri10]

what is the best way to alleviate this issue right now? this isn't a critical issue right?

not critical at all
my take on this: we should revert #886 since we didn;t hear more complains on #344 post-fix
thoughts @Kludex ?

[Kludex]

We still need to do something on h11_impl side, if I got all those messages right...

But I'm not against removing the whole trace there. 👍

[staubina]

@euri10 and @Kludex, With the revert I still see the Warnings, which is expected based on the code change. Is there something we should be doing in my deployment of Uvicorn to correct for this warning? Or is this just a Warning we should expect when we get requests with invalid methods?

We are using FastAPI with Uvicorn.

[Kludex]

I guess the answer would be: "this is just a warning you should expect when you get requests with invalid method".

[euri10]

yep, you'll just see WARNING: Invalid HTTP request received. and not the full traceback anymore, there's no functional change

[michealroberts]

So the latest fixes are not working imho. I have the same issue whereby I am deploying a Fast API application to a kubernetes cluster with uvicorn as the server of choice, and I am seeing the following issue:

INFO:     Will watch for changes in these directories: ['/usr/src/app']
INFO:     Uvicorn running on http://0.0.0.0:5000 (Press CTRL+C to quit)
INFO:     Started reloader process [1] using WatchFiles
INFO:     Started server process [10]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     10.244.0.66:60910 - "GET / HTTP/1.1" 307 Temporary Redirect
INFO:     10.244.0.66:60912 - "GET / HTTP/1.1" 307 Temporary Redirect
WARNING:  Invalid HTTP request received.
WARNING:  Invalid HTTP request received.
INFO:     10.244.0.66:32774 - "GET / HTTP/1.1" 307 Temporary Redirect
INFO:     10.244.0.66:32776 - "GET / HTTP/1.1" 307 Temporary Redirect
WARNING:  Invalid HTTP request received.
WARNING:  Invalid HTTP request received.
INFO:     10.244.0.66:32864 - "GET / HTTP/1.1" 307 Temporary Redirect
WARNING:  Invalid HTTP request received.
INFO:     10.244.0.66:32866 - "GET / HTTP/1.1" 307 Temporary Redirect
WARNING:  Invalid HTTP request received.
WARNING:  Invalid HTTP request received.
INFO:     10.244.0.66:32872 - "GET / HTTP/1.1" 307 Temporary Redirect
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [10]
INFO:     Stopping reloader process [1]

Basically, a number of requests are being reported as "Invalid" - then the server process is shutting down and the pod enters into its CrashLoopBackoff phase.

[Kludex]

We might need to add more information on that message, but besides that, there's no issue here... Can you track down the endpoint and the call?

[michealroberts]

@Kludex I feel like there is an issue, because this basically stops the server from reporting a healthy status to the kubernetes pod health checker, as it is causing it to reload and then shutdown after 5-10 invalid HTTP requests. The issue doesn’t happen on local, and those get requests are coming from the liveness probe. It’s definitely a uvicorn issue, because I have had multiple different servers running on kubernetes but uvicorn has so far been very problematic. Happy to be educated…of course!

[Kludex]

The issue doesn't happen locally because you're not making the same call as the one being made in production...

Again, can you please share the endpoint code and the call that is being made?

[zxcfer]

Got the same error calling without method

import json
import random
import socket
import time
import uuid

HOST = "localhost"  # Standard loopback interface address (localhost)
PORT = 65432  # Port to listen on (non-privileged ports are > 1023)
NUM_MESSAGES = 3

if __name__ == "__main__":
    msgs = []
    for _ in range(NUM_MESSAGES):
        msgs.append(
            {
                "timestamp": int(time.time()) + random.randint(1, 10),
                "msg": str(uuid.uuid4()),
            }
        )

    msg_str = json.dumps(msgs)

    with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
        s.connect((HOST, PORT))
        s.sendall(bytes(msg_str, encoding="utf-8"))