awslabs/amazon-sqs-java-temporary-queues-client

Virtual queues created and deleted in loop

sheldon-markk opened this issue · 14 comments

sheldon-markk commented

We are currently testing temporary queues with our apis for request/response messaging. After running the api the messages are passed and response is received as expected. Can see the queues on sqs console too.

After 5 min the idleSweepPeriods thread runs to check for idle queues and multiple virtual queue are created and deleted can seem them written to application logs continuously.

 INFO [SQSMessageConsumer-Thread-9] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 6 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/markk-api-queue85eb0b0b-854c-456c-baae-0dc69dfc8a5d-0#markk-api-queue320a6d11-1d0a-48b5-ab69-29588c722e36
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 7 and Queue Name is markk-api-queueb47c3650-5980-4bdf-8e99-8b8336303286
 INFO [SQSMessageConsumer-Thread-9] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 6 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/markk-api-queue85eb0b0b-854c-456c-baae-0dc69dfc8a5d-0#markk-api-queueb47c3650-5980-4bdf-8e99-8b8336303286
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix markk-api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 7 and Queue Name is markk-api-queueaa9a124d-0cec-4c9e-97c0-39d9993351ee
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 8 and Queue Name is markk-api-queue628ecf70-03b2-41c8-ad56-c6838973cf21
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix markk-api-queue for idleness
sheldon-markk commented

Kept the server running for a while and then started getting out of memory errors

INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix markk-api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 115 and Queue Name is markk-api-queuecdf5c01c-46a8-4558-ad10-6ed11dacacf6
[7654.397s][warning][os,thread] Failed to start thread - pthread_create failed (EAGAIN) for attributes: stacksize: 1024k, guardsize: 4k, detached.
[7654.397s][warning][os,thread] Failed to start thread - pthread_create failed (EAGAIN) for attributes: stacksize: 1024k, guardsize: 4k, detached.
Exception in thread "SQSMessageConsumer-Thread-2074" java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached
	at java.base/java.lang.Thread.start0(Native Method)
	at java.base/java.lang.Thread.start(Thread.java:803)
	at java.base/java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:937)
	at java.base/java.util.concurrent.ThreadPoolExecutor.processWorkerExit(ThreadPoolExecutor.java:1005)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
robin-aws commented

Thanks for reporting this @sheldon-markk. How long does the server run before exhausting memory? Can you share your configuration here? I'm assuming you're just using the AmazonSQSRequester interface and builder?

I'll see if I can reproduce this myself.

sheldon-markk commented 
amazonSQS = SQSUtility.getSQSClient(SQSUtility.getRegion());
        amazonSQSRequester = AmazonSQSRequesterClientBuilder.standard()
                .withAmazonSQS(amazonSQS)
                .withInternalQueuePrefix(INTERNAL_QUEUE_PREFIX)
                .build();

Sending the request

String queueUrl = SQSUtility.getQueueUrl(apiQueueRequest, region);
            LOGGER.info("SQS: request {0} for queue {1}", apiQueueRequest,queueUrl);
            SendMessageRequest queueRequest = new SendMessageRequest()
                    .withQueueUrl(queueUrl)
                    .withMessageBody(Json.encode(apiQueueRequest));
            responseBody = amazonSQSRequester.sendMessageAndGetResponse(
                    queueRequest, 5, TimeUnit.SECONDS).getBody();
            LOGGER.info("SQS: response {0} from queue {1}", responseBody,queueUrl);

Consumer

SQSMessageConsumer consumerSQS = SQSMessageConsumerBuilder.standard()
                .withAmazonSQS(sqsResponder.getAmazonSQS())
                .withQueueUrl(queueUrl)
                .withConsumer(message -> {
                    LOGGER.info("SQS: request {0} received for queue {1}",message.getBody(),queueUrl);
                    executeApi(sqsResponder,message);
                }).build();
        consumerSQS.start();

 private void executeApi(AmazonSQSResponder sqsResponder, Message consumerMessage) {
        ApiQueueRequest request = CustomJson.decodeValue(consumerMessage.getBody(),ApiQueueRequest.class);
        String reponse = //run api to get response
        sqsResponder.sendResponseMessage(MessageContent.fromMessage(consumerMessage),
                        new MessageContent(response));
            }
        });
    }
sheldon-markk commented

Log entries
When request is made

SQS: request com.entities.http.request.ApiQueueRequest@5f7ac35 for queue queue-name
 INFO [vert.x-worker-thread-13] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 1 and Queue Name is api-queue3706be2d-189f-4548-a6ff-51cc1fd3dc1e

Response log

INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 0 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queuebcd52e08-1fa8-49d5-88a3-f367932bc434-0#api-queue3706be2d-189f-4548-a6ff-51cc1fd3dc1e

I keep the server running and then the list of log entries create and delete queues occurs. This happened on aws-sdk-java version 1.11.546.

sheldon-markk commented

Today when we upgraded the aws-sdk-java version 1.11.623, this issue does not occur.

sheldon-markk commented

After a bit we restarted our app server and then the idleSweeper did this, created and deleting virtual queues in loop.

INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 1 and Queue Name is api-queue3d6ee080-b939-4dfe-b69f-5d498276d3b8
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 2 and Queue Name is api-queue00e44485-3f33-4a8c-a567-19c880abdf75
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queue6925bded-720c-44fa-8557-05e10b4122b2
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 4 and Queue Name is api-queue436d977d-03cd-4909-a98e-3d7ae350a68e
 INFO [SQSMessageConsumer-Thread-7] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 3 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue6925bded-720c-44fa-8557-05e10b4122b2
 INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue3d6ee080-b939-4dfe-b69f-5d498276d3b8
 INFO [SQSMessageConsumer-Thread-8] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 1 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue436d977d-03cd-4909-a98e-3d7ae350a68e
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 2 and Queue Name is api-queuec05cbbad-fa56-4b7e-825d-a99146263d94
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queue5ea2bd00-638e-4156-b22f-6f1883b44e7e
 INFO [SQSMessageConsumer-Thread-6] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue00e44485-3f33-4a8c-a567-19c880abdf75
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queuef1398600-9c29-495d-94fb-5474dab9425e
 INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue5ea2bd00-638e-4156-b22f-6f1883b44e7e
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queuef6b86838-5617-41bb-8a18-1d1bab287053
 INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuef6b86838-5617-41bb-8a18-1d1bab287053
 INFO [SQSMessageConsumer-Thread-8] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuec05cbbad-fa56-4b7e-825d-a99146263d94
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 2 and Queue Name is api-queuec061ff46-39b6-44ba-8c1a-d5b09239eda0
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queuea2b4d839-6bf0-4aee-9671-1bface130a72
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 4 and Queue Name is api-queuecb8d2612-6912-4d43-a04e-fc1574e0bdf8
 INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 3 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuea2b4d839-6bf0-4aee-9671-1bface130a72
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 4 and Queue Name is api-queue262c2874-64fd-426e-a779-4e8f5ff74ab5
 INFO [SQSMessageConsumer-Thread-7] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 3 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuecb8d2612-6912-4d43-a04e-fc1574e0bdf8
 INFO [SQSMessageConsumer-Thread-6] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuef1398600-9c29-495d-94fb-5474dab9425e
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queuec2ae3115-60ce-4aa2-aaef-e8b9b8e96b11
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 4 and Queue Name is api-queue669d804b-8301-4982-82f7-ef5b6d5f5162
 INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 3 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue262c2874-64fd-426e-a779-4e8f5ff74ab5
 INFO [SQSMessageConsumer-Thread-6] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 3 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuec2ae3115-60ce-4aa2-aaef-e8b9b8e96b11
 INFO [SQSMessageConsumer-Thread-7] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 1 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue669d804b-8301-4982-82f7-ef5b6d5f5162
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 2 and Queue Name is api-queue7e0b9c1e-5ae1-4bd2-99ee-1bfa6211ba83
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queue41f553b8-0ce9-4da8-a71d-e2c54c12674c
 INFO [SQSMessageConsumer-Thread-8] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queuec061ff46-39b6-44ba-8c1a-d5b09239eda0
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queuec293e73f-0725-4ea0-814e-9d8ca66812fc
 INFO [SQSMessageConsumer-Thread-7] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue7e0b9c1e-5ae1-4bd2-99ee-1bfa6211ba83
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queue8e1eac17-9136-4d16-83b0-a8b2a19be741
 INFO [SQSMessageConsumer-Thread-5] (AmazonSQSVirtualQueuesClient.java:190) – Deleting Virtual Queue is 2 and Queue Name is https://sqs.us-west-1.amazonaws.com/385242147137/api-queue38fc7417-a1ac-4d66-b033-e3817d0fa687-0#api-queue41f553b8-0ce9-4da8-a71d-e2c54c12674c
 INFO [SQSMessageConsumer-Thread-2] (IdleQueueSweeper.java:49) – Checking all queues begining with prefix api-queue for idleness
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 3 and Queue Name is api-queued0f914db-9949-4e36-bd79-108f9ef3bc5d
 INFO [SQSMessageConsumer-Thread-2] (AmazonSQSVirtualQueuesClient.java:161) – Total Virtual Queue Created is 4 and Queue Name is api-queue007cb5f1-c700-4b77-8163-b4a1395dcd6e
sheldon-markk commented

This the issues is related to #11 as we had more that 100 queues created since yesterday.

dekelpilli commented

Today when we upgraded the aws-sdk-java version 1.11.623, this issue does not occur.

@sheldon-markk can you explain the new behaviour once you upgraded?

Also, you say it's related to #11, does that mean you've seen the .rO0ABXA= (null) messages on your queues?

sheldon-markk commented

Once we upgraded we assumed the issue was resolved as we did not see multiple queues created, but this was not the case.
I checked the messages in the queues and yes they are null messages, over a 1000 now.

robin-aws commented

Just wanted to give an update here: I haven't gotten to the bottom of the null message yet, but I did discover the memory leak that leads to the out of memory errors. I'm planning on fixing that and adding a DLQ to the sweeping queue, as well as inserting a few more explicit checks for null to hopefully catch it on the sending side instead of the receiving side.

Note that seeing lots of virtual queue use during the sweeping is by design to a degree - the distributed sweeping task uses virtual queues itself. The issue is more in the noisy logging. That snuck in from #7 - I'll remove it if I can get the requester to agree to it.

sheldon-markk commented

With the 1.0.1 release now things are working fine.

robin-aws commented

Closing this issue as the specific symptoms it describes (the memory leak and the excess logging) are resolved. Will continue to track the null messages problem in #11. Please reopen if necessary!

ravinderdasari8 commented

@sheldon-markk :
I am trying to implement request-response messaging pattern. I would say I am new to it,

Could you please explain below:

  1. Did you kept supplier i.e. amazonSQSRequester.sendMessageAndGetResponse()
    and
    consumer i.e. consumerSQS.start();

How did they communicate with each other. Is it by consumer is also subscribed to the same queue?

In my case I mixed it with @SQSListerner; but I get the message body and parameters as NULL.

  1. Did the flow stop automatically after processing the message.

Any help would be much appreciated.

ravinderdasari8 commented

@sheldon-markk : I tried to see your repo for any code example; but I didn't find any :(