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

Created on 26 Sep 2019  Â·  18Comments  Â·  Source: encode/uvicorn

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?

picture feluxe

Most helpful comment

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

picture reminizdeveloper on 2 Dec 2019
👍3

All 18 comments

This seems like a cors issue, try to add a cors Middleware
https://www.starlette.io/middleware/

Le jeu. 26 sept. 2019 à 8:28 PM, feluxe notifications@github.com a écrit :

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
https://developer.mozilla.org/en-US/docs/Glossary/Preflight_request
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?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/encode/uvicorn/issues/441?email_source=notifications&email_token=AAINSPT4MCAW77XXLBBC26LQLT5M7A5CNFSM4I25QUSKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4HN622WA,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAINSPU5I7ZV3P6DFCLLRDTQLT5M7ANCNFSM4I25QUSA
.

euri10 picture euri10 on 26 Sep 2019

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.

feluxe picture feluxe on 26 Sep 2019
👍1

Are you able to replicate this behavior with an alternate client?
Eg. Can you replicate the behavior using Python's requests?
Does the behavior replicate against the basic uvicorn quickstart example?

tomchristie picture tomchristie on 7 Oct 2019

Happy to reopen this if there's a simple replicable example with another client.

tomchristie picture tomchristie on 24 Oct 2019

Hi, I am facing the same issue with a web application that is using my API services enabled by FastAPI, Uvicorn and Gunicorn. Could someone look into this?

gautamsinghania95 picture gautamsinghania95 on 5 Nov 2019

@gautamsinghania95 In order to look into this issue we need to be able to replicate it, so help us out here... What's the simplest possible example case that you can create that replicates the issue? Can you show a single page example that we can use to replicate it? What client are you using, and how are you making the request?

tomchristie picture tomchristie on 5 Nov 2019

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

reminizdeveloper picture reminizdeveloper on 2 Dec 2019
👍3

I encountered a similar issue running fastAPI in a container on Azure's app service infrastructure.

I am able to replicate my problem using a minimal fastAPI app, using starlette.middleware.cors import CORSMiddleware to whitelist a frontend:

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

This works fine locally, and deployed, until I configure any Allowed Origins in Azure's app service control panel. At that moment I get sporadic respones on some resource calls and become unable to load /openapi.json

When I say "some resource calls", I am not able to specify much. One resource that simply return a string for testing, works all the time. A more complex resource that uses a database call and other operations, I am able to consistently call successfully and cause an internal server error every other call.. Totally weird behaviour!

Please let me know if this sounds at all related. This was a very shitty bug to track down, so please let me know, if you think this should be posted elsewhere. @tomchristie what do you think?

MrMathias picture MrMathias on 29 Mar 2020

@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.
jlienSage picture jlienSage on 4 Apr 2020
👍1

@tomchristie, you can replicate the issue as follows, but it does require an Azure subscription.

  1. Create a simple FastAPI api with a Dockerfile based off one of the "tiangolo/uvicorn-gunicorn" images. Push this container to a container registry.
  2. Create an Azure app service and have it use the container image you just created.
  3. Go to the /docs page for your Azure app service, confirm it works as expected.
  4. Go back to the Azure app service configuration and turn on CORS, allowing '*'.
  5. Make multiple requests within a few seconds of each other and observe every other request fails. I was able to do this with the /docs page and curl.
jlienSage picture jlienSage on 7 Apr 2020

Could you confirm this happens with a container running latest version of uvicorn?

I'm asking this because last time I popped a container from the image mentioned it was running uvicorn 0.9, so it would be helpful to see at least if you're running latest version of the code.

euri10 picture euri10 on 7 Apr 2020

@euri10
Not sure how to get that as the container doesn't have bash but it is running gunicorn 19.9.0. Using tiangolo/uvicorn-gunicorn:python3.7-alpine3.8.

jlienSage picture jlienSage on 7 Apr 2020

Use docker exec - it /bin/ash if it is alpine, or run uvicorn - - version,
or define a route returns uvicorn.__version__

Le mar. 7 avr. 2020 à 7:29 PM, John Lien notifications@github.com a
écrit :

@euri10 https://github.com/euri10
Not sure how to get that as the container doesn't have bash but it is
running gunicorn 19.9.0. Using
tiangolo/uvicorn-gunicorn:python3.7-alpine3.8.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/encode/uvicorn/issues/441#issuecomment-610517243, or
unsubscribe
https://github.com/notifications/unsubscribe-auth/AAINSPRCXD4WYIHBHXXKNSDRLNPHVANCNFSM4I25QUSA
.

euri10 picture euri10 on 7 Apr 2020

@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"

jlienSage picture jlienSage on 7 Apr 2020
👍1

I'm seeing this aswell - even with CORS off, but with Azure AD authentication enabled, just using the API docs hits the same issue - it is alternating requests give responses of 200/500/200/500 when calling from swagger UI to openapi.json

djpugh picture djpugh on 23 Jun 2020

The workaround for GNUICORN_CMD_ARGS works for me too.

djpugh picture djpugh on 23 Jun 2020

@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 �[41m�[30mfail�[39m�[22m�[49m: 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 �[41m�[30mfail�[39m�[22m�[49m: 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.

Today I uploaded my FastAPI app on Azure Web Service using Docker container and I am also facing same issue. Everything is working fine on the app but Docs and Static files are not working. Please suggest solution.

deependrasolanky picture deependrasolanky on 30 Jun 2020

@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 �[41m�[30mfail�[39m�[22m�[49m: 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 �[41m�[30mfail�[39m�[22m�[49m: 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.

Today I uploaded my FastAPI app on Azure Web Service using Docker container and I am also facing same issue. Everything is working fine on the app but Docs and Static files are not working. Please suggest solution.

I just tested again after removing CORS settings in Azure portal and everything is working fine.

deependrasolanky picture deependrasolanky on 30 Jun 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

joshua-s picture joshua-s  Â·  5Comments
rspadim picture rspadim  Â·  5Comments
yezyilomo picture yezyilomo  Â·  5Comments
adriangallegos picture adriangallegos  Â·  6Comments
unitto1 picture unitto1  Â·  7Comments