search

Chainlit / chainlit

Build Conversational AI in minutes ⚡️
https://docs.chainlit.io
Apache License 2.0
7.13k stars 935 forks source link

Login issue: Invalid request for /login/callback #691

Closed jdb78 closed 8 months ago

jdb78 commented 9 months ago

This is a strange one and only seems to happen if the app is deployed on Azure App Service. At login, sometimes (not always!), I get a Invalid HTTP request received. with status: 400 Bad request. If you refresh long enough, you eventually get logged in.

Here is a log with chainlit 1.0.200 where I annonymized some details.

You can see that it all passes the oauth callback (which does some additional pulling of data from graphapi) but then seems to error

2024-01-24T10:16:07.043042428Z 2024-01-24 10:16:07 - load_ssl_context verify=True cert=None trust_env=True http2=False
2024-01-24T10:16:07.043568126Z 2024-01-24 10:16:07 - load_verify_locations cafile='/opt/pysetup/.venv/lib/python3.11/site-packages/certifi/cacert.pem'
2024-01-24T10:16:07.049984803Z 2024-01-24 10:16:07 - connect_tcp.started host='login.microsoftonline.com' port=443 local_address=None timeout=5.0 socket_options=None
2024-01-24T10:16:07.064571449Z 2024-01-24 10:16:07 - connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7eea91f7ac10>
2024-01-24T10:16:07.064660998Z 2024-01-24 10:16:07 - start_tls.started ssl_context=<ssl.SSLContext object at 0x7eea91ddfc80> server_hostname='login.microsoftonline.com' timeout=5.0
2024-01-24T10:16:07.088082821Z 2024-01-24 10:16:07 - start_tls.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7eea91e03810>
2024-01-24T10:16:07.088632742Z 2024-01-24 10:16:07 - send_request_headers.started request=<Request [b'POST']>
2024-01-24T10:16:07.089092005Z 2024-01-24 10:16:07 - send_request_headers.complete
2024-01-24T10:16:07.089124546Z 2024-01-24 10:16:07 - send_request_body.started request=<Request [b'POST']>
2024-01-24T10:16:07.089195880Z 2024-01-24 10:16:07 - send_request_body.complete
2024-01-24T10:16:07.089214054Z 2024-01-24 10:16:07 - receive_response_headers.started request=<Request [b'POST']>
2024-01-24T10:16:07.211936736Z 2024-01-24 10:16:07 - receive_response_headers.complete return_value=...
2024-01-24T10:16:07.212810200Z 2024-01-24 10:16:07 - HTTP Request: POST https://login.microsoftonline.com/<org>/oauth2/v2.0/token "HTTP/1.1 200 OK"
2024-01-24T10:16:07.213145620Z 2024-01-24 10:16:07 - receive_response_body.started request=<Request [b'POST']>
2024-01-24T10:16:07.213417381Z 2024-01-24 10:16:07 - receive_response_body.complete
2024-01-24T10:16:07.213691256Z 2024-01-24 10:16:07 - response_closed.started
2024-01-24T10:16:07.213983875Z 2024-01-24 10:16:07 - response_closed.complete
2024-01-24T10:16:07.214681196Z 2024-01-24 10:16:07 - close.started
2024-01-24T10:16:07.214980919Z 2024-01-24 10:16:07 - close.complete
2024-01-24T10:16:07.215748171Z 2024-01-24 10:16:07 - load_ssl_context verify=True cert=None trust_env=True http2=False
2024-01-24T10:16:07.216307281Z 2024-01-24 10:16:07 - load_verify_locations cafile='/opt/pysetup/.venv/lib/python3.11/site-packages/certifi/cacert.pem'
2024-01-24T10:16:07.221995420Z 2024-01-24 10:16:07 - connect_tcp.started host='graph.microsoft.com' port=443 local_address=None timeout=5.0 socket_options=None
2024-01-24T10:16:07.228401798Z 2024-01-24 10:16:07 - connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7eea91f44650>
2024-01-24T10:16:07.228505553Z 2024-01-24 10:16:07 - start_tls.started ssl_context=<ssl.SSLContext object at 0x7eea91f38710> server_hostname='graph.microsoft.com' timeout=5.0
2024-01-24T10:16:07.237024910Z 2024-01-24 10:16:07 - start_tls.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7eea91f466d0>
2024-01-24T10:16:07.237356323Z 2024-01-24 10:16:07 - send_request_headers.started request=<Request [b'GET']>
2024-01-24T10:16:07.237779067Z 2024-01-24 10:16:07 - send_request_headers.complete
2024-01-24T10:16:07.238054084Z 2024-01-24 10:16:07 - send_request_body.started request=<Request [b'GET']>
2024-01-24T10:16:07.238066728Z 2024-01-24 10:16:07 - send_request_body.complete
2024-01-24T10:16:07.238538973Z 2024-01-24 10:16:07 - receive_response_headers.started request=<Request [b'GET']>
2024-01-24T10:16:07.317246218Z 2024-01-24 10:16:07 - receive_response_headers.complete return_value=...
2024-01-24T10:16:07.317763773Z 2024-01-24 10:16:07 - HTTP Request: GET https://graph.microsoft.com/v1.0/me "HTTP/1.1 200 OK"
2024-01-24T10:16:07.318247011Z 2024-01-24 10:16:07 - receive_response_body.started request=<Request [b'GET']>
2024-01-24T10:16:07.318719579Z 2024-01-24 10:16:07 - receive_response_body.complete
2024-01-24T10:16:07.318756488Z 2024-01-24 10:16:07 - response_closed.started
2024-01-24T10:16:07.319215370Z 2024-01-24 10:16:07 - response_closed.complete
2024-01-24T10:16:07.319984025Z 2024-01-24 10:16:07 - send_request_headers.started request=<Request [b'GET']>
2024-01-24T10:16:07.320456703Z 2024-01-24 10:16:07 - send_request_headers.complete
2024-01-24T10:16:07.320470869Z 2024-01-24 10:16:07 - send_request_body.started request=<Request [b'GET']>
2024-01-24T10:16:07.320476911Z 2024-01-24 10:16:07 - send_request_body.complete
2024-01-24T10:16:07.320481409Z 2024-01-24 10:16:07 - receive_response_headers.started request=<Request [b'GET']>
2024-01-24T10:16:07.384526130Z 2024-01-24 10:16:07 - receive_response_headers.complete return_value=...
2024-01-24T10:16:07.384929968Z 2024-01-24 10:16:07 - HTTP Request: GET https://graph.microsoft.com/v1.0/me/photos/48x48/$value "HTTP/1.1 200 OK"
2024-01-24T10:16:07.385041127Z 2024-01-24 10:16:07 - receive_response_body.started request=<Request [b'GET']>
2024-01-24T10:16:07.385904720Z 2024-01-24 10:16:07 - receive_response_body.complete
2024-01-24T10:16:07.385919167Z 2024-01-24 10:16:07 - response_closed.started
2024-01-24T10:16:07.385925599Z 2024-01-24 10:16:07 - response_closed.complete
2024-01-24T10:16:07.385930308Z 2024-01-24 10:16:07 - close.started
2024-01-24T10:16:07.387363762Z 2024-01-24 10:16:07 - close.complete
2024-01-24T10:16:07.387377898Z 2024-01-24 10:16:07 - load_ssl_context verify=True cert=None trust_env=True http2=False
2024-01-24T10:16:07.387383118Z 2024-01-24 10:16:07 - load_verify_locations cafile='/opt/pysetup/.venv/lib/python3.11/site-packages/certifi/cacert.pem'
2024-01-24T10:16:07.392968714Z 2024-01-24 10:16:07 - connect_tcp.started host='graph.microsoft.com' port=443 local_address=None timeout=5.0 socket_options=None
2024-01-24T10:16:07.398909850Z 2024-01-24 10:16:07 - connect_tcp.complete return_value=<httpcore._backends.sync.SyncStream object at 0x7eea91ec4710>
2024-01-24T10:16:07.398985512Z 2024-01-24 10:16:07 - start_tls.started ssl_context=<ssl.SSLContext object at 0x7eea91f38b00> server_hostname='graph.microsoft.com' timeout=5.0
2024-01-24T10:16:07.410364651Z 2024-01-24 10:16:07 - start_tls.complete return_value=<httpcore._backends.sync.SyncStream object at 0x7eea91f478d0>
2024-01-24T10:16:07.410971892Z 2024-01-24 10:16:07 - send_request_headers.started request=<Request [b'GET']>
2024-01-24T10:16:07.410997921Z 2024-01-24 10:16:07 - send_request_headers.complete
2024-01-24T10:16:07.411016646Z 2024-01-24 10:16:07 - send_request_body.started request=<Request [b'GET']>
2024-01-24T10:16:07.411023088Z 2024-01-24 10:16:07 - send_request_body.complete
2024-01-24T10:16:07.411028378Z 2024-01-24 10:16:07 - receive_response_headers.started request=<Request [b'GET']>
2024-01-24T10:16:07.652759272Z 2024-01-24 10:16:07 - receive_response_headers.complete return_value=...
2024-01-24T10:16:07.653235028Z 2024-01-24 10:16:07 - HTTP Request: GET https://graph.microsoft.com/v1.0/me/memberOf "HTTP/1.1 200 OK"
2024-01-24T10:16:07.653771356Z 2024-01-24 10:16:07 - receive_response_body.started request=<Request [b'GET']>
2024-01-24T10:16:07.654370993Z 2024-01-24 10:16:07 - receive_response_body.complete
2024-01-24T10:16:07.654384288Z 2024-01-24 10:16:07 - response_closed.started
2024-01-24T10:16:07.654389548Z 2024-01-24 10:16:07 - response_closed.complete
2024-01-24T10:16:07.654393736Z 2024-01-24 10:16:07 - close.started
2024-01-24T10:16:07.656100182Z 2024-01-24 10:16:07 - close.complete
2024-01-24T10:16:07.663496200Z 2024-01-24 10:16:07 - Update id='....' with User{'identifier': None, 'metadata': {'image': ...}}}
2024-01-24T10:16:07.674745547Z INFO: 169.254.134.8:50610 - "GET /auth/oauth/azure-ad/callback?code=<<code>>&session_state=.... HTTP/1.1" 307 Temporary Redirect
2024-01-24T10:16:07.691541245Z WARNING: Invalid HTTP request received.

In the browser the invalid HTTP request looks like this:

Request URL:
https://<<host>>.com/login/callback?access_token=<<token>>&token_type=bearer
Request Method:
GET
Status Code:
400 Bad Request
Remote Address:
20.90.134.32:443
Referrer Policy:
strict-origin-when-cross-origin
Content-Type:
text/plain; charset=utf-8
Date:
Tue, 23 Jan 2024 21:54:12 GMT
Transfer-Encoding:
chunked
Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7
Accept-Encoding:
gzip, deflate, br
Accept-Language:
en-GB,en;q=0.9
Cache-Control:
max-age=0
Connection:
keep-alive
Dnt:
1
Host:
<<host>>.com
Sec-Ch-Ua:
"Not_A Brand";v="8", "Chromium";v="120", "Google Chrome";v="120"
Sec-Ch-Ua-Mobile:
?0
Sec-Ch-Ua-Platform:
"macOS"
Sec-Fetch-Dest:
document
Sec-Fetch-Mode:
navigate
Sec-Fetch-Site:
none
Sec-Fetch-User:
?1
Upgrade-Insecure-Requests:
1
User-Agent:
Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36

Any idea where the issue might come from? / Suggestions how to debug this?

willydouhard commented 9 months ago

Did you set the CHAINLIT_URL env variable?

jdb78 commented 9 months ago

Yes. That is set. Otherwise it would also never work. The issue is intermittent, so it works if you just refresh sufficiently often. I am not sure where the error occurs and how to get a proper traceback on it.

jdb78 commented 9 months ago

The issue might be uvicorn. What seemed to help (tbc) is installing uvicorn with the standard extra. I think this adds httptools and uvloop. Running things now with UVICORN_HTTP=httptools and UVICORN_TIMEOUT_KEEP_ALIVE=0 and have not seen any issues with new users.

tpatel commented 8 months ago

Closing as this has been solved. Thanks for having shared your solution, feel free to re-open if it pops up again.

hayescode commented 5 months ago

@jdb78 I am glad I found this thread!! I also am having this issue in Azure App Service.

Just to be clear all you did was set those environment variables in the app service and that fixed it?