Fast API는 python3 ASGI WAS 프레임워크입니다.
흔히 웹서버로 uvicorn을 사용하고있습니다.
이번 포스팅은 client > proxy(i.g. nginx) > uvicorn > Fast API 통신과정에서 uvicorn까지 트래픽이 들어왔지만 Fast API의 미들웨어에 인입 로그도 찍히지 않고 request가 지연되는 현상에 대한 트러블슈팅입니다.
이슈 확인
1. background task 기능을 포함한 API를 호출후, 다음 API 요청이 간헐적으로 매우 느림(오지 않음)
2. Fast API의 미들웨어 로그상 아무런 요청/인입이 없음
3. background task가 완료되면 요청이 들어옴
원인
1. Keep-alive 유지
매번 발생하는 이슈가 아니여서 원인을 찾는게 쉽지 않았지만, 공통점을 찾았고 keep alive와 관련있음을 확인했습니다.
keep alive 이슈를 찾기 어려웠던 이유는 Fast API로 만든 서버와 통신하는 client 또한 python3 기반으로 만든 CLI Tool이었기 때문에 keep alive가 적용될 거라고 생각하기 어려웠습니다.
CLI tool은 requests 패키지의 Session 클래스 기반으로 통신하여 한번의 명령어(Process)안에 여러번 호출되는 Session은 keep alive가 적용되겠지만 , CLI 도구의 서로 다른 실행은 Process가 새로 실행되는 것이기 때문에 keep alive가 당연히 유지되지 않을 거라고 생각했습니다. 그리고 일반적인 상황에서는 Process가 죽으면 소켓이 파괴되므로 당연합니다.
다만, 위 통신과정을 보면 proxy를 사용하고 있는데 client는 소켓을 파괴시켰지만 proxy가 소켓을 재사용하면서 proxy와 was간 keep alive가 유지된 것으로 추측하고 있습니다. -> (아직 확인중)
위에서 사용하는 proxy는 쿠버네티스 환경의 ingress-nginx-controller이며, 커널의 SO_REUSEADDR 옵셔을 사용하고 있는 것으로 보입니다. 해당 옵션은 time_wait의 상태등의 소켓을 재사용할 수 있게하여 포트가 고갈되지 않게합니다.
https://github.com/nginx/nginx/blob/master/src/core/ngx_connection.c#L498
만약 이런식으로 proxy가 소켓을 재사용하는 경우, FastAPI 서버측에서 keep-alive가 유지된게 아닐까 추측중입니다.
proxy가 재사용하는 조건에 대해서는 아직 입증하지 못했습니다.
일단 로컬에서 띄운 FastAPI와 통신에서는 재현되지 않았지만, ingress-nginx-controller를 사용하는 환경에서만 간헐적으로 재현되고 있습니다.
2. Keep-alive에서 FastAPI.BackgroundTasks의 wait 버그
FastAPI, uvicorn에 버그가 있습니다.. (누가 버그라고 해야될까..)
23년 7월 17일 기준 최신 FastAPI, uvicorn을 사용해도 동일합니다.
Fast API는 기본적으로 endpoint 함수가 서브루티인 경우, loop.run_in_executor 함수를 통해 코루틴을 랩핑한 쓰레드로 실행합니다.
BackgroundTasks도 같은 원리인데, 문제는 uvicorn에게 send() 함수를 통해서 response를 보냈지만 아직 backgroundTask를 await하면서 http connection을 아직 해당 쓰레드에서 점유하고 있는 문제가 있습니다...
(ASGI app <> ASGI server는 send, receive 함수/인터페이스를 통해 서로 정보를 전달합니다.)
--> send, receive가 uvicorn에서 개발된 함수이며 인터페이스는 ASGI 명세를 따릅니다.
--> send, receive를 호출함으로서 uvicron에게 콜백되는 구조입니다.
--> 최초의 인입점인 uvicorn은 ASGIapp(sope, send,receive) 방식으로 호출하여 ASGI app에게 데이터와 인터페이스를 넘깁니다.
--> ASGIapp의 최초 인입점이 __call__인 이유입니다. (서로 호출하는 방식은 ASGI의 명세)
--------------
아래는 starlette > response.py 파일의 StreamingResponse 구현입니다.
(Starlette은 FastAPI가 사용하는 ASGI app 개발도구입니다.)
Starlette이 uvicorn으로 header부분을 포함한 앞부분을 먼저 보내고, StreamingResponse를 통해 body부분을 보냅니다.
보시듯이 Starlette background 작업이 있는 경우, uvicorn에게 send를 보내고(recevie도 받고) client가 response를 받도록합니다.
문제는 background 작업이 끝나기 전까지 uvicorn도 해당 http_transaction 코루틴은 이벤트루프에서 함께 멈추는데 (await background로 인해서) uvicorn은 keep-alive 로직부터 끝났다고 판단을 못시킨 것으로 보입니다. --> 실제로 코루틴이 멈춘 시점이후로 keep-alive 카운팅도 멈춤
* uvicorn은 more_body : False를 받아야 http_transaction을 죽이는 것으로 보입니다.
* Starlette의 위 run_until_first_complete 내부에 stream_response, listen_for_disconnect 로직을 보면 body 전송과 more_body: False까지 처리합니다.
* 모든 과정이 끝나야 backgroundTask가 실행됩니다.
하지만, 아래에서 실제 테스트한 결과는 ... body_iterator 부분과 마지막 send more_body: False 사이에 BackgroundTask가 실행되고 그 동안 uvicorn 코루틴은 멈춰있습니다.
--------------
정상적인 동작인 경우, keep-alive 설정이 있더라도 request/response가 끝났다면 uvicorn과 커뮤니케이션을 통해 http.disconnect 상태에 돌입하고 uvicorn은 keep-alive timeout 시간까지만 소켓을 유지시키다 파괴합니다.
아래는 정상적인 uvicorn/FastAPI의 keep-alive 통신 trace log입니다.
# uvicorn main:app --log-level trace
# 첫번째 API 요청
# HTTP connection made 소켓 생성
2023-07-17 06:56:10,850 TRACE - [ID:None][h11_impl][connection_made][132] 127.0.0.1:56071 - HTTP connection made
2023-07-17 06:56:10,851 TRACE - [ID:None][message_logger][trace][43] 127.0.0.1:56071 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 56071), 'scheme': 'http', 'method': 'GET', 'root_path': '', 'path': '/test', 'raw_path': b'/test', 'query_string': b'', 'headers': '<...>', 'state': {}}
2023-07-17 06:56:10,851 INFO - [ID:a20971db][middlware][custom_middleware][105] Start HTTPTransaction: 127.0.0.1:56071 - "GET /test"
2023-07-17 06:56:10,854 INFO - [ID:a20971db][middlware][custom_middleware][117] Completed HTTPTransaction: 127.0.0.1:56071 - "GET /test"
# FastAPI(ASGI app) --> uvicorn에게 200 및 header 정보 전달
2023-07-17 06:56:10,855 TRACE - [ID:a20971db][message_logger][trace][43] 127.0.0.1:56071 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
2023-07-17 06:56:10,855 INFO - [ID:a20971db][h11_impl][send][489] 127.0.0.1:56071 - "GET /test HTTP/1.1" 200
# 그 뒤로 Body(stream) 정보 순차적으로 전달
2023-07-17 06:56:10,855 TRACE - [ID:a20971db][message_logger][trace][43] 127.0.0.1:56071 - ASGI [2] Send {'type': 'http.response.body', 'body': '<16 bytes>', 'more_body': True}
2023-07-17 06:56:10,855 TRACE - [ID:a20971db][message_logger][trace][43] 127.0.0.1:56071 - ASGI [2] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False}
# more_body=False를 보내고, uvicorn은 http.connection을 종료시키고 FastAPI는 해당 내용을 수신함(receive) / http layer에서 종료지, 소켓이 파괴된건 아님
2023-07-17 06:56:10,855 TRACE - [ID:a20971db][message_logger][trace][43] 127.0.0.1:56071 - ASGI [2] Receive {'type': 'http.disconnect'}
2023-07-17 06:56:10,855 TRACE - [ID:a20971db][message_logger][trace][43] 127.0.0.1:56071 - ASGI [2] Completed
# keep-alive-timeout전에 다시 요청시 소켓 재사용으로 생성 없음
2023-07-17 06:56:15,477 TRACE - [ID:None][message_logger][trace][43] 127.0.0.1:56071 - ASGI [3] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 56071), 'scheme': 'http', 'method': 'GET', 'root_path': '', 'path': '/test', 'raw_path': b'/test', 'query_string': b'', 'headers': '<...>', 'state': {}}
2023-07-17 06:56:15,477 INFO - [ID:7dd296c6][middlware][custom_middleware][105] Start HTTPTransaction: 127.0.0.1:56071 - "GET /test"
2023-07-17 06:56:15,480 INFO - [ID:7dd296c6][middlware][custom_middleware][117] Completed HTTPTransaction: 127.0.0.1:56071 - "GET /test"
2023-07-17 06:56:15,481 TRACE - [ID:7dd296c6][message_logger][trace][43] 127.0.0.1:56071 - ASGI [3] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
2023-07-17 06:56:15,481 INFO - [ID:7dd296c6][h11_impl][send][489] 127.0.0.1:56071 - "GET /test HTTP/1.1" 200
2023-07-17 06:56:15,482 TRACE - [ID:7dd296c6][message_logger][trace][43] 127.0.0.1:56071 - ASGI [3] Send {'type': 'http.response.body', 'body': '<16 bytes>', 'more_body': True}
2023-07-17 06:56:15,482 TRACE - [ID:7dd296c6][message_logger][trace][43] 127.0.0.1:56071 - ASGI [3] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False}
2023-07-17 06:56:15,483 TRACE - [ID:7dd296c6][message_logger][trace][43] 127.0.0.1:56071 - ASGI [3] Receive {'type': 'http.disconnect'}
2023-07-17 06:56:15,483 TRACE - [ID:7dd296c6][message_logger][trace][43] 127.0.0.1:56071 - ASGI [3] Completed
# 5초가 지나서 소켓이 파괴됨 / HTTP connection lost
2023-07-17 06:56:20,483 TRACE - [ID:None][h11_impl][connection_lost][139] 127.0.0.1:56071 - HTTP connection lost
# 그후 재요청하게되면 소켓을 다시 생성함 / HTTP connection made
2023-07-17 06:56:24,186 TRACE - [ID:None][h11_impl][connection_made][132] 127.0.0.1:56116 - HTTP connection made
2023-07-17 06:56:24,187 TRACE - [ID:None][message_logger][trace][43] 127.0.0.1:56116 - ASGI [4] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 56116), 'scheme': 'http', 'method': 'GET', 'root_path': '', 'path': '/test', 'raw_path': b'/test', 'query_string': b'', 'headers': '<...>', 'state': {}}
2023-07-17 06:56:24,187 INFO - [ID:dc950ed6][middlware][custom_middleware][105] Start HTTPTransaction: 127.0.0.1:56116 - "GET /test"
2023-07-17 06:56:24,188 INFO - [ID:dc950ed6][middlware][custom_middleware][117] Completed HTTPTransaction: 127.0.0.1:56116 - "GET /test"
2023-07-17 06:56:24,189 TRACE - [ID:dc950ed6][message_logger][trace][43] 127.0.0.1:56116 - ASGI [4] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
2023-07-17 06:56:24,189 INFO - [ID:dc950ed6][h11_impl][send][489] 127.0.0.1:56116 - "GET /test HTTP/1.1" 200
2023-07-17 06:56:24,189 TRACE - [ID:dc950ed6][message_logger][trace][43] 127.0.0.1:56116 - ASGI [4] Send {'type': 'http.response.body', 'body': '<16 bytes>', 'more_body': True}
2023-07-17 06:56:24,189 TRACE - [ID:dc950ed6][message_logger][trace][43] 127.0.0.1:56116 - ASGI [4] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False}
2023-07-17 06:56:24,189 TRACE - [ID:dc950ed6][message_logger][trace][43] 127.0.0.1:56116 - ASGI [4] Receive {'type': 'http.disconnect'}
2023-07-17 06:56:24,190 TRACE - [ID:dc950ed6][message_logger][trace][43] 127.0.0.1:56116 - ASGI [4] Completed
2023-07-17 06:56:29,191 TRACE - [ID:None][h11_impl][connection_lost][139] 127.0.0.1:56116 - HTTP connection l
문제는 backgroundTasks()를 사용할 때, FastAPI가 backgroundTasks를 완료할 때까지 more_body=False를 uvicorn에게 전송하지 않고 await 한다는 것입니다. (하지만 response는 정상적으로 보냅니다. 보내는 원리는 아래에서 설명)
아래는 간단한 backgroundTasks를 사용하는 endpoint 함수입니다.
참고로 저는 keep-alive 통신은 chrome -> fastapi-swagger에서 진행했습니다. (그외 requests.Session등으로도 재현 가능합니다.)
@app.get('/test')
def test(background_tasks: BackgroundTasks):
rid = g().request_id
def task():
print("background start!", rid)
time.sleep(10)
print("background end", rid)
backgroundTasks.add_task(task)
# task()
return {"a": rid}
# 동일한 http transaction의 log는 ID 필드로 분류 가능합니다.
# ID 필드는 custom_middleware 단계에서 contextvar를 통해 할당합니다. -> 동일한 thread에서 공유하는 값
backgroundTasks 비정상 통신 로그
# 첫 요청, 소켓 생셩 및 연결
2023-07-17 07:14:53,763 TRACE - [ID:None][h11_impl][connection_made][132] 127.0.0.1:60480 - HTTP connection made
2023-07-17 07:14:53,763 TRACE - [ID:None][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 60480), 'scheme': 'http', 'method': 'GET', 'root_path': '', 'path': '/test', 'raw_path': b'/test', 'query_string': b'', 'headers': '<...>', 'state': {}}
2023-07-17 07:14:53,764 INFO - [ID:9d531154][middlware][custom_middleware][105] Start HTTPTransaction: 127.0.0.1:60480 - "GET /test"
# 백그라운드 시작
background start! 9d531154
2023-07-17 07:14:53,766 INFO - [ID:9d531154][middlware][custom_middleware][117] Completed HTTPTransaction: 127.0.0.1:60480 - "GET /test"
2023-07-17 07:14:53,767 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
2023-07-17 07:14:53,767 INFO - [ID:9d531154][h11_impl][send][489] 127.0.0.1:60480 - "GET /test HTTP/1.1" 200
2023-07-17 07:14:53,768 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Send {'type': 'http.response.body', 'body': '<16 bytes>', 'more_body': True}
# 보통의 경우, FastAPI -> uvicorn으로 more_body=False를 전송하지만, 이번에는 uvicorn에게 받음
# client측에서 더 받을 정보가 없다고 응답 받았기 때문으로 추측, client -> uvicorn -> Fast API(receive)로 more_body=False
2023-07-17 07:14:53,768 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Receive {'type': 'http.request', 'body': '<0 bytes>', 'more_body': False}
# 여기서 부터 문제..
# background가 끝날 때까지, 그 누구도 해당 http transaction(thread)와 http 연결을 닫지 않음
background end 9d531154
# background가 끝나니 정상일때와 같은 상황으로 FastAPI -> uvicorn으로 'more_body': False send
2023-07-17 07:15:03,772 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False}
# send를 받으니 이제서야 uvicorn이 연결을 종료됬다고 응답받음
2023-07-17 07:15:03,773 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Receive {'type': 'http.disconnect'}
# 그리고 한참전에 보냈었던 요청이 이제서야 uvicorn -> FastAPI로 전송됨
# 보다싶히 ID가 이전 그대로임, ID는 쓰레드에서 공유하는 값이므로 원래라면 custom_middleware에서 셋팅전에는 None이 정상임
# 즉, 이전과 동일한 thread에서 이번 요청을 받아버림 -> 이래서 background가 끝날떄까지 await을 모두 기다린 것으로 추정
2023-07-17 07:15:03,773 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [3] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 60480), 'scheme': 'http', 'method': 'GET', 'root_path': '', 'path': '/test', 'raw_path': b'/test', 'query_string': b'', 'headers': '<...>', 'state': {}}
2023-07-17 07:15:03,773 INFO - [ID:0e8988ff][middlware][custom_middleware][105] Start HTTPTransaction: 127.0.0.1:60480 - "GET /test"
# Completed 메시지가 이제야 들어옴, 위에서 ID를 바꿨지만 예전 ID인 걸로봣서는 Started scop 첫 인입만 동일한 thread였고 그후 새로운 thread로 분기된 것으로 보임, 아마 starlette의 코루틴, 서브루틴 분기문에서 신규 thread가 실행된 듯
2023-07-17 07:15:03,776 TRACE - [ID:9d531154][message_logger][trace][43] 127.0.0.1:60480 - ASGI [2] Completed
background start! 0e8988ff
2023-07-17 07:15:03,777 INFO - [ID:0e8988ff][middlware][custom_middleware][117] Completed HTTPTransaction: 127.0.0.1:60480 - "GET /test"
# client쪽에서 먼저 끊었지만 일단은 response는 정상적으로 갔음
2023-07-17 07:15:03,777 TRACE - [ID:0e8988ff][message_logger][trace][43] 127.0.0.1:60480 - ASGI [3] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
2023-07-17 07:15:03,777 INFO - [ID:0e8988ff][h11_impl][send][489] 127.0.0.1:60480 - "GET /test HTTP/1.1" 200
2023-07-17 07:15:03,777 TRACE - [ID:0e8988ff][message_logger][trace][43] 127.0.0.1:60480 - ASGI [3] Send {'type': 'http.response.body', 'body': '<16 bytes>', 'more_body': True}
2023-07-17 07:15:03,778 TRACE - [ID:0e8988ff][message_logger][trace][43] 127.0.0.1:60480 - ASGI [3] Receive {'type': 'http.request', 'body': '<0 bytes>', 'more_body': False}
# H11Protocal은 uvicorn에서 Http 연결 하나를 표현하는 객체 클래스임
# timeout_keep_alive 시간은 한참전에 끝났는데 이제야 keep_alive보고 소켓을 죽이는 분기문에 도착해서 error를 발생 시킨 것으로 추측
# 내용을 보면 timeout을 넘겨서 죽여야하는데, 아직 send_body 상태이므로 error가 발생된 듯
Exception in callback <bound method H11Protocol.timeout_keep_alive_handler of <uvicorn.protocols.http.h11_impl.H11Protocol object at 0x1143093a0>>
handle: <TimerHandle H11Protocol.timeout_keep_alive_handler>
Traceback (most recent call last):
File "uvloop/cbhandles.pyx", line 252, in uvloop.loop.TimerHandle._run
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py", line 374, in timeout_keep_alive_handler
self.conn.send(event)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_connection.py", line 510, in send
data_list = self.send_with_data_passthrough(event)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_connection.py", line 535, in send_with_data_passthrough
self._process_event(self.our_role, event)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_connection.py", line 272, in _process_event
self._cstate.process_event(role, type(event), server_switch_event)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_state.py", line 289, in process_event
self._fire_event_triggered_transitions(role, _event_type)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_state.py", line 307, in _fire_event_triggered_transitions
raise LocalProtocolError(
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_BODY
# 결국 시간이 지나서 두번쨰 요청의 background도 종료됨
background end 0e8988ff
# 첫번째 요청과 마찬가지로 이제서야 'more_body': False를 전송함
2023-07-17 07:15:13,783 TRACE - [ID:0e8988ff][message_logger][trace][43] 127.0.0.1:60480 - ASGI [3] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False}
# 이전에 H11Protocal의 상태가 Error로 변경됬고 해당 상태에서 send와 같은 나머지 처리는 error로 raise 하는 듯
2023-07-17 07:15:13,784 TRACE - [ID:0e8988ff][message_logger][trace][43] 127.0.0.1:60480 - ASGI [3] Raised exception
2023-07-17 07:15:13,785 ERROR - [ID:0e8988ff][h11_impl][run_asgi][424] Exception in ASGI application
Traceback (most recent call last):
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py", line 419, in run_asgi
result = await app( # type: ignore[func-returns-value]
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/middleware/proxy_headers.py", line 84, in __call__
return await self.app(scope, receive, send)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/middleware/message_logger.py", line 84, in __call__
raise exc from None
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/middleware/message_logger.py", line 80, in __call__
await self.app(scope, inner_receive, inner_send)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/fastapi/applications.py", line 199, in __call__
await super().__call__(scope, receive, send)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/applications.py", line 112, in __call__
await self.middleware_stack(scope, receive, send)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/middleware/errors.py", line 181, in __call__
raise exc from None
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/middleware/errors.py", line 159, in __call__
await self.app(scope, receive, _send)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/middleware/base.py", line 26, in __call__
await response(scope, receive, send)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/responses.py", line 224, in __call__
await run_until_first_complete(
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/concurrency.py", line 24, in run_until_first_complete
[task.result() for task in done]
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/concurrency.py", line 24, in <listcomp>
[task.result() for task in done]
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/responses.py", line 221, in stream_response
await send({"type": "http.response.body", "body": b"", "more_body": False})
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/starlette/middleware/errors.py", line 156, in _send
await send(message)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/middleware/message_logger.py", line 74, in inner_send
await send(message)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py", line 521, in send
output = self.conn.send(event)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_connection.py", line 510, in send
data_list = self.send_with_data_passthrough(event)
File "/Users/ahsung/PycharmProjects/test-api/venv/lib/python3.9/site-packages/h11/_connection.py", line 525, in send_with_data_passthrough
raise LocalProtocolError("Can't send data when our state is ERROR")
h11._util.LocalProtocolError: Can't send data when our state is ERROR
# 최종적으로 소켓을 죽임
2023-07-17 07:15:13,795 TRACE - [ID:None][h11_impl][connection_lost][139] 127.0.0.1:60480 - HTTP connection lost
문제를 보면, 정상 상태일 때 FastAPI (ASGI app)은 endpoint 함수의 작업을 끝내고 아래 과정으로 진행합니다.
1. body를 send()함수를 통해 uvicorn으로 stream/나눠서 전송
2. 다 보내면 more_body = False를 uvicorn으로 전송
3. uvicorn은 ASGI app으로 부터 more_body를 받으면 http transaction, thread를 종료시킴 (소켓은 keep-alive까지 그대로 유지함)
4. keep-alive를 사용한 새로운 요청이 오면, 새로운 http transaction(thread)에 기존 소켓을 그대로 사용해서 진행함
- 소켓을 그대로 가져간다는 것은 H11Protocal 객체가 그대로 사용된 다는 것! (참고로 H11Protocal를 사용하는 곳은 asyncio.server 함수이다. / uvicorn 내부에서 사용)
backgroundTasks가 실행되는 경우, endpoint 함수가 반환됬음에도 2번 과정이 바로 실행이 안됩니다.
대신, client가 정상적으로 응답을 받을 수 있었던 이유는 client가 body stream을 전부 받고 더이상 받을 body가 없다고 판단하여 client측에서 먼저 종료를 보냈기 때문으로 추측됩니다. -> 그래서 more_body = False가 client -> uvicorn -> ASGI app 방향
즉, server는 아직 http transaction이 종료됬다고 생각하지 않지만, client는 다 받았다고 생각하여 끊은 상태입니다.
결국 uvicorn은 기존 http transaction(세션,thread)와 소켓의 연결을 그대로 유지한 상태이다보니 다음 요청이 keep-alive로 들어왔을 때, 아직 http transaction(backgroundTask)가 진행중이니 대기 상태라고 볼 수 있습니다.
backgroundTask가 완료되면, more_body = False를 FastAPI가 send하고 그제서야 다음 요청을 처리하는 것으로 보입니다.
* 로그를보면 header+앞부분을 먼저 보내고 background가 실행 -> StreamResponse가 실행되더군요..
* 성능 때문에 누군가 먼저 header response만 보내고 background를 실행한 것 (send,recive) 같습니다. (FastAPI에서 튜닝한건지..)
아래는 starlette > response.py > Response 클래스 내용 부분입니다.
StreamingResponse를 제외한 모든 Response는 위 현상을 설명할 수 있는 로직처럼 실행되는 것 같네요
그럼에도 StreamingResponse를 고려했던 이유는 `starlette > middleware > base.py > BaseHTTPMiddleware`가 사용하기 때문입니다.
저도 Custom 미들웨어를 추가할때, 해당 클래스를 사용했구요.
만약 지금 현상을 추측해본다면 아래처럼 설명할 수 있을 것 같습니다.
## 추측
- BaseHTTPMiddleware로 인입 -> call_next 통해서 ASGI app(endpoint function) 전달
- 미들웨어 반환전, 다른 layer에서 header부분과 body 첫 부분을 적당히 전송 / response 실행-> await response()
- 위 로직과 같이 backgroundTask에서 await으로 현재 call_stack에 쌓인 코루틴들은 대기
- uvicorn(client)에서 more_body: False 받음(receive) --> 외부에서 보는 client<>서버간 http 통신은 종료
- backgroundTask 대기 -> uvicorn <> FastAPI 통신 대기 -> background 종료
- BaseHTTPMiddleware의 call_next가 반환됨, 이후에 남은 body_stream을 보내기 시작함
만약 이 추측이 맞다면, 매우 큰용량의 Body를 쌓아서 보내게되도 background 끝나기전까지 그 다음 Body stream도 pending될 확률이 높아보입니다.
결국 현재 버그는 FastAPI, uvicorn간 서로 동작하는 방식을 잘 못이해한데서 발생한게 아닐까 싶습니다..
1. uvicorn은 ASGI app으로부터 more_body = False를 받아야만 http transaction을 정상 종료합니다.
2. 1번을 불변으로 생각한다면, Fast API는 backgroudnTasks를 기다리지말고 more_body = False를 보냈어야합니다. (1차 관점)
3. uvicorn은 client로부터 더이상 받을 데이터가 없다고 전달 받았을 때, ASGI app은 more_body = False를 receive했습니다.
- 그렇다면 이때라도, FastAPI(ASGI app)은 more_body = False를 전송해서 종료되게끔 했어야합니다.
4. 1번을 버그로 생각할 수도 있습니다. uvicorn은 client로부터 더이상 받을 데이터가 없다고 전달 받았다면 fastapi(ASGi app) 상관없이 스스로 종료시키도록 개발되었어야합니다.
keep-alive 요청이 아니라면, 사실 H11Protocal이 모두 따로 생성되기 때문에 위와 같은 지연 현상은 없습니다.
(H11Protocal간 코루틴은 서로 분기되어 병렬로 실행 / 서로 콜스택 관계가 아님)
하지만 proxy로 인해서 keep-alive가 어쩔수 없이 발생한다면 ... proxy 서버의 SO_REUSEADDR을 막아야하는건지... 애매한 상황이죠
--> 첨고로 uvicorn의 keep-ailive를 끄는 방법은 "0"으로 설정해서 파괴 시키는 것 밖에 없습니다.
--> uvicorn의 소켓이 파괴되기전에 상대가 어쩄든 동일한 소켓을 다시 보내면 일단 keep-alive 로직을 타긴합니다.
--> 다만, 일반적으로 0초면 무조건 먼저 파괴되니까 이슈 없지만 어쩄든 background task로 소켓파괴가 미뤄지만 답없음
(일반적인 상황에서, keep-alive가 아닌데 소켓 파괴전에 중첩으로 보낸다는건 소켓이 현재 진행중인 http transaction외 트래픽이 흘러들어오는 것으로 판단할 수 있음 -> 이건 해킹수준의 동작임 / 실제 해킹이면 tcp seq num이 깨질 확률이 높음)
정말 http transaction(protocal)이 끝나지 않은거라면 keep alive에서 소켓을 아직 이전 transaction이 점유중이니 지연되는건 지극히 정상적인 상황입니다.
keep-alive의 경우 H11Protocal 객체를 그대로 공유하게되면서 H11Protocal 객체가 이전의 endpoint 함수를 await할 때까지 새로운 요청이 기다리는 것은 맞지만, backgroundTask는 목적성을 보면 http transaction과는 상관이 없는 추가 작업이죠
H11Protocal이 endpoint 함수를 await하는 코루틴 콜스택과 BackgroundTask의 코루틴이 별개로 진행됬으면 어땟을까 싶네요
(물론 저는 async def가 아니므로 사실상 thread를 래핑한 코루틴입니다.)
솔루션
아직 솔루션을 제대로 적용해보지는 못했지만, 단순하게 backgroundTask를 안쓰면 되지 않을까 싶습니다.
backgroudTask는 FastAPI에서 자동으로 인식해서 실행하고 H11Protocal 객체가 굳이 backgroundTask까지 기다리는게 문제인게 아닐까 싶습니다.
backgroundTask를 사용하지 않고 H11Protocal이 await할 코루틴을 인식할 필요 없도록 자체적으로 background task 모듈을 개발하면 어떨까 싶네요.
1. 코루틴을 쓴다면, asyncio.create_task를 사용해서 이벤트루프에서 독립적인 코루틴으로 실행
2. 서브루틴이라면, 일반 thread 모듈 예로 threading.Thread를 사용해서 실행 (테스트 완료 -> 가능)
참고로 backgroundTasks는 서브루틴을 실행할 때, threadpoolexecutor를 default executor로 실행합니다. (조정 불가능)
default executor는 endpoint 함수가 서브루틴인 경우도 사용하고, default executor는 컴퓨터 CPU의 + 4 ~ 6 정도로 그 이상의 thread는 동시에 실행되고 있을 수 없어서 제약이 있습니다.
(--> --workers를 늘리면 늘어나나?_)
-------------
uvicorn과 starlette의 중요 class, 함수 로직들을 봤을 때는 크게 문제는 없어보였습니다.
대체왜.. backgroundTask가 uvicorn <> starllette 통신이 모두 끝나고 실행되는게 아니라 중간에 실행된건진 모르겠지만
자세한 원인은 실제로 코드에 breaking point를 찍어가면서 찾아봐야될거 같습니다.
'Python > FastAPI' 카테고리의 다른 글
| FastAPI can not use request body in middleware / 미들웨어에서 request body 사용 불가 / FastAPI(starlette) AGSI flow (1) | 2022.04.10 |
|---|
댓글