[go: nahoru, domu]

Skip to content
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.

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

bug: LocalStack seems to break when downloading large files (~1.5GB, related to processing time?) #10988

Open
1 task done
daniel-frak opened this issue Jun 10, 2024 · 11 comments
Assignees
Labels
area: infrastructure Installation and startup of LocalStack and components aws:s3 Amazon Simple Storage Service status: in progress Currently being worked on type: bug Bug report

Comments

@daniel-frak
Copy link
daniel-frak commented Jun 10, 2024

Is there an existing issue for this?

  • I have searched the existing issues

Current Behavior

Trying to download a large file (~1.5GB) from S3, where it takes some time to process the response, leads to a Too little data for declared Content-Length exception.
I personally witnessed the error within 3 minutes of starting the download, but reports from other teammates suggest that this can happen instantly (the delay before the error occurs seems random).

Expected Behavior

Downloading a large file should work, regardless of size and time it takes to process.

How are you starting LocalStack?

With a docker-compose file

Steps To Reproduce

How are you starting localstack (e.g., bin/localstack command, arguments, or docker-compose.yml)

version: '3.3'
services:
  localstack:
    image: localstack/localstack:3.4.0
    restart: unless-stopped
    ports:
      - "4566:4566"
    environment:
      - DEBUG=1
    volumes:
      - ./localstack/localstack-script.sh:/etc/localstack/init/ready.d/script.sh # Init script
      - localstack:/var/lib/localstack"

networks:
  internal:

volumes:
  localstack:

Client commands (e.g., AWS SDK code snippet, or sequence of "awslocal" commands)

Upload a large file using Test::thisWorks:

@RequiredArgsConstructor
public class Test {
    private final S3Client s3Client;

    public List<Byte> thisWorks(String bucketName, String objectKey) throws IOException {
        ResponseInputStream<GetObjectResponse> response = s3Client.getObject(request ->
                request.bucket(bucketName).key(objectKey));

        return Bytes.asList(response.readAllBytes());
    }
}

Notice the download succeed.

Upload a large file using Test::thisFails:

@RequiredArgsConstructor
public class Test
{
    private final S3Client s3Client;

    public List<MyDomainObject> thisFails(String bucketName, String objectKey) throws IOException {
        ResponseInputStream<GetObjectResponse> response = s3Client.getObject(request ->
                request.bucket(bucketName).key(objectKey));

        try (var reader = new BufferedReader(new InputStreamReader(response, StandardCharsets.UTF_8))) {
            var csvToBean = buildCsvToBeanReader(reader);
            return csvToBean.parse();
        }
    }

    private CsvToBean<MyDomainObject> buildCsvToBeanReader(BufferedReader reader) {
        return new CsvToBeanBuilder<MyDomainObject>(reader)
                .withType(MyDomainObject.class)
                .withSeparator(',')
                .build();
    }
}

Notice the download fail.

Environment

- OS: Ubuntu 24.04
- LocalStack:
  LocalStack version: 3.4.0
  LocalStack Docker image sha: (could not find in logs)
  LocalStack build date: 2024-04-25
  LocalStack build git hash: 6f971ac81

Anything else?

I've tried to find the fault in my code for a few days now but I can't find anything obvious. The logs are just cryptic enough for me to suggest that this might be a bug with LocalStack itself.

I included OpenCSV code in the example, as that is the most obvious way to make it fail for us.
Some additional information:

  1. Downloading the file all-at-once using readAllBytes seems to work.
  2. I tried increasing the AWS HttpClient timeouts. This didn't have any impact on the issue occurring.
  3. I tried reproducing the error using a small file and Thread.sleep() (to simulate processing while the Response is open) and the error didn't occur.
  4. As mentioned, the error can apparently either show up instantaneously, or after a few minutes.

The log from my application is (shortened):

java.lang.RuntimeException: Error parsing CSV line: 6430053, values: [...]
	at com.opencsv.bean.concurrent.LineExecutor.checkExceptions(LineExecutor.java:64) ~[opencsv-5.9.jar:na]
	at com.opencsv.bean.concurrent.IntolerantThreadPoolExecutor.areMoreResultsAvailable(IntolerantThreadPoolExecutor.java:303) ~[opencsv-5.9.jar:na]
	at com.opencsv.bean.concurrent.IntolerantThreadPoolExecutor.tryAdvance(IntolerantThreadPoolExecutor.java:313) ~[opencsv-5.9.jar:na]
	at com.opencsv.bean.concurrent.LineExecutor.tryAdvance(LineExecutor.java:24) ~[opencsv-5.9.jar:na]
	at java.base/java.util.Spliterator.forEachRemaining(Spliterator.java:332) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[na:na]
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:921) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[na:na]
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:682) ~[na:na]
	at com.opencsv.bean.CsvToBean.parse(CsvToBean.java:126) ~[opencsv-5.9.jar:na]
	at [...]
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
	at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:169) ~[spring-messaging-6.1.8.jar:6.1.8]
	at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:119) ~[spring-messaging-6.1.8.jar:6.1.8]
	at io.awspring.cloud.sqs.listener.adapter.AbstractMethodInvokingListenerAdapter.invokeHandler(AbstractMethodInvokingListenerAdapter.java:56) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.adapter.MessagingMessageListenerAdapter.onMessage(MessagingMessageListenerAdapter.java:41) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.AsyncComponentAdapters$BlockingMessageListenerAdapter.lambda$onMessage$0(AsyncComponentAdapters.java:208) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.AsyncComponentAdapters$AbstractThreadingComponentAdapter.runInSameThread(AsyncComponentAdapters.java:120) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.AsyncComponentAdapters$AbstractThreadingComponentAdapter.execute(AsyncComponentAdapters.java:111) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.AsyncComponentAdapters$BlockingMessageListenerAdapter.onMessage(AsyncComponentAdapters.java:208) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.pipeline.MessageListenerExecutionStage.process(MessageListenerExecutionStage.java:49) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.pipeline.MessageProcessingPipelineBuilder$ComposingMessagePipelineStage.lambda$process$0(MessageProcessingPipelineBuilder.java:80) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at java.base/java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[na:na]
	at java.base/java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2341) ~[na:na]
	at io.awspring.cloud.sqs.listener.pipeline.MessageProcessingPipelineBuilder$ComposingMessagePipelineStage.process(MessageProcessingPipelineBuilder.java:80) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.pipeline.MessageProcessingPipelineBuilder$FutureComposingMessagePipelineStage.process(MessageProcessingPipelineBuilder.java:104) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.pipeline.MessageProcessingPipelineBuilder$FutureComposingMessagePipelineStage.process(MessageProcessingPipelineBuilder.java:104) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.pipeline.MessageProcessingPipelineBuilder$FutureComposingMessagePipelineStage.process(MessageProcessingPipelineBuilder.java:104) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.pipeline.MessageProcessingPipelineBuilder$FutureComposingMessagePipelineStage.process(MessageProcessingPipelineBuilder.java:104) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at io.awspring.cloud.sqs.listener.sink.AbstractMessageProcessingPipelineSink.lambda$execute$0(AbstractMessageProcessingPipelineSink.java:99) ~[spring-cloud-aws-sqs-3.1.1.jar:3.1.1]
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run$$$capture(CompletableFuture.java:1768) ~[na:na]
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]
Caused by: org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 1,348,550,980; received: 1,107,689,472)
	at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178) ~[httpcore-4.4.16.jar:4.4.16]
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135) ~[httpclient-4.5.13.jar:4.5.13]
	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:119) ~[na:na]
	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:119) ~[na:na]
	at software.amazon.awssdk.core.io.SdkFilterInputStream.read(SdkFilterInputStream.java:66) ~[sdk-core-2.21.46.jar:na]
	at software.amazon.awssdk.core.internal.metrics.BytesReadTrackingInputStream.read(BytesReadTrackingInputStream.java:49) ~[sdk-core-2.21.46.jar:na]
	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:119) ~[na:na]
	at software.amazon.awssdk.core.io.SdkFilterInputStream.read(SdkFilterInputStream.java:66) ~[sdk-core-2.21.46.jar:na]
	at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:350) ~[na:na]
	at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:393) ~[na:na]
	at java.base/sun.nio.cs.StreamDecoder.lockedRead(StreamDecoder.java:217) ~[na:na]
	at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:171) ~[na:na]
	at java.base/java.io.InputStreamReader.read(InputStreamReader.java:188) ~[na:na]
	at java.base/java.io.BufferedReader.fill(BufferedReader.java:160) ~[na:na]
	at java.base/java.io.BufferedReader.implReadLine(BufferedReader.java:370) ~[na:na]
	at java.base/java.io.BufferedReader.readLine(BufferedReader.java:347) ~[na:na]
	at java.base/java.io.BufferedReader.readLine(BufferedReader.java:436) ~[na:na]
	at com.opencsv.stream.reader.LineReader.readLine(LineReader.java:41) ~[opencsv-5.9.jar:na]
	at com.opencsv.CSVReader.getNextLine(CSVReader.java:367) ~[opencsv-5.9.jar:na]
	at com.opencsv.CSVReader.primeNextRecord(CSVReader.java:235) ~[opencsv-5.9.jar:na]
	at com.opencsv.CSVReader.flexibleRead(CSVReader.java:610) ~[opencsv-5.9.jar:na]
	at com.opencsv.CSVReader.readNext(CSVReader.java:204) ~[opencsv-5.9.jar:na]
	at com.opencsv.bean.concurrent.SingleLineReader.readNextLine(SingleLineReader.java:49) ~[opencsv-5.9.jar:na]
	at com.opencsv.bean.concurrent.CompleteFileReader.run(CompleteFileReader.java:91) ~[opencsv-5.9.jar:na]
	... 1 common frames omitted

The log from LocalStack is:

2024-06-10T06:41:20.323 ERROR --- [-functhread6] hypercorn.error            : Error in ASGI Framework
2024-06-10T06:41:20.337746830Z Traceback (most recent call last):
2024-06-10T06:41:20.337765833Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/tcp_server.py", line 95, in _read_data
2024-06-10T06:41:20.337782785Z     data = await asyncio.wait_for(self.reader.read(MAX_RECV), self.config.read_timeout)
2024-06-10T06:41:20.337798631Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.337815464Z   File "/usr/local/lib/python3.11/asyncio/tasks.py", line 452, in wait_for
2024-06-10T06:41:20.337831584Z     return await fut
2024-06-10T06:41:20.337847489Z            ^^^^^^^^^
2024-06-10T06:41:20.337863233Z   File "/usr/local/lib/python3.11/asyncio/streams.py", line 711, in read
2024-06-10T06:41:20.337878846Z     await self._wait_for_data('read')
2024-06-10T06:41:20.337894271Z   File "/usr/local/lib/python3.11/asyncio/streams.py", line 543, in _wait_for_data
2024-06-10T06:41:20.337910381Z     await self._waiter
2024-06-10T06:41:20.337925697Z   File "/usr/local/lib/python3.11/asyncio/selector_events.py", line 1061, in write
2024-06-10T06:41:20.337941297Z     n = self._sock.send(data)
2024-06-10T06:41:20.337957015Z         ^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.337972872Z TimeoutError: timed out
2024-06-10T06:41:20.337988824Z 
2024-06-10T06:41:20.338004097Z During handling of the above exception, another exception occurred:
2024-06-10T06:41:20.338019924Z 
2024-06-10T06:41:20.338035452Z Traceback (most recent call last):
2024-06-10T06:41:20.338050828Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/task_group.py", line 27, in _handle
2024-06-10T06:41:20.338067274Z     await app(scope, receive, send, sync_spawn, call_soon)
2024-06-10T06:41:20.338083156Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/app_wrappers.py", line 34, in __call__
2024-06-10T06:41:20.338099637Z     await self.app(scope, receive, send)
2024-06-10T06:41:20.338115389Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/gateway/asgi.py", line 75, in __call__
2024-06-10T06:41:20.338134029Z     return await self.adapter(scope, receive, send)
2024-06-10T06:41:20.338150053Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.338165938Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/asgi.py", line 540, in __call__
2024-06-10T06:41:20.338182178Z     return await self.handle_http(scope, receive, send)
2024-06-10T06:41:20.338197687Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.338213495Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/asgi.py", line 611, in handle_http
2024-06-10T06:41:20.338229503Z     await response.close()
2024-06-10T06:41:20.338244961Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/asgi.py", line 322, in close
2024-06-10T06:41:20.338263097Z     await self.send({"type": "http.response.body", "body": b"", "more_body": False})
2024-06-10T06:41:20.338280141Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/protocol/http_stream.py", line 189, in app_send
2024-06-10T06:41:20.338296140Z     await self.send(EndBody(stream_id=self.stream_id))
2024-06-10T06:41:20.338311566Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/protocol/h11.py", line 139, in stream_send
2024-06-10T06:41:20.338327500Z     await self._send_h11_event(h11.EndOfMessage())
2024-06-10T06:41:20.338342987Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/protocol/h11.py", line 243, in _send_h11_event
2024-06-10T06:41:20.338359314Z     data = self.connection.send(event)
2024-06-10T06:41:20.338375307Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.338391162Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_connection.py", line 512, in send
2024-06-10T06:41:20.338406735Z     data_list = self.send_with_data_passthrough(event)
2024-06-10T06:41:20.338422149Z                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.338437790Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_connection.py", line 545, in send_with_data_passthrough
2024-06-10T06:41:20.338453262Z     writer(event, data_list.append)
2024-06-10T06:41:20.338468551Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_writers.py", line 67, in __call__
2024-06-10T06:41:20.338484611Z     self.send_eom(event.headers, write)
2024-06-10T06:41:20.338500225Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_writers.py", line 96, in send_eom
2024-06-10T06:41:20.338516486Z     raise LocalProtocolError("Too little data for declared Content-Length")
2024-06-10T06:41:20.338532629Z h11._util.LocalProtocolError: Too little data for declared Content-Length
2024-06-10T06:41:20.339861427Z 2024-06-10T06:41:20.323 ERROR --- [-functhread6] hypercorn.error            : Error in ASGI Framework
2024-06-10T06:41:20.339891878Z Traceback (most recent call last):
2024-06-10T06:41:20.339909165Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/tcp_server.py", line 95, in _read_data
2024-06-10T06:41:20.339929814Z     data = await asyncio.wait_for(self.reader.read(MAX_RECV), self.config.read_timeout)
2024-06-10T06:41:20.339946045Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.339961740Z   File "/usr/local/lib/python3.11/asyncio/tasks.py", line 452, in wait_for
2024-06-10T06:41:20.339977820Z     return await fut
2024-06-10T06:41:20.339993261Z            ^^^^^^^^^
2024-06-10T06:41:20.340008428Z   File "/usr/local/lib/python3.11/asyncio/streams.py", line 711, in read
2024-06-10T06:41:20.340024048Z     await self._wait_for_data('read')
2024-06-10T06:41:20.340039473Z   File "/usr/local/lib/python3.11/asyncio/streams.py", line 543, in _wait_for_data
2024-06-10T06:41:20.340055464Z     await self._waiter
2024-06-10T06:41:20.340071326Z   File "/usr/local/lib/python3.11/asyncio/selector_events.py", line 1061, in write
2024-06-10T06:41:20.340087085Z     n = self._sock.send(data)
2024-06-10T06:41:20.340102471Z         ^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.340117850Z TimeoutError: timed out
2024-06-10T06:41:20.340132991Z 
2024-06-10T06:41:20.340148083Z During handling of the above exception, another exception occurred:
2024-06-10T06:41:20.340163668Z 
2024-06-10T06:41:20.340179002Z Traceback (most recent call last):
2024-06-10T06:41:20.340194423Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/task_group.py", line 27, in _handle
2024-06-10T06:41:20.340210148Z     await app(scope, receive, send, sync_spawn, call_soon)
2024-06-10T06:41:20.340225872Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/app_wrappers.py", line 34, in __call__
2024-06-10T06:41:20.340241588Z     await self.app(scope, receive, send)
2024-06-10T06:41:20.340256994Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/gateway/asgi.py", line 75, in __call__
2024-06-10T06:41:20.340272897Z     return await self.adapter(scope, receive, send)
2024-06-10T06:41:20.340288601Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.340304245Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/asgi.py", line 540, in __call__
2024-06-10T06:41:20.340319913Z     return await self.handle_http(scope, receive, send)
2024-06-10T06:41:20.340335239Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.340350586Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/asgi.py", line 611, in handle_http
2024-06-10T06:41:20.340366408Z     await response.close()
2024-06-10T06:41:20.340381930Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/rolo/asgi.py", line 322, in close
2024-06-10T06:41:20.340398964Z     await self.send({"type": "http.response.body", "body": b"", "more_body": False})
2024-06-10T06:41:20.340415610Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/protocol/http_stream.py", line 189, in app_send
2024-06-10T06:41:20.340431540Z     await self.send(EndBody(stream_id=self.stream_id))
2024-06-10T06:41:20.340447112Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/protocol/h11.py", line 139, in stream_send
2024-06-10T06:41:20.340463163Z     await self._send_h11_event(h11.EndOfMessage())
2024-06-10T06:41:20.340478776Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/protocol/h11.py", line 243, in _send_h11_event
2024-06-10T06:41:20.340494329Z     data = self.connection.send(event)
2024-06-10T06:41:20.340509719Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.340524989Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_connection.py", line 512, in send
2024-06-10T06:41:20.340540818Z     data_list = self.send_with_data_passthrough(event)
2024-06-10T06:41:20.340556874Z                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.340572689Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_connection.py", line 545, in send_with_data_passthrough
2024-06-10T06:41:20.340588309Z     writer(event, data_list.append)
2024-06-10T06:41:20.340603554Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_writers.py", line 67, in __call__
2024-06-10T06:41:20.340619180Z     self.send_eom(event.headers, write)
2024-06-10T06:41:20.340634599Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/h11/_writers.py", line 96, in send_eom
2024-06-10T06:41:20.340650378Z     raise LocalProtocolError("Too little data for declared Content-Length")
2024-06-10T06:41:20.340666127Z h11._util.LocalProtocolError: Too little data for declared Content-Length
2024-06-10T06:41:20.341936148Z 2024-06-10T06:41:20.338 ERROR --- [-functhread6] asyncio                    : Unhandled exception in client_connected_cb
2024-06-10T06:41:20.341970439Z transport: <asyncio.sslproto._SSLProtocolTransport object at 0x7135dafa8470>
2024-06-10T06:41:20.341988699Z Traceback (most recent call last):
2024-06-10T06:41:20.342004551Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/run.py", line 109, in _server_callback
2024-06-10T06:41:20.342020629Z     await TCPServer(app, loop, config, context, reader, writer)
2024-06-10T06:41:20.342036325Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/tcp_server.py", line 74, in run
2024-06-10T06:41:20.342052392Z     await self._close()
2024-06-10T06:41:20.342068057Z   File "/opt/code/localstack/localstack/utils/server/http2_server.py", line 79, in _close
2024-06-10T06:41:20.342084328Z     return await _close_orig(self)
2024-06-10T06:41:20.342100231Z            ^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.342115753Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/hypercorn/asyncio/tcp_server.py", line 117, in _close
2024-06-10T06:41:20.342131420Z     await self.writer.wait_closed()
2024-06-10T06:41:20.342146819Z   File "/usr/local/lib/python3.11/asyncio/streams.py", line 364, in wait_closed
2024-06-10T06:41:20.342162739Z     await self._protocol._get_close_waiter(self)
2024-06-10T06:41:20.342178418Z   File "/usr/local/lib/python3.11/asyncio/selector_events.py", line 1061, in write
2024-06-10T06:41:20.342194076Z     n = self._sock.send(data)
2024-06-10T06:41:20.342209541Z         ^^^^^^^^^^^^^^^^^^^^^
2024-06-10T06:41:20.342225098Z TimeoutError: timed out
@daniel-frak daniel-frak added status: triage needed Requires evaluation by maintainers type: bug Bug report labels Jun 10, 2024
@bentsku
Copy link
Contributor
bentsku commented Jun 10, 2024

Hello @daniel-frak and thanks for your report!

Could you try starting LocalStack with the following configuration variable: GATEWAY_SERVER=twisted and see if that would solve your issue?

As a side note, this configuration variable value will be the default in our next minor release coming up this week, so when using our next version 3.5, you would not need to set it anymore.

I hope this solves the issue, if not please feel free to ping me on this issue and we can investigate further.

Thank you!

@bentsku bentsku self-assigned this Jun 10, 2024
@bentsku bentsku added area: infrastructure Installation and startup of LocalStack and components status: response required Waiting for a response from the reporter aws:s3 Amazon Simple Storage Service and removed status: triage needed Requires evaluation by maintainers labels Jun 10, 2024
@daniel-frak
Copy link
Author

Thanks for the fast response!

I changed the docker-compose like this:

  localstack:
    image: localstack/localstack:3.4.0
    restart: unless-stopped
    ports:
      - "4566:4566"
    environment:
      - DEBUG=1
      - GATEWAY_SERVER=twisted
    volumes:
      - ./localstack/localstack-script.sh:/etc/localstack/init/ready.d/script.sh # Init script
      - localstack:/var/lib/localstack"

Then I deleted the container and its volume, and created it again. I ran the import and, ~1.5min later, I unfortunately got the same error :(

Is there some way to confirm that the GATEWAY_SERVER variable is being used?

Just in case, here's the setup log for LocalStack (there are some Docker SDK errors there):

LocalStack supervisor: starting
2024-06-10T10:22:05.858353704Z LocalStack supervisor: localstack process (PID 15) starting
2024-06-10T10:22:06.440615918Z 
2024-06-10T10:22:06.440653751Z LocalStack version: 3.4.0
2024-06-10T10:22:06.443076541Z LocalStack build date: 2024-04-25
2024-06-10T10:22:06.443117103Z LocalStack build git hash: 6f971ac81
2024-06-10T10:22:06.443139052Z 
2024-06-10T10:22:06.523570847Z 2024-06-10T10:22:06.523 DEBUG --- [  MainThread] stevedore._cache           : reading /root/.cache/python-entrypoints/d35e4e67651afb879a90faab8281bd850e9d0be05b8a632c88cce40c18d273c4
2024-06-10T10:22:06.532139187Z 2024-06-10T10:22:06.531 DEBUG --- [  MainThread] stevedore._cache           : writing to /root/.cache/python-entrypoints/d35e4e67651afb879a90faab8281bd850e9d0be05b8a632c88cce40c18d273c4
2024-06-10T10:22:06.533430154Z 2024-06-10T10:22:06.533 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='_patch_botocore_json_parser', value='localstack.aws.client:_patch_botocore_json_parser', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.533971537Z 2024-06-10T10:22:06.533 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='_publish_config_as_analytics_event', value='localstack.runtime.analytics:_publish_config_as_analytics_event', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.534375934Z 2024-06-10T10:22:06.534 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='_publish_container_info', value='localstack.runtime.analytics:_publish_container_info', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.534403387Z 2024-06-10T10:22:06.534 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='_run_init_scripts_on_start', value='localstack.runtime.init:_run_init_scripts_on_start', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.536032803Z 2024-06-10T10:22:06.535 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='deprecation_warnings', value='localstack.plugins:deprecation_warnings', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.536336623Z 2024-06-10T10:22:06.536 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='register_custom_endpoints', value='localstack.services.lambda_.plugins:register_custom_endpoints', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.550076568Z 2024-06-10T10:22:06.549 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='register_partition_adjusting_proxy_listener', value='localstack.plugins:register_partition_adjusting_proxy_listener', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.550119049Z 2024-06-10T10:22:06.550 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='setup_dns_configuration_on_host', value='localstack.dns.plugins:setup_dns_configuration_on_host', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.550930195Z 2024-06-10T10:22:06.550 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='start_dns_server', value='localstack.dns.plugins:start_dns_server', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.550955482Z 2024-06-10T10:22:06.550 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='validate_configuration', value='localstack.services.lambda_.plugins:validate_configuration', group='localstack.hooks.on_infra_start')
2024-06-10T10:22:06.551176825Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start._patch_botocore_json_parser = <function _patch_botocore_json_parser at 0x7f4c8d449300>)
2024-06-10T10:22:06.551264646Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:_patch_botocore_json_parser
2024-06-10T10:22:06.551321784Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start._publish_config_as_analytics_event = <function _publish_config_as_analytics_event at 0x7f4c8d449760>)
2024-06-10T10:22:06.551378502Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:_publish_config_as_analytics_event
2024-06-10T10:22:06.551446727Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start._publish_container_info = <function _publish_container_info at 0x7f4c8d449a80>)
2024-06-10T10:22:06.551492315Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:_publish_container_info
2024-06-10T10:22:06.551567317Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start._run_init_scripts_on_start = <function _run_init_scripts_on_start at 0x7f4c8d44aa20>)
2024-06-10T10:22:06.551629769Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:_run_init_scripts_on_start
2024-06-10T10:22:06.551691353Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start.deprecation_warnings = <function deprecation_warnings at 0x7f4c8d44b1a0>)
2024-06-10T10:22:06.551745814Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:deprecation_warnings
2024-06-10T10:22:06.551801121Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start.register_custom_endpoints = <function register_custom_endpoints at 0x7f4c8dc6d080>)
2024-06-10T10:22:06.551872224Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:register_custom_endpoints
2024-06-10T10:22:06.551920012Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start.register_partition_adjusting_proxy_listener = <function register_partition_adjusting_proxy_listener at 0x7f4c8d44b060>)
2024-06-10T10:22:06.552097410Z 2024-06-10T10:22:06.551 DEBUG --- [  MainThread] plux.runtime.manager       : plugin localstack.hooks.on_infra_start:register_partition_adjusting_proxy_listener is disabled, reason: Load condition for plugin was false
2024-06-10T10:22:06.552156514Z 2024-06-10T10:22:06.552 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start.setup_dns_configuration_on_host = <function setup_dns_configuration_on_host at 0x7f4c8d3296c0>)
2024-06-10T10:22:06.552216907Z 2024-06-10T10:22:06.552 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:setup_dns_configuration_on_host
2024-06-10T10:22:06.552292699Z 2024-06-10T10:22:06.552 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start.start_dns_server = <function start_dns_server at 0x7f4c8d329580>)
2024-06-10T10:22:06.552346573Z 2024-06-10T10:22:06.552 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:start_dns_server
2024-06-10T10:22:06.552406751Z 2024-06-10T10:22:06.552 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_start.validate_configuration = <function validate_configuration at 0x7f4c8d4c80e0>)
2024-06-10T10:22:06.552458360Z 2024-06-10T10:22:06.552 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_start:validate_configuration
2024-06-10T10:22:06.574051513Z 2024-06-10T10:22:06.573 DEBUG --- [  MainThread] localstack.dns.server      : Determined fallback dns: 127.0.0.11
2024-06-10T10:22:06.574131553Z 2024-06-10T10:22:06.574 DEBUG --- [  MainThread] localstack.dns.server      : Starting DNS servers (tcp/udp port 53 on 0.0.0.0)...
2024-06-10T10:22:06.574221071Z 2024-06-10T10:22:06.574 DEBUG --- [  MainThread] localstack.dns.server      : Adding host .*localhost.localstack.cloud pointing to LocalStack
2024-06-10T10:22:06.574266141Z 2024-06-10T10:22:06.574 DEBUG --- [  MainThread] localstack.dns.server      : Adding host .*localhost.localstack.cloud with record DynamicRecord(record_type=<RecordType.A: 1>, record_id=None)
2024-06-10T10:22:06.574334318Z 2024-06-10T10:22:06.574 DEBUG --- [  MainThread] localstack.dns.server      : Adding host .*localhost.localstack.cloud with record DynamicRecord(record_type=<RecordType.AAAA: 2>, record_id=None)
2024-06-10T10:22:06.575305457Z 2024-06-10T10:22:06.575 DEBUG --- [-functhread1] localstack.dns.server      : DNS Server started
2024-06-10T10:22:07.609577214Z 2024-06-10T10:22:07.609 DEBUG --- [  MainThread] localstack.dns.server      : DNS server startup finished.
2024-06-10T10:22:07.637718484Z 2024-06-10T10:22:07.614 DEBUG --- [-functhread2] l.u.c.docker_sdk_client    : Creating Docker SDK client failed: Error while fetching server API version: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.637871069Z Traceback (most recent call last):
2024-06-10T10:22:07.637916860Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 793, in urlopen
2024-06-10T10:22:07.638014483Z     response = self._make_request(
2024-06-10T10:22:07.638065763Z                ^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.638103530Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 496, in _make_request
2024-06-10T10:22:07.638149075Z     conn.request(
2024-06-10T10:22:07.638188648Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connection.py", line 400, in request
2024-06-10T10:22:07.638269544Z     self.endheaders()
2024-06-10T10:22:07.638323757Z   File "/usr/local/lib/python3.11/http/client.py", line 1298, in endheaders
2024-06-10T10:22:07.638369050Z     self._send_output(message_body, encode_chunked=encode_chunked)
2024-06-10T10:22:07.638450495Z   File "/usr/local/lib/python3.11/http/client.py", line 1058, in _send_output
2024-06-10T10:22:07.638487911Z     self.send(msg)
2024-06-10T10:22:07.638517548Z   File "/usr/local/lib/python3.11/http/client.py", line 996, in send
2024-06-10T10:22:07.638547936Z     self.connect()
2024-06-10T10:22:07.638581183Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/transport/unixconn.py", line 27, in connect
2024-06-10T10:22:07.638711966Z     sock.connect(self.unix_socket)
2024-06-10T10:22:07.638776238Z FileNotFoundError: [Errno 2] No such file or directory
2024-06-10T10:22:07.638829817Z 
2024-06-10T10:22:07.638883351Z During handling of the above exception, another exception occurred:
2024-06-10T10:22:07.638998551Z 
2024-06-10T10:22:07.639052214Z Traceback (most recent call last):
2024-06-10T10:22:07.639101092Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/adapters.py", line 486, in send
2024-06-10T10:22:07.639146309Z     resp = conn.urlopen(
2024-06-10T10:22:07.639616577Z            ^^^^^^^^^^^^^
2024-06-10T10:22:07.639713432Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 847, in urlopen
2024-06-10T10:22:07.639774725Z     retries = retries.increment(
2024-06-10T10:22:07.639831525Z               ^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.639931142Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/util/retry.py", line 470, in increment
2024-06-10T10:22:07.639982675Z     raise reraise(type(error), error, _stacktrace)
2024-06-10T10:22:07.640030992Z           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.640086030Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/util/util.py", line 38, in reraise
2024-06-10T10:22:07.640181174Z     raise value.with_traceback(tb)
2024-06-10T10:22:07.640247644Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 793, in urlopen
2024-06-10T10:22:07.640307996Z     response = self._make_request(
2024-06-10T10:22:07.640360227Z                ^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.640488957Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 496, in _make_request
2024-06-10T10:22:07.640543137Z     conn.request(
2024-06-10T10:22:07.640579101Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connection.py", line 400, in request
2024-06-10T10:22:07.640641601Z     self.endheaders()
2024-06-10T10:22:07.640684818Z   File "/usr/local/lib/python3.11/http/client.py", line 1298, in endheaders
2024-06-10T10:22:07.640737232Z     self._send_output(message_body, encode_chunked=encode_chunked)
2024-06-10T10:22:07.640791723Z   File "/usr/local/lib/python3.11/http/client.py", line 1058, in _send_output
2024-06-10T10:22:07.640933885Z     self.send(msg)
2024-06-10T10:22:07.641003491Z   File "/usr/local/lib/python3.11/http/client.py", line 996, in send
2024-06-10T10:22:07.641060470Z     self.connect()
2024-06-10T10:22:07.641111888Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/transport/unixconn.py", line 27, in connect
2024-06-10T10:22:07.641202613Z     sock.connect(self.unix_socket)
2024-06-10T10:22:07.641253489Z urllib3.exceptions.ProtocolError: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.641295348Z 
2024-06-10T10:22:07.641338814Z During handling of the above exception, another exception occurred:
2024-06-10T10:22:07.641453060Z 
2024-06-10T10:22:07.641514581Z Traceback (most recent call last):
2024-06-10T10:22:07.641570592Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 214, in _retrieve_server_version
2024-06-10T10:22:07.641615201Z     return self.version(api_version=False)["ApiVersion"]
2024-06-10T10:22:07.641699036Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.641749172Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/daemon.py", line 181, in version
2024-06-10T10:22:07.641789397Z     return self._result(self._get(url), json=True)
2024-06-10T10:22:07.641827474Z                         ^^^^^^^^^^^^^^
2024-06-10T10:22:07.641901201Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/utils/decorators.py", line 46, in inner
2024-06-10T10:22:07.641957613Z     return f(self, *args, **kwargs)
2024-06-10T10:22:07.642009143Z            ^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.642058713Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 237, in _get
2024-06-10T10:22:07.642148384Z     return self.get(url, **self._set_request_timeout(kwargs))
2024-06-10T10:22:07.642205343Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.642260310Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/sessions.py", line 602, in get
2024-06-10T10:22:07.642348446Z     return self.request("GET", url, **kwargs)
2024-06-10T10:22:07.642401540Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.642443530Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/sessions.py", line 589, in request
2024-06-10T10:22:07.642482755Z     resp = self.send(prep, **send_kwargs)
2024-06-10T10:22:07.642562186Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.642615275Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/sessions.py", line 703, in send
2024-06-10T10:22:07.642668485Z     r = adapter.send(request, **kwargs)
2024-06-10T10:22:07.642717539Z         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.642814062Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/adapters.py", line 501, in send
2024-06-10T10:22:07.642870683Z     raise ConnectionError(err, request=request)
2024-06-10T10:22:07.642924954Z requests.exceptions.ConnectionError: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.642976753Z 
2024-06-10T10:22:07.643091846Z During handling of the above exception, another exception occurred:
2024-06-10T10:22:07.643154629Z 
2024-06-10T10:22:07.643204498Z Traceback (most recent call last):
2024-06-10T10:22:07.643251046Z   File "/opt/code/localstack/localstack/utils/container_utils/docker_sdk_client.py", line 76, in _create_client
2024-06-10T10:22:07.643342793Z     return docker.from_env(timeout=DOCKER_SDK_DEFAULT_TIMEOUT_SECONDS)
2024-06-10T10:22:07.643399341Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.643452318Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/client.py", line 96, in from_env
2024-06-10T10:22:07.643497843Z     return cls(
2024-06-10T10:22:07.643647208Z            ^^^^
2024-06-10T10:22:07.643714334Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/client.py", line 45, in __init__
2024-06-10T10:22:07.643762775Z     self.api = APIClient(*args, **kwargs)
2024-06-10T10:22:07.643814176Z                ^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.643905084Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 197, in __init__
2024-06-10T10:22:07.643963257Z     self._version = self._retrieve_server_version()
2024-06-10T10:22:07.644015672Z                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.644063047Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 221, in _retrieve_server_version
2024-06-10T10:22:07.644166740Z     raise DockerException(
2024-06-10T10:22:07.644222598Z docker.errors.DockerException: Error while fetching server API version: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.644350362Z 2024-06-10T10:22:07.618 DEBUG --- [  MainThread] localstack.runtime.init    : Init scripts discovered: {BOOT: [], START: [], READY: [Script(path='/etc/localstack/init/ready.d/script.sh', stage=READY, state=UNKNOWN)], SHUTDOWN: []}
2024-06-10T10:22:07.644469677Z 2024-06-10T10:22:07.637 DEBUG --- [  MainThread] localstack.plugins         : Checking for the usage of deprecated community features and configs...
2024-06-10T10:22:07.650905075Z 2024-06-10T10:22:07.650 DEBUG --- [  MainThread] localstack.dns.server      : Overwriting container DNS server to point to localhost
2024-06-10T10:22:07.659236822Z 2024-06-10T10:22:07.651 DEBUG --- [-functhread2] l.u.c.docker_sdk_client    : Creating Docker SDK client failed: Error while fetching server API version: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.659349258Z Traceback (most recent call last):
2024-06-10T10:22:07.659460248Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 793, in urlopen
2024-06-10T10:22:07.659521122Z     response = self._make_request(
2024-06-10T10:22:07.659572022Z                ^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.659682751Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 496, in _make_request
2024-06-10T10:22:07.659783131Z     conn.request(
2024-06-10T10:22:07.659842132Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connection.py", line 400, in request
2024-06-10T10:22:07.659897879Z     self.endheaders()
2024-06-10T10:22:07.659947385Z   File "/usr/local/lib/python3.11/http/client.py", line 1298, in endheaders
2024-06-10T10:22:07.660035115Z     self._send_output(message_body, encode_chunked=encode_chunked)
2024-06-10T10:22:07.660087396Z   File "/usr/local/lib/python3.11/http/client.py", line 1058, in _send_output
2024-06-10T10:22:07.660135819Z     self.send(msg)
2024-06-10T10:22:07.660186455Z   File "/usr/local/lib/python3.11/http/client.py", line 996, in send
2024-06-10T10:22:07.660311507Z     self.connect()
2024-06-10T10:22:07.660371355Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/transport/unixconn.py", line 27, in connect
2024-06-10T10:22:07.660423706Z     sock.connect(self.unix_socket)
2024-06-10T10:22:07.660508961Z FileNotFoundError: [Errno 2] No such file or directory
2024-06-10T10:22:07.660560136Z 
2024-06-10T10:22:07.660605700Z During handling of the above exception, another exception occurred:
2024-06-10T10:22:07.660650518Z 
2024-06-10T10:22:07.660698022Z Traceback (most recent call last):
2024-06-10T10:22:07.660744796Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/adapters.py", line 486, in send
2024-06-10T10:22:07.660832729Z     resp = conn.urlopen(
2024-06-10T10:22:07.660883111Z            ^^^^^^^^^^^^^
2024-06-10T10:22:07.660929841Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 847, in urlopen
2024-06-10T10:22:07.661012951Z     retries = retries.increment(
2024-06-10T10:22:07.661065475Z               ^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.661116419Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/util/retry.py", line 470, in increment
2024-06-10T10:22:07.661165833Z     raise reraise(type(error), error, _stacktrace)
2024-06-10T10:22:07.661291424Z           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.661348008Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/util/util.py", line 38, in reraise
2024-06-10T10:22:07.661398351Z     raise value.with_traceback(tb)
2024-06-10T10:22:07.661449797Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 793, in urlopen
2024-06-10T10:22:07.661542260Z     response = self._make_request(
2024-06-10T10:22:07.661589824Z                ^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.661635422Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 496, in _make_request
2024-06-10T10:22:07.661716600Z     conn.request(
2024-06-10T10:22:07.661766289Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/urllib3/connection.py", line 400, in request
2024-06-10T10:22:07.661817544Z     self.endheaders()
2024-06-10T10:22:07.661862347Z   File "/usr/local/lib/python3.11/http/client.py", line 1298, in endheaders
2024-06-10T10:22:07.661908228Z     self._send_output(message_body, encode_chunked=encode_chunked)
2024-06-10T10:22:07.662024964Z   File "/usr/local/lib/python3.11/http/client.py", line 1058, in _send_output
2024-06-10T10:22:07.662079934Z     self.send(msg)
2024-06-10T10:22:07.662127345Z   File "/usr/local/lib/python3.11/http/client.py", line 996, in send
2024-06-10T10:22:07.662240075Z     self.connect()
2024-06-10T10:22:07.662295081Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/transport/unixconn.py", line 27, in connect
2024-06-10T10:22:07.662344986Z     sock.connect(self.unix_socket)
2024-06-10T10:22:07.662389277Z urllib3.exceptions.ProtocolError: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.662482667Z 
2024-06-10T10:22:07.662533864Z During handling of the above exception, another exception occurred:
2024-06-10T10:22:07.662582538Z 
2024-06-10T10:22:07.662629056Z Traceback (most recent call last):
2024-06-10T10:22:07.662678734Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 214, in _retrieve_server_version
2024-06-10T10:22:07.662765781Z     return self.version(api_version=False)["ApiVersion"]
2024-06-10T10:22:07.662816243Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.662860988Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/daemon.py", line 181, in version
2024-06-10T10:22:07.662941852Z     return self._result(self._get(url), json=True)
2024-06-10T10:22:07.662993352Z                         ^^^^^^^^^^^^^^
2024-06-10T10:22:07.663040947Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/utils/decorators.py", line 46, in inner
2024-06-10T10:22:07.663088260Z     return f(self, *args, **kwargs)
2024-06-10T10:22:07.663169819Z            ^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.663217688Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 237, in _get
2024-06-10T10:22:07.663264116Z     return self.get(url, **self._set_request_timeout(kwargs))
2024-06-10T10:22:07.663312639Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.663401195Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/sessions.py", line 602, in get
2024-06-10T10:22:07.663456883Z     return self.request("GET", url, **kwargs)
2024-06-10T10:22:07.663505328Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.663552586Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/sessions.py", line 589, in request
2024-06-10T10:22:07.663732368Z     resp = self.send(prep, **send_kwargs)
2024-06-10T10:22:07.663794558Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.663862484Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/sessions.py", line 703, in send
2024-06-10T10:22:07.663949369Z     r = adapter.send(request, **kwargs)
2024-06-10T10:22:07.664004938Z         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.664081851Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/requests/adapters.py", line 501, in send
2024-06-10T10:22:07.664134940Z     raise ConnectionError(err, request=request)
2024-06-10T10:22:07.664225815Z requests.exceptions.ConnectionError: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.664286067Z 
2024-06-10T10:22:07.664333271Z During handling of the above exception, another exception occurred:
2024-06-10T10:22:07.664379805Z 
2024-06-10T10:22:07.664422711Z Traceback (most recent call last):
2024-06-10T10:22:07.664503412Z   File "/opt/code/localstack/localstack/utils/container_utils/docker_sdk_client.py", line 76, in _create_client
2024-06-10T10:22:07.664552139Z     return docker.from_env(timeout=DOCKER_SDK_DEFAULT_TIMEOUT_SECONDS)
2024-06-10T10:22:07.664597316Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.664673420Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/client.py", line 96, in from_env
2024-06-10T10:22:07.664721143Z     return cls(
2024-06-10T10:22:07.664768948Z            ^^^^
2024-06-10T10:22:07.664814579Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/client.py", line 45, in __init__
2024-06-10T10:22:07.664897465Z     self.api = APIClient(*args, **kwargs)
2024-06-10T10:22:07.664945468Z                ^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.664999703Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 197, in __init__
2024-06-10T10:22:07.665057320Z     self._version = self._retrieve_server_version()
2024-06-10T10:22:07.665142260Z                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-06-10T10:22:07.665190690Z   File "/opt/code/localstack/.venv/lib/python3.11/site-packages/docker/api/client.py", line 221, in _retrieve_server_version
2024-06-10T10:22:07.665239928Z     raise DockerException(
2024-06-10T10:22:07.665285220Z docker.errors.DockerException: Error while fetching server API version: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))
2024-06-10T10:22:07.666751581Z 2024-06-10T10:22:07.666 DEBUG --- [  MainThread] localstack.utils.threads   : start_thread called without providing a custom name
2024-06-10T10:22:07.669252804Z 2024-06-10T10:22:07.668 DEBUG --- [-functhread3] localstack.utils.run       : Executing command: whoami
2024-06-10T10:22:07.875159013Z 2024-06-10T10:22:07.875  WARN --- [-functhread3] l.services.internal        : Enabling diagnose endpoint, please be aware that this can expose sensitive information via your network.
2024-06-10T10:22:08.053283292Z 2024-06-10T10:22:08.053 DEBUG --- [-functhread3] localstack.utils.ssl       : Attempting to download local SSL certificate file
2024-06-10T10:22:08.405311337Z 2024-06-10T10:22:08.405 DEBUG --- [-functhread3] localstack.utils.http      : Starting download from https://github.com/localstack/localstack-artifacts/raw/master/local-certs/server.key to /var/lib/localstack/cache/server.test.pem
2024-06-10T10:22:08.406124895Z 2024-06-10T10:22:08.405 DEBUG --- [-functhread3] localstack.utils.http      : Downloaded 100% (total 4K of 4K) to /var/lib/localstack/cache/server.test.pem
2024-06-10T10:22:08.407959121Z 2024-06-10T10:22:08.407 DEBUG --- [-functhread3] localstack.utils.http      : Done downloading https://github.com/localstack/localstack-artifacts/raw/master/local-certs/server.key, response code 200, total 4K
2024-06-10T10:22:08.580031351Z 2024-06-10T10:22:08.579  INFO --- [  MainThread] localstack.utils.bootstrap : Execution of "start_runtime_components" took 912.98ms
2024-06-10T10:22:08.581368883Z 2024-06-10T10:22:08.580 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='acm:default', value='localstack.services.providers:acm', group='localstack.aws.provider')
2024-06-10T10:22:08.589872690Z 2024-06-10T10:22:08.589 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='apigateway:default', value='localstack.services.providers:apigateway', group='localstack.aws.provider')
2024-06-10T10:22:08.590089873Z 2024-06-10T10:22:08.589 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='cloudformation:default', value='localstack.services.providers:cloudformation', group='localstack.aws.provider')
2024-06-10T10:22:08.590414888Z 2024-06-10T10:22:08.590 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='cloudwatch:default', value='localstack.services.providers:cloudwatch', group='localstack.aws.provider')
2024-06-10T10:22:08.590721723Z 2024-06-10T10:22:08.590 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='cloudwatch:v1', value='localstack.services.providers:cloudwatch_v1', group='localstack.aws.provider')
2024-06-10T10:22:08.590941763Z 2024-06-10T10:22:08.590 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='cloudwatch:v2', value='localstack.services.providers:cloudwatch_v2', group='localstack.aws.provider')
2024-06-10T10:22:08.591264416Z 2024-06-10T10:22:08.590 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='config:default', value='localstack.services.providers:awsconfig', group='localstack.aws.provider')
2024-06-10T10:22:08.591450279Z 2024-06-10T10:22:08.591 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='dynamodb:default', value='localstack.services.providers:dynamodb', group='localstack.aws.provider')
2024-06-10T10:22:08.591761840Z 2024-06-10T10:22:08.591 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='dynamodbstreams:default', value='localstack.services.providers:dynamodbstreams', group='localstack.aws.provider')
2024-06-10T10:22:08.592022365Z 2024-06-10T10:22:08.591 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='ec2:default', value='localstack.services.providers:ec2', group='localstack.aws.provider')
2024-06-10T10:22:08.592311770Z 2024-06-10T10:22:08.592 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='es:default', value='localstack.services.providers:es', group='localstack.aws.provider')
2024-06-10T10:22:08.592542920Z 2024-06-10T10:22:08.592 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='events:default', value='localstack.services.providers:events', group='localstack.aws.provider')
2024-06-10T10:22:08.592821692Z 2024-06-10T10:22:08.592 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='events:v1', value='localstack.services.providers:events_v1', group='localstack.aws.provider')
2024-06-10T10:22:08.593123281Z 2024-06-10T10:22:08.592 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='events:v2', value='localstack.services.providers:events_v2', group='localstack.aws.provider')
2024-06-10T10:22:08.593260130Z 2024-06-10T10:22:08.593 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='firehose:default', value='localstack.services.providers:firehose', group='localstack.aws.provider')
2024-06-10T10:22:08.593545933Z 2024-06-10T10:22:08.593 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='iam:default', value='localstack.services.providers:iam', group='localstack.aws.provider')
2024-06-10T10:22:08.593779473Z 2024-06-10T10:22:08.593 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='kinesis:default', value='localstack.services.providers:kinesis', group='localstack.aws.provider')
2024-06-10T10:22:08.594025595Z 2024-06-10T10:22:08.593 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='kms:default', value='localstack.services.providers:kms', group='localstack.aws.provider')
2024-06-10T10:22:08.594260665Z 2024-06-10T10:22:08.594 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='lambda:asf', value='localstack.services.providers:lambda_asf', group='localstack.aws.provider')
2024-06-10T10:22:08.594477904Z 2024-06-10T10:22:08.594 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='lambda:default', value='localstack.services.providers:lambda_', group='localstack.aws.provider')
2024-06-10T10:22:08.594719845Z 2024-06-10T10:22:08.594 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='lambda:v2', value='localstack.services.providers:lambda_v2', group='localstack.aws.provider')
2024-06-10T10:22:08.595009899Z 2024-06-10T10:22:08.594 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='logs:default', value='localstack.services.providers:logs', group='localstack.aws.provider')
2024-06-10T10:22:08.595302798Z 2024-06-10T10:22:08.595 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='opensearch:default', value='localstack.services.providers:opensearch', group='localstack.aws.provider')
2024-06-10T10:22:08.595536966Z 2024-06-10T10:22:08.595 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='redshift:default', value='localstack.services.providers:redshift', group='localstack.aws.provider')
2024-06-10T10:22:08.595869935Z 2024-06-10T10:22:08.595 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='resource-groups:default', value='localstack.services.providers:resource_groups', group='localstack.aws.provider')
2024-06-10T10:22:08.596095987Z 2024-06-10T10:22:08.595 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='resourcegroupstaggingapi:default', value='localstack.services.providers:resourcegroupstaggingapi', group='localstack.aws.provider')
2024-06-10T10:22:08.596329359Z 2024-06-10T10:22:08.596 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='route53:default', value='localstack.services.providers:route53', group='localstack.aws.provider')
2024-06-10T10:22:08.596637719Z 2024-06-10T10:22:08.596 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='route53resolver:default', value='localstack.services.providers:route53resolver', group='localstack.aws.provider')
2024-06-10T10:22:08.596875726Z 2024-06-10T10:22:08.596 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3:asf', value='localstack.services.providers:s3_asf', group='localstack.aws.provider')
2024-06-10T10:22:08.597165510Z 2024-06-10T10:22:08.596 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3:default', value='localstack.services.providers:s3', group='localstack.aws.provider')
2024-06-10T10:22:08.597377829Z 2024-06-10T10:22:08.597 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3:legacy_v2', value='localstack.services.providers:s3_legacy_v2', group='localstack.aws.provider')
2024-06-10T10:22:08.597656619Z 2024-06-10T10:22:08.597 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3:stream', value='localstack.services.providers:s3_stream', group='localstack.aws.provider')
2024-06-10T10:22:08.597906437Z 2024-06-10T10:22:08.597 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3:v2', value='localstack.services.providers:s3_v2', group='localstack.aws.provider')
2024-06-10T10:22:08.598237482Z 2024-06-10T10:22:08.597 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3:v3', value='localstack.services.providers:s3_v3', group='localstack.aws.provider')
2024-06-10T10:22:08.598376852Z 2024-06-10T10:22:08.598 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='s3control:default', value='localstack.services.providers:s3control', group='localstack.aws.provider')
2024-06-10T10:22:08.598693842Z 2024-06-10T10:22:08.598 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='scheduler:default', value='localstack.services.providers:scheduler', group='localstack.aws.provider')
2024-06-10T10:22:08.598894683Z 2024-06-10T10:22:08.598 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='secretsmanager:default', value='localstack.services.providers:secretsmanager', group='localstack.aws.provider')
2024-06-10T10:22:08.599185496Z 2024-06-10T10:22:08.598 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='ses:default', value='localstack.services.providers:ses', group='localstack.aws.provider')
2024-06-10T10:22:08.599373682Z 2024-06-10T10:22:08.599 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='sns:default', value='localstack.services.providers:sns', group='localstack.aws.provider')
2024-06-10T10:22:08.599683519Z 2024-06-10T10:22:08.599 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='sqs:default', value='localstack.services.providers:sqs', group='localstack.aws.provider')
2024-06-10T10:22:08.599947030Z 2024-06-10T10:22:08.599 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='ssm:default', value='localstack.services.providers:ssm', group='localstack.aws.provider')
2024-06-10T10:22:08.600207128Z 2024-06-10T10:22:08.599 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='stepfunctions:default', value='localstack.services.providers:stepfunctions', group='localstack.aws.provider')
2024-06-10T10:22:08.600396905Z 2024-06-10T10:22:08.600 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='stepfunctions:legacy', value='localstack.services.providers:stepfunctions_v1', group='localstack.aws.provider')
2024-06-10T10:22:08.600939223Z 2024-06-10T10:22:08.600 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='stepfunctions:v1', value='localstack.services.providers:stepfunctions_legacy', group='localstack.aws.provider')
2024-06-10T10:22:08.601096512Z 2024-06-10T10:22:08.600 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='stepfunctions:v2', value='localstack.services.providers:stepfunctions_v2', group='localstack.aws.provider')
2024-06-10T10:22:08.601207325Z 2024-06-10T10:22:08.600 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='sts:default', value='localstack.services.providers:sts', group='localstack.aws.provider')
2024-06-10T10:22:08.601519306Z 2024-06-10T10:22:08.601 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='support:default', value='localstack.services.providers:support', group='localstack.aws.provider')
2024-06-10T10:22:08.601824186Z 2024-06-10T10:22:08.601 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='swf:default', value='localstack.services.providers:swf', group='localstack.aws.provider')
2024-06-10T10:22:08.601994564Z 2024-06-10T10:22:08.601 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='transcribe:default', value='localstack.services.providers:transcribe', group='localstack.aws.provider')
2024-06-10T10:22:08.603012099Z Ready.
2024-06-10T10:22:08.603252326Z 2024-06-10T10:22:08.603 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='_run_init_scripts_on_ready', value='localstack.runtime.init:_run_init_scripts_on_ready', group='localstack.hooks.on_infra_ready')
2024-06-10T10:22:08.603409921Z 2024-06-10T10:22:08.603 DEBUG --- [  MainThread] stevedore.extension        : found extension EntryPoint(name='register_virtual_host_routes', value='localstack.services.s3.virtual_host:register_virtual_host_routes', group='localstack.hooks.on_infra_ready')
2024-06-10T10:22:08.604885462Z 2024-06-10T10:22:08.604 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_ready._run_init_scripts_on_ready = <function _run_init_scripts_on_ready at 0x7f4c8d44ab60>)
2024-06-10T10:22:08.605028447Z 2024-06-10T10:22:08.604 DEBUG --- [  MainThread] plux.runtime.manager       : loading plugin localstack.hooks.on_infra_ready:_run_init_scripts_on_ready
2024-06-10T10:22:08.605134213Z 2024-06-10T10:22:08.604 DEBUG --- [  MainThread] plux.runtime.manager       : instantiating plugin PluginSpec(localstack.hooks.on_infra_ready.register_virtual_host_routes = <function register_virtual_host_routes at 0x7f4c84328540>)
2024-06-10T10:22:08.605317734Z 2024-06-10T10:22:08.605 DEBUG --- [  MainThread] plux.runtime.manager       : plugin localstack.hooks.on_infra_ready:register_virtual_host_routes is disabled, reason: Load condition for plugin was false
2024-06-10T10:22:08.605535601Z 2024-06-10T10:22:08.605 DEBUG --- [  MainThread] localstack.runtime.init    : Running READY script /etc/localstack/init/ready.d/script.sh

@localstack-bot localstack-bot removed the status: response required Waiting for a response from the reporter label Jun 10, 2024
@bentsku
Copy link
Contributor
bentsku commented Jun 10, 2024

Ah, sorry to hear it's still an issue.
Could you maybe try with localstack/localstack:latest instead of 3.4, just to be sure?

You can also use LS_LOG=trace and run the test case and share the LocalStack logs, we might get more data into why it's failing and what requests does LocalStack receive.

With the above logs, we should see what server LocalStack uses as the logs are different, no mention to hypercorn anymore.

@bentsku bentsku added the status: response required Waiting for a response from the reporter label Jun 10, 2024
@daniel-frak
Copy link
Author

For whatever reason, using localstack:latest like this:

  localstack:
    image: localstack/localstack:latest
    restart: unless-stopped
    ports:
      - "4566:4566"
    environment:
      - DEBUG=1
      - LS_LOG=trace
      - GATEWAY_SERVER=twisted
    volumes:
      - ./localstack/localstack-script.sh:/etc/localstack/init/ready.d/script.sh # Init script
      - localstack:/var/lib/localstack"

... Pulls localstack:3.2.1.dev. Unfortunately, the problem persists.

What I apparently failed to notice before is that with GATEWAY_SERVER=twisted the error disappears from LocalStack logs, although the problem persists. The client still throws org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body.

I've attached logs with LS_LOG=trace for both 3.4.0 and 3.2.1.dev, from initialisation all the way to the failed import:

@localstack-bot localstack-bot removed the status: response required Waiting for a response from the reporter label Jun 11, 2024
@bentsku
Copy link
Contributor
bentsku commented Jun 11, 2024

Hi!

For the old image being used, this is because it is the one you have on your system. You can run docker pull localstack/localstack:latest before starting the docker compose, or add the pull_policy field with the always value. See https://docs.docker.com/compose/compose-file/05-services/#pull_policy, if you setting the image to latest.

The problem persisting with the old image makes sense.

Looking at the logs, as they use twisted, like you said, the error is not shown in the logs anymore. I still suspect the timeout like your first intuition with the following:

I tried reproducing the error using a small file and Thread.sleep() (to simulate processing while the Response is open) and the error didn't occur.

The LocalStack S3 server will send the response in chunks of 65536 bytes. Was the small file you tried with sleep bigger than this?

I have a feeling maybe the OpenCSV isn't pulling enough data from the server and the server then times out sending this particular chunk. Maybe our timeout is too small, or the chunk size too big. I could try making it configurable to see if that solves this particular issue, I'll also ping some members of the team responsible for our HTTP server.

In the meantime, if you'd like to repeat the experiment with the Thread.sleep() with a bigger file, we could maybe see if that's exactly the issue.

Sorry again for the inconvenience, we'll get to the bottom of this!

@bentsku bentsku added the status: response required Waiting for a response from the reporter label Jun 11, 2024
@daniel-frak
Copy link
Author

Thanks for the great support!

The file I was using Thread.sleep() with was indeed just 704 bytes.

I'll try it with a bigger file (>65536 bytes) tomorrow and I'll let you know how it went.

@localstack-bot localstack-bot removed the status: response required Waiting for a response from the reporter label Jun 11, 2024
@bentsku bentsku added the status: response required Waiting for a response from the reporter label Jun 11, 2024
@daniel-frak
Copy link
Author

Some new information:

  1. I have confirmed that the code works in production (with AWS in place of LocalStack), which further suggests that the issue is in how LocalStack handles things.
  2. Using localstack:latest (3.4.1.dev) didn't fix the issue.
  3. Using a bigger file (173MB) with Thread.sleep() in a local test reproduced the issue.

Running the test twice more without Thread.sleep() didn't produce the issue with that particular file, so this is more evidence that there's a link between file size and processing time.

The relevant code:

try (var reader = new BufferedReader(new InputStreamReader(response, StandardCharsets.UTF_8))) {
    var csvToBean = buildCsvToBeanReader(reader);
    Thread.sleep(120_000);
    csvToBean.parse();
}

Is there any other way I can assist in finding the cause? Should I try with some other file sizes?

@localstack-bot localstack-bot removed the status: response required Waiting for a response from the reporter label Jun 12, 2024
@bentsku
Copy link
Contributor
bentsku commented Jun 12, 2024

Hello! Thanks for coming back to me.

So there is a 120s sleep time before continuing processing and this fails. But does this 120s sleep time fails against AWS as well?
This is a rather tricky issue to debug, we'd maybe need more data about timing, how much OpenCSV is pulling, in order to be sure to solve it.

Would there be any way to create a very small reproducer in a Git repo, so that we could reproduce the issue ourselves too? The sample could manually create the big CSV itself before uploading it.

@bentsku bentsku added the status: response required Waiting for a response from the reporter label Jun 12, 2024
@daniel-frak
Copy link
Author

I asked about our production code and apparently it has already been tested with Thread.sleep() in this way:

try (var reader = new BufferedReader(new InputStreamReader(response, StandardCharsets.UTF_8))) {
    var csvToBean = buildCsvToBeanReader(reader);

    var iterator = csvToBean.iterator();
    count = 0;
    while (iterator.hasNext()) {
        iterator.next();
        count++;
        if (count % 500_000 == 0) {
            Thread.sleep(60000);
        }
    }
}

The whole import apparently took 20 minutes and was successful, so I guess that test's done.

I'll try to create a minimal repro repository today!

@localstack-bot localstack-bot removed the status: response required Waiting for a response from the reporter label Jun 13, 2024
@daniel-frak
Copy link
Author
daniel-frak commented Jun 13, 2024

I created a minimal reproduction here:

https://github.com/daniel-frak/localstack-s3-issue-reproduction

I managed to make it fail when uploading a 10 megabyte file with a 90 second Thread.sleep():

org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 10,000,000; received: 9,502,720)

Anything much lower than that seemed to not reproduce the error.

@bentsku bentsku added status: backlog Triaged but not yet being worked on status: in progress Currently being worked on and removed status: backlog Triaged but not yet being worked on labels Jun 13, 2024
@bentsku
Copy link
Contributor
bentsku commented Jun 13, 2024

Thank you for taking the time to make the sample! I'll come back to you once I have more info to share, but will look into it shortly.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: infrastructure Installation and startup of LocalStack and components aws:s3 Amazon Simple Storage Service status: in progress Currently being worked on type: bug Bug report
Projects
None yet
Development

No branches or pull requests

3 participants