uvicorn: Stuck with: WARNING: Invalid HTTP request received.

Hi there,

I’m using FastAPI with uvicorn and I’m running into an issue which I’m not sure how to debug/solve. I wasn’t sure where to post this, but since the error message comes from uvicorn I decided to post it here.

There is no issue if I send a single GET request:

DEBUG: ('10.144.0.115', 48348) - Connected
DEBUG: ('10.144.0.115', 48348) - ASGI [48] Started
DEBUG: ('10.144.0.115', 48348) - ASGI [48] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('10.144.0.115', 48348) - "GET /charts HTTP/1.1" 200
DEBUG: ('10.144.0.115', 48348) - ASGI [48] Received {'type': 'http.response.body', 'body': '<41112 bytes>'}
DEBUG: ('10.144.0.115', 48348) - ASGI [48] Completed
DEBUG: ('10.144.0.115', 48348) - Disconnected

But if I send a second GET request while the connection from the first request is still open I get WARNING: Invalid HTTP request received.. Here is the complete log for the two requests:

DEBUG: ('10.144.0.115', 49422) - Connected
DEBUG: ('10.144.0.115', 49422) - ASGI [51] Started
DEBUG: ('10.144.0.115', 49422) - ASGI [51] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('10.144.0.115', 49422) - "GET /charts HTTP/1.1" 200
DEBUG: ('10.144.0.115', 49422) - ASGI [51] Received {'type': 'http.response.body', 'body': '<41112 bytes>'}
DEBUG: ('10.144.0.115', 49422) - ASGI [51] Completed
WARNING: Invalid HTTP request received.
DEBUG: ('10.144.0.115', 49422) - Disconnected
DEBUG: ('10.144.0.115', 49430) - Connected
DEBUG: ('10.144.0.115', 49430) - ASGI [52] Started
DEBUG: ('10.144.0.115', 49430) - ASGI [52] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('10.144.0.115', 49430) - "GET /charts HTTP/1.1" 200
DEBUG: ('10.144.0.115', 49430) - ASGI [52] Received {'type': 'http.response.body', 'body': '<41112 bytes>'}
DEBUG: ('10.144.0.115', 49430) - ASGI [52] Completed
DEBUG: ('10.144.0.115', 49430) - Disconnected

This isn’t too bad, because I still receive the responses for each request, even with the warning.

But if I try to send a POST request from a react-frontend it gets worse. The POST request from the frontend comes with a Preflight OPTIONS request. That means if I hit the send-button in the frontend the browser sends an OPTIONS request immediately followed by a POST request.

The server log looks like this:

DEBUG: ('10.144.0.115', 44982) - Connected
DEBUG: ('10.144.0.115', 44982) - ASGI [14] Started
DEBUG: ('10.144.0.115', 44982) - ASGI [14] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('10.144.0.115', 44982) - "OPTIONS /colors HTTP/1.1" 200
DEBUG: ('10.144.0.115', 44982) - ASGI [14] Received {'type': 'http.response.body', 'body': '<2 bytes>'}
DEBUG: ('10.144.0.115', 44982) - ASGI [14] Completed
WARNING: Invalid HTTP request received.
DEBUG: ('10.144.0.115', 44982) - Disconnected

The OPTIONS request gets through, but the POST request doesn’t. The payload from the frontend doesn’t reach the backend.

Now the strangest thing: If I hammer the send-button multiple times a second, the POST request will get through eventually.

Does anyone know what’s going on or how this could be solved?

About this issue

  • Original URL
  • State: closed
  • Created 5 years ago
  • Comments: 18 (6 by maintainers)

Most upvoted comments

Hi there, I do have the same issue but I can’t replicate it locally, I only see it on a deployed kubernetes cluster.

I am using gunicorn and the issue disappear if I switch from uvicorn.workers.UvicornWorker to uvicorn.workers.UvicornH11Worker.

It seems related to #344

@euri10 Just rebuilt our image using latest base image. Uvicorn is 0.11.3 and gunicorn is 20.0.4.

The issue persists when we turn on CORS and Azure inserts its middleware to handle CORS.

Update: @euri10 Adding the following environment variable is a work-around for this issue: GUNICORN_CMD_ARGS="--keep-alive 0"

@MrMathias

We are having the exact issue you are.

I was able to get the logs for my app. Looks like when you turn on CORS Azure App Service adds an ASP.NET middleware container, that isn’t there when no hosts are added in Azure portal. Once you add a host (even ‘*’), this container show up.

Maybe the issue lies in how the ASP.NET container is forwarding requests? If that is indeed what it’s doing.

2020-04-03 23:10:55.569 INFO  - Starting container for site
2020-04-03 23:10:55.570 INFO  - docker run -d -p 9426:80 --name app-image_9_7f572073 -e WEBSITE_CORS_ALLOWED_ORIGINS=* -e WEBSITE_CORS_SUPPORT_CREDENTIALS=False -e WEBSITES_ENABLE_APP_SERVICE_STORAGE=false -e WEBSITE_SITE_NAME=app-image -e WEBSITE_AUTH_ENABLED=False -e PORT=80 -e WEBSITE_ROLE_INSTANCE_ID=0 -e WEBSITE_HOSTNAME=app-image.azurewebsites.net -e WEBSITE_INSTANCE_ID=058934452a43339bdce881ba0f8ccabe7ab2e9c -e HTTP_LOGGING_ENABLED=1 appcr.azurecr.io/app-image:latest
2020-04-03 23:10:57.812 INFO  - Starting container for site
2020-04-03 23:10:57.813 INFO  - docker run -d -p 6645:8081 --name app-image_9_7f572073_middleware -e WEBSITE_CORS_ALLOWED_ORIGINS=* -e WEBSITE_CORS_SUPPORT_CREDENTIALS=False -e WEBSITES_ENABLE_APP_SERVICE_STORAGE=false -e WEBSITE_SITE_NAME=app-image -e WEBSITE_AUTH_ENABLED=False -e WEBSITE_ROLE_INSTANCE_ID=0 -e WEBSITE_HOSTNAME=app-image.azurewebsites.net -e WEBSITE_INSTANCE_ID=05893460edd64de419339bdce881ba0f8ccabe7ab2e9c -e HTTP_LOGGING_ENABLED=1 appsvc/middleware:2001061754 /Host.ListenUrl=http://0.0.0.0:8081 /Host.DestinationHostUrl=http://172.16.4.5:80 /Host.UseFileLogging=true
2020-04-03 23:11:00.325 INFO  - Initiating warmup request to container app-image_9_7f572073 for site app-image
2020-04-03 23:11:05.142 INFO  - Container app-image_9_7f572073 for site app-image initialized successfully and is ready to serve requests.
2020-04-03 23:11:05.149 INFO  - Initiating warmup request to container app-image_9_7f572073_middleware for site app-image
2020-04-03 23:11:06.712 INFO  - Container app-image_9_7f572073_middleware for site app-image initialized successfully and is ready to serve requests.
2020-04-03T23:10:57.529518893Z Checking for script in /app/prestart.sh
2020-04-03T23:10:57.529711693Z Running script /app/prestart.sh
2020-04-03T23:10:57.535610195Z Running inside /app/prestart.sh, you could add migrations to this file, e.g.:
2020-04-03T23:10:57.536461695Z
2020-04-03T23:10:57.536471895Z #! /usr/bin/env bash
2020-04-03T23:10:57.536475295Z
2020-04-03T23:10:57.536478095Z # Let the DB start
2020-04-03T23:10:57.536481095Z sleep 10;
2020-04-03T23:10:57.536483995Z # Run migrations
2020-04-03T23:10:57.536486895Z alembic upgrade head
2020-04-03T23:10:57.536489795Z
2020-04-03T23:11:02.362777760Z [2020-04-03 23:11:02 +0000] [1] [INFO] Starting gunicorn 19.9.0
2020-04-03T23:11:02.365039960Z [2020-04-03 23:11:02 +0000] [1] [INFO] Listening at: http://0.0.0.0:80 (1)
2020-04-03T23:11:02.365460460Z [2020-04-03 23:11:02 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
2020-04-03T23:11:02.385645366Z [2020-04-03 23:11:02 +0000] [7] [INFO] Booting worker with pid: 7
2020-04-03T23:11:02.411729172Z [2020-04-03 23:11:02 +0000] [8] [INFO] Booting worker with pid: 8
2020-04-03T23:11:05.139935586Z [2020-04-03 23:11:05 +0000] [7] [INFO] Started server process [7]
2020-04-03T23:11:05.140494386Z [2020-04-03 23:11:05 +0000] [7] [INFO] Waiting for application startup.
2020-04-03T23:11:05.141699287Z [2020-04-03 23:11:05 +0000] [7] [INFO] ('172.16.4.1', 30823) - "GET /robots933456.txt HTTP/1.1" 404
2020-04-03T23:11:05.298654228Z [2020-04-03 23:11:05 +0000] [8] [INFO] Started server process [8]
2020-04-03T23:11:05.299286428Z [2020-04-03 23:11:05 +0000] [8] [INFO] Waiting for application startup.
2020-04-03T23:11:06.664643885Z [2020-04-03 23:11:06 +0000] [7] [INFO] ('172.16.4.6', 59220) - "GET /robots933456.txt HTTP/1.1" 404
2020-04-03T23:11:10.545418592Z [2020-04-03 23:11:10 +0000] [7] [INFO] ('172.16.4.6',59220) - "GET /item HTTP/1.1" 200
2020-04-03T23:11:10.644182218Z [2020-04-03 23:11:10 +0000] [7] [WARNING] Invalid HTTP request received.
2020-04-03T23:11:10.737007042Z fail: Middleware[0]
2020-04-03T23:11:10.737043342Z       Unhandled exception in request pipeline: System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-04-03T23:11:10.737050842Z        ---> System.IO.IOException: The response ended prematurely.
2020-04-03T23:11:10.737874042Z          at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
2020-04-03T23:11:10.737885342Z          --- End of inner exception stack trace ---
2020-04-03T23:11:10.737889542Z          at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
2020-04-03T23:11:10.737893042Z          at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2020-04-03T23:11:10.737896542Z          at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2020-04-03T23:11:10.737900042Z          at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
2020-04-03T23:11:10.737903342Z          at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-03T23:11:10.737906742Z          at Microsoft.Azure.AppService.MiddlewareShim.Startup.ForwardRequestAsync(HttpContext context) in /EasyAuth/Middleware.Host/Startup.cs:line 197
2020-04-03T23:11:10.737910142Z          at Microsoft.Azure.AppService.MiddlewareShim.Startup.OnRequest(HttpContext context) in /EasyAuth/Middleware.Host/Startup.cs:line 151
2020-04-03T23:11:10.754963346Z fail: Microsoft.AspNetCore.Server.Kestrel[13]
2020-04-03T23:11:10.754979746Z       Connection id "0HLUO4H4Q9FHP", Request id "0HLUO4H4Q9FHP:00000001": An unhandled exception was thrown by the application.
2020-04-03T23:11:10.755602246Z System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-04-03T23:11:10.755613546Z  ---> System.IO.IOException: The response ended prematurely.
2020-04-03T23:11:10.755618046Z    at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
2020-04-03T23:11:10.755621446Z    --- End of inner exception stack trace ---
2020-04-03T23:11:10.755624746Z    at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
2020-04-03T23:11:10.755628046Z    at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2020-04-03T23:11:10.755631546Z    at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2020-04-03T23:11:10.757077447Z    at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
2020-04-03T23:11:10.757095147Z    at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-03T23:11:10.757100447Z    at Microsoft.Azure.AppService.MiddlewareShim.Startup.ForwardRequestAsync(HttpContext context) in /EasyAuth/Middleware.Host/Startup.cs:line 197
2020-04-03T23:11:10.757104347Z    at Microsoft.Azure.AppService.MiddlewareShim.Startup.OnRequest(HttpContext context) in /EasyAuth/Middleware.Host/Startup.cs:line 151
2020-04-03T23:11:10.757108047Z    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
2020-04-03T23:11:05.141699287Z [2020-04-03 23:11:05 +0000] [7] [INFO] ('172.16.4.1', 30823) - "GET /robots933456.txt HTTP/1.1" 404
2020-04-03T23:11:05.298654228Z [2020-04-03 23:11:05 +0000] [8] [INFO] Started server process [8]
2020-04-03T23:11:05.299286428Z [2020-04-03 23:11:05 +0000] [8] [INFO] Waiting for application startup.
2020-04-03T23:11:06.664643885Z [2020-04-03 23:11:06 +0000] [7] [INFO] ('172.16.4.6', 59220) - "GET /robots933456.txt HTTP/1.1" 404
2020-04-03T23:11:10.545418592Z [2020-04-03 23:11:10 +0000] [7] [INFO] ('172.16.4.6', 59220) - "GET /item HTTP/1.1" 200
2020-04-03T23:11:10.644182218Z [2020-04-03 23:11:10 +0000] [7] [WARNING] Invalid HTTP request received.
2020-04-03T23:13:03.854095207Z [2020-04-03 23:13:03 +0000] [8] [INFO] ('172.16.4.6', 59392) - "GET /docs HTTP/1.1" 200
2020-04-03T23:13:04.067111450Z [2020-04-03 23:13:04 +0000] [8] [WARNING] Invalid HTTP request received.

Thanks for your reply!

I already tried this, without luck:

from starlette.middleware.cors import CORSMiddleware

#...

@app.on_event("startup")
async def startup():

    #...

    app.add_middleware(
        CORSMiddleware,
        allow_origins=["*"],
        allow_credentials=True,
        allow_methods=["*"],
        allow_headers=["*"],
    )

Another thing I noticed:

  • A single POST request send via Isomnia (Rest API client) gets through without errors: 200 Ok.
  • A second POST request send via Insomia 1 second after the first one won’t get through: 502 Bad Gateway.
  • A second POST request send via Insomia 5 seconds after the first request will get through: 200 Ok.

To break the whole thing down a bit:

The server can handle ONE request just fine, but it fails in different ways, as soon as a SECOND request is send from the same user while the connection is still open.

Update

I found out that the issue doesn’t exist if I start uvicorn with timeout_keep_alive=0.