8000 fix h11 LocalProtocolError on connection close by client by alexrashed · Pull Request #9190 · localstack/localstack · GitHub
[go: up one dir, main page]
Skip to content

fix h11 LocalProtocolError on connection close by client #9190

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
merged 1 commit into from
Sep 20, 2023
Merged

fix h11 LocalProtocolError on connection close by client #9190

merged 1 commit into from
Sep 20, 2023

Conversation

alexrashed
Copy link
Member

Motivation

This PR fixes a cosmetic error when a client unexpectedly closes the connection, because h11 would try to send a response with a predefined content length, even though the connection has been closed and there's no body left to send.
This can be reproduced f.e. if you exploit the initial service catalog cache building (which takes ~1.5 seconds):

  • Start a bash which fires health requests to the (not yet running) LocalStack instance: 
    until curl --fail --silent --max-time 1 http://localhost:4566/_localstack/health; do sleep "0.1"; done
  • Remove existing service catalog caches: 
    sudo rm -rf ~/.cache/localstack/volume/cache/
  • Afterwards start LocalStack: 
    localstack start
  • The following error will be logged: 
    2023-09-20T14:01:05.126 DEBUG --- [-functhread6] localstack.http.asgi       : Error while writing responses: Connection closed (client_info: 172.17.0.1:56602)
2023-09-20T14:01:05.128 ERROR --- [-functhread6] hypercorn.error            : Error in ASGI Framework
Traceback (most recent call last):
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/asyncio/task_group.py", line 23, in _handle
await app(scope, receive, send, sync_spawn, call_soon)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/app_wrappers.py", line 33, in __call__
await self.app(scope, receive, send)
File "/opt/code/localstack/localstack/aws/serving/asgi.py", line 70, in __call__
return await self.adapter(scope, receive, send)
File "/opt/code/localstack/localstack/http/asgi.py", line 488, in __call__
return await self.handle_http(scope, receive, send)
File "/opt/code/localstack/localstack/http/asgi.py", line 559, in handle_http
await response.close()
File "/opt/code/localstack/localstack/http/asgi.py", line 311, in close
await self.send({"type": "http.response.body", "body": b"", "more_body": False})
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/protocol/http_stream.py", line 188, in app_send
await self.send(EndBody(stream_id=self.stream_id))
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/protocol/h11.py", line 138, in stream_send
await self._send_h11_event(h11.EndOfMessage())
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/protocol/h11.py", line 240, in _send_h11_event
data = self.connection.send(event)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_connection.py", line 512, in send
data_list = self.send_with_data_passthrough(event)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_connection.py", line 545, in send_with_data_passthrough
writer(event, data_list.append)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_writers.py", line 67, in __call__
self.send_eom(event.headers, write)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_writers.py", line 96, in send_eom
raise LocalProtocolError("Too little data for declared Content-Length")
h11._util.LocalProtocolError: Too little data for declared Content-Length
2023-09-20T14:01:05.128 ERROR --- [-functhread6] hypercorn.error            : Error in ASGI Framework
Traceback (most recent call last):
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/asyncio/task_group.py", line 23, in _handle
await app(scope, receive, send, sync_spawn, call_soon)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/app_wrappers.py", line 33, in __call__
await self.app(scope, receive, send)
File "/opt/code/localstack/localstack/aws/serving/asgi.py", line 70, in __call__
return await self.adapter(scope, receive, send)
File "/opt/code/localstack/localstack/http/asgi.py", line 488, in __call__
return await self.handle_http(scope, receive, send)
File "/opt/code/localstack/localstack/http/asgi.py", line 559, in handle_http
await response.close()
File "/opt/code/localstack/localstack/http/asgi.py", line 311, in close
await self.send({"type": "http.response.body", "body": b"", "more_body": False})
File "/opt/
8000
code/localstack/.venv/lib/python3.10/site-packages/hypercorn/protocol/http_stream.py", line 188, in app_send
await self.send(EndBody(stream_id=self.stream_id))
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/protocol/h11.py", line 138, in stream_send
await self._send_h11_event(h11.EndOfMessage())
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/hypercorn/protocol/h11.py", line 240, in _send_h11_event
data = self.connection.send(event)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_connection.py", line 512, in send
data_list = self.send_with_data_passthrough(event)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_connection.py", line 545, in send_with_data_passthrough
writer(event, data_list.append)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_writers.py", line 67, in __call__
self.send_eom(event.headers, write)
File "/opt/code/localstack/.venv/lib/python3.10/site-packages/h11/_writers.py", line 96, in send_eom
raise LocalProtocolError("Too little data for declared Content-Length")
h11._util.LocalProtocolError: Too little data for declared Content-Length

This issue was introduced with #8582 (because since then the shutdown of generators is properly handled).
/cc @whummer

Changes

  • Before raising a BrokenPipeError, set WsgiStartResponse.finalized = True to avoid sending the connection close response.

Testing

Unfortunately, I was having a hard time coming up with a test.
I verified the fix locally, however, I'm happy for any feedback for a unit test.

@alexrashed alexrashed added the semver: patch Non-breaking changes which can be included in patch releases label Sep 20, 2023
@alexrashed alexrashed added this to the 2.3 milestone Sep 20, 2023
@alexrashed alexrashed requested a review from dfangl September 20, 2023 14:03
@alexrashed alexrashed requested a review from thrau as a code owner September 20, 2023 14:03
@alexrashed alexrashed self-assigned this Sep 20, 2023
thrau
thrau approved these changes Sep 20, 2023
View reviewed changes
Copy link
Member
@thrau thrau left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that's a really nice catch! solution LGTM

@coveralls
Copy link

Coverage Status

coverage: 83.044% (+0.06%) from 82.986% when pulling 6393a0a on fix-h11-error-on-client-close into d0db54b on master.

@github-actions
Copy link

LocalStack Community integration with Pro

       2 files         2 suites   1h 11m 27s ⏱️
2 216 tests 1 719 ✔️ 497 💤 0 ❌
2 217 runs  1 719 ✔️ 498 💤 0 ❌

Results for commit 6393a0a.

@alexrashed alexrashed merged commit b438929 into master Sep 20, 2023
@alexrashed alexrashed deleted the fix-h11-error-on-client-close branch September 20, 2023 14:46
@joe4dev
Copy link
Member
joe4dev commented Sep 20, 2023

Great to see this annoying error go 🥳 Thank you @alexrashed 🙏🙏🙏
I got that all over the place while debugging Lambda (CI) logs and just ran into it today again during debugging with the LS debug extension (https://github.com/thrau/localstack-extension-pycharm-debug) 🙌

@joe4dev
Copy link
Member
joe4dev commented Sep 20, 2023

@alexrashed Regarding testing: How about using a (boto) client with a very short connection timeout? Obviously, LocalStack needs to be busy longer than that timeout (e.g., sync Lambda invoke with sleep but we should pick something more lightweight /unitesty)?

@alexrashed
Copy link
Member Author

Actually, I can trigger the bug in a test, but it's hard to verify that the error is not happening anymore (because the client obviously already closed the connection)...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@thrau thrau thrau approved these changes

@dfangl dfangl dfangl approved these changes

Assignees

@alexrashed alexrashed

Labels
semver: patch Non-breaking changes which can be included in patch releases
Projects
None yet
Milestone
2.3
Development

Successfully merging this pull request may close these issues.
5 participants
@alexrashed @coveralls @joe4dev @thrau @dfangl
0