Repository: localstack/localstack
Pull request: Use asyncio run_in_executor to prevent is_ssl_socket check from blocking
This PR aims to fix blocking of the whole event loop for the lookahead for the SSL duplex socket.
Currently, the method is_ssl_socket will block until the first 5 bytes can be read - if the client does not provide these bytes, the eventloop will block and refuse any connections for the time being.

This PR fixes this by executing the method in an executor, and waiting for the result in the eventloop, therefore keeping it responsive.

Thanks @thrau for the tip!
Should fix #5499 .

Problem statement:
bug: Opening TCP connections to localstack slows down concurrent requests
### Is there an existing issue for this?

- [X] I have searched the existing issues

### Current Behavior

It seems like whenever I open a connection to `localhost:4566` (4566 being exposed from the localstack container), for the next ~1 second any HTTP calls will have delayed responses. If I open 10 connections, the delay will be 10 seconds.

### Expected Behavior

Multiple connections can be opened and don't impact other requests until a certain connection limit.

### How are you starting LocalStack?

With a `docker run` command

### Steps To Reproduce

1. run localstack: `docker run --rm -it -p 4566:4566 --name ls localstack/localstack:0.14.0` - I managed to reproduce it with versions as old as 0.12.0
2. run something like this to see how long curls take inside the container: 

```bash
docker exec -it ls /bin/bash

# inside the container:
while true; do time curl localhost:4566; sleep 0.1; done
```

3. open connections with telnet:

```
telnet localhost 4566
```

4. observe extended response times in the curl loop. For me it's ~1s extra per open connection (I'm simulating opening more connections with a JVM application opening sockets as I request).

### Environment

```markdown
- OS: macOS / ubuntu, tried both x86 and arm64 macs, and an arm64 linux
- LocalStack: 0.12.0, 0.13.1, 0.14.0
```


### Anything else?

This surfaces itself as extremely slow responses whenever you have e.g. a JVM application that keeps a cached connection pool. Even 10 connections in a pool are enough to cause consistent delays every couple seconds (which I think is after the connections are closed due to the defaults on my client), under no additional traffic targeting localstack.

Hints from issue discussion:
I checked how this behaved in 0.11.1 (on amd64) and it's even worse - the server hangs indefinitely as long as the telnet session is open!
I enabled debug logging in the event loop. This is what I get when I open 10 TCP connections at once: (it logs every second)

<details>
<summary>diff</summary>

```diff
diff --git a/localstack/utils/server/http2_server.py b/localstack/utils/server/http2_server.py
index a20fbea2..adce9412 100644
--- a/localstack/utils/server/http2_server.py
+++ b/localstack/utils/server/http2_server.py
@@ -218,6 +218,7 @@ def run_server(port, bind_address, handler=None, asynchronous=True, ssl_creds=No
         setup_quart_logging()
         config.bind = ["%s:%s" % (bind_address, port)]
         loop = loop or ensure_event_loop()
+        loop.set_debug(True)
         run_kwargs = {}
         if shutdown_event:
             run_kwargs["shutdown_trigger"] = shutdown_event.wait
```

</details>

<details>
<summary>Details</summary>

```
2022-02-17T11:20:44.146:WARNING:asyncio: Executing <Task pending name='Task-76' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c76f10>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.008 seconds
2022-02-17T11:20:58.023:WARNING:asyncio: Executing <Task pending name='Task-79' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb78ce4c0>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.008 seconds
2022-02-17T11:20:59.039:WARNING:asyncio: Executing <Task pending name='Task-81' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c5dca0>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.008 seconds
2022-02-17T11:21:00.049:WARNING:asyncio: Executing <Task pending name='Task-82' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c5d3d0>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.009 seconds
2022-02-17T11:21:01.059:WARNING:asyncio: Executing <Task pending name='Task-83' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c5dd90>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.008 seconds
2022-02-17T11:21:02.067:WARNING:asyncio: Executing <Task pending name='Task-84' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c5db80>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.007 seconds
2022-02-17T11:21:03.076:WARNING:asyncio: Executing <Task pending name='Task-85' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c93f10>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.009 seconds
2022-02-17T11:21:04.087:WARNING:asyncio: Executing <Task pending name='Task-86' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c76910>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.009 seconds
2022-02-17T11:21:05.099:WARNING:asyncio: Executing <Task pending name='Task-87' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c76cd0>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.011 seconds
2022-02-17T11:21:06.107:WARNING:asyncio: Executing <Task pending name='Task-88' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c763a0>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.008 seconds
2022-02-17T11:21:07.117:WARNING:asyncio: Executing <Task pending name='Task-89' coro=<_accept_connection2() running at /opt/code/localstack/localstack/services/generic_proxy.py:921> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xffffb7c76b20>()] created at /usr/local/lib/python3.8/asyncio/base_events.py:422> created at /usr/local/lib/python3.8/asyncio/selector_events.py:196> took 1.008 seconds
```

</details>

@MarcelStranak I think this might be more related to the threadpool usage but I don't have enough experience with python stuff to tell for sure 😅 
Checked and it still happens on 0.14.2, can someone take a look? It seems like a fundamental flaw that prevents any kind of connection pooling on the client side.
@whummer - Any thoughts on this one? Some of our company's users are demotivated to use localstack due to this issue.
Hey Eric @etspaceman! I think we've pinned down the problem to the SSL socket multiplexing here, and we're looking into different ways to solve the problem ASAP.  https://github.com/localstack/localstack/blob/master/localstack/services/generic_proxy.py#L780

Commit message: use asyncio run_in_executor to make is_ssl_socket check threaded

Patch to review:
diff --git a/localstack/services/generic_proxy.py b/localstack/services/generic_proxy.py
index f3ebda2552fa1..9f8ee0be16e1e 100644
--- a/localstack/services/generic_proxy.py
+++ b/localstack/services/generic_proxy.py
@@ -1,5 +1,6 @@
 from __future__ import annotations
 
+import asyncio
 import functools
 import json
 import logging
@@ -935,7 +936,8 @@ def do_shutdown(self):
 
 
 async def _accept_connection2(self, protocol_factory, conn, extra, sslcontext, *args, **kwargs):
-    is_ssl_socket = DuplexSocket.is_ssl_socket(conn)
+    loop = asyncio.get_event_loop()
+    is_ssl_socket = await loop.run_in_executor(None, DuplexSocket.is_ssl_socket, conn)
     if is_ssl_socket is False:
         sslcontext = None
     result = await _accept_connection2_orig(


Code review comments:
diff_hunk: @@ -935,7 +936,8 @@ def do_shutdown(self):
 
 
 async def _accept_connection2(self, protocol_factory, conn, extra, sslcontext, *args, **kwargs):
-    is_ssl_socket = DuplexSocket.is_ssl_socket(conn)
+    loop = asyncio.get_event_loop()
+    is_ssl_socket = await loop.run_in_executor(None, DuplexSocket.is_ssl_socket, conn)
path: localstack/services/generic_proxy.py
text: @user1:
maybe we can re-use the `localstack.utils.asyncio.run_sync()` method here? it does a bit of magic that's maybe useful.

@author:
Done, tested locally, behaves the same! :+1: