search

softwaremill / elasticmq

In-memory message queue with an Amazon SQS-compatible interface. Runs stand-alone or embedded.
https://softwaremill.com/open-source/
Apache License 2.0
2.51k stars 194 forks source link

Wrong MessageId returned sometimes #71

Closed slobo closed 8 years ago

slobo commented 8 years ago

Hi Adam, I'm running into an issue where only sometimes MessageId from result of SendMessage is not the same one that gets returned by ReceiveMessage. It seems that SendMessage generates "double the actions" (see log), and then ReceiveMessage does the same, and one of the MessageIds gets returned first at random.

A simple script that utilizes official AWS SDK v3 is pasted at bottom that just generates a random message, then sends it, receives it back and compares MessageId and MessageBody. MessageBody always matches, but MessageId sometimes doesn't.

This is my config:

include classpath("application.conf")

node-address {
    protocol = http
    host = "*"
    port = 80
    context-path = ""
}

rest-sqs {
    enabled = true
    bind-port = 9324
    bind-hostname = "0.0.0.0"
    # Possible values: relaxed, strict
    sqs-limits = strict
}

queues {
    test-123 {}
}

log configuration:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="org.elasticmq" level="TRACE"/>

    <root level="TRACE">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Log:

aws-sqs1 2016-04-08T22:31:43.158011421Z 22:31:43.157 [elasticmq-akka.actor.default-dispatcher-8] DEBUG akka.io.TcpListener - New connection accepted
aws-sqs1 2016-04-08T22:31:43.165876552Z 22:31:43.165 [elasticmq-akka.actor.default-dispatcher-4] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.180708743Z 22:31:43.180 [elasticmq-akka.actor.default-dispatcher-8] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.181264827Z 22:31:43.180 [elasticmq-akka.actor.default-dispatcher-8] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.190740346Z 22:31:43.190 [elasticmq-akka.actor.default-dispatcher-4] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.190948696Z 22:31:43.190 [elasticmq-akka.actor.default-dispatcher-4] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.191659715Z 22:31:43.191 [elasticmq-akka.actor.default-dispatcher-4] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Sent message with id 620173eb-1e11-4f51-b5a0-f14a31b5f426
aws-sqs1 2016-04-08T22:31:43.194201887Z 22:31:43.191 [elasticmq-akka.actor.default-dispatcher-2] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Sent message with id b994f26a-b80e-4777-a952-7dde16951d06
aws-sqs1 2016-04-08T22:31:43.209773326Z 22:31:43.209 [elasticmq-akka.actor.default-dispatcher-6] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.210000653Z 22:31:43.209 [elasticmq-akka.actor.default-dispatcher-6] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
aws-sqs1 2016-04-08T22:31:43.210338297Z 22:31:43.210 [elasticmq-akka.actor.default-dispatcher-2] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Receiving message 620173eb-1e11-4f51-b5a0-f14a31b5f426
aws-sqs1 2016-04-08T22:31:43.213298828Z 22:31:43.212 [elasticmq-akka.actor.default-dispatcher-8] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Receiving message b994f26a-b80e-4777-a952-7dde16951d06

Simple test program that sometimes succeeds, sometimes fails

<?php

use Aws\Sqs\SqsClient;

class AwsFakeTest extends PHPUnit_Framework_TestCase {

  public function testSQS(){
    $sqs = new SqsClient([
      'version'  => 'latest',
      'region'   => 'us-east-1',
      'endpoint' => 'http://localhost:9324',]);

    $queue = $sqs->getQueueUrl(['QueueName' => 'test-123']);

    // ensure we are operating on clean dataset
    $sqs->purgeQueue(['QueueUrl' => $queue['QueueUrl']]);

    $message_body = 'hello world ' . uniqid();

    $message = $sqs->sendMessage([
      'MessageBody' => $message_body,
      'QueueUrl'    => $queue['QueueUrl']]);

    $this->assertNotEmpty($message['MessageId'],
      'Got back some MessageId when storing new message');

    $receipt = $sqs->receiveMessage([
      'AttributeNames' => ['All'],
      'QueueUrl' => $queue['QueueUrl']]);

    $this->assertEquals($message_body, $receipt['Messages'][0]['Body'],
      'Received same message content');

    $this->assertEquals($message['MessageId'], $receipt['Messages'][0]['MessageId'],
      'Received back same message_id ');
  }
}

The test that fails is 'Received back same message_id`. Any suggestions?

Here is a trace from mitmproxy, only one SendMessage is issued with the following body:

2016-04-08 16:37:09 POST http://10.10.0.110:9324/queue/test-123
                         ← 200 text/plain 579B 26ms
                       Request                                             Response                                              Detail
Host:                   10.10.0.110:9324
Proxy-Connection:       Keep-Alive
Content-Type:           application/x-www-form-urlencoded
aws-sdk-invocation-id:  614d4c4662680d30f9ee1b0538c4e492
aws-sdk-retry:          0/0
X-Amz-Date:             20160408T233709Z
Authorization:          AWS4-HMAC-SHA256 Credential=dummy_aws_access_key/20160408/us-east-1/sqs/aws4_request,
                        SignedHeaders=aws-sdk-invocation-id;aws-sdk-retry;host;x-amz-date,
                        Signature=68fa98c4943903dea5186bd1737b435b2e98b0c048f73c27afe6d7a6b4cc7ae9
User-Agent:             aws-sdk-php/3.17.5 GuzzleHttp/6.2.0 curl/7.47.0 PHP/5.6.19
Content-Length:         139
URLEncoded form                                                                                                                                       [m:Auto]
Action:      SendMessage
Version:     2012-11-05
MessageBody: hello world 570840a584481
QueueUrl:    http://10.10.0.110:9324/queue/test-123

(Btw, it seems that with perl library i talked about last time this is not a problem)

adamw commented 8 years ago

I tried reproducing using the Java SDK but things work as expected. Are you sure there's only one request coming in? Maybe you could set the elasticmq.debug configuration property to true, this should log the requests as well.

Otherwise, this would need some debugging - is it possible to somehow run this PHP test locally, without installing half of the internet? ;)

slobo commented 8 years ago

Thanks for looking into this. This reproduces it on my computer:

curl -H 'Host:localhost:9324' -H 'Content-Type:application/x-www-form-urlencoded' -H 'aws-sdk-invocation-id:cde964dbc58b36399d4937f448f0f0a5' -H 'aws-sdk-retry:0/0' -H 'X-Amz-Date:20160413T040326Z' -H 'Authorization:AWS4-HMAC-SHA256 Credential=dummy_aws_access_key/20160413/us-east-1/sqs/aws4_request, SignedHeaders=aws-sdk-invocation-id;aws-sdk-retry;host;x-amz-date, Signature=884868bd3a224fbeed486a525562f2d7b796abce4cbd1e9bfa51da33f3bb68cf' -H 'User-Agent:aws-sdk-php/3.17.5 GuzzleHttp/6.2.0 curl/7.47.0 PHP/5.6.19' -H 'Content-Length:137' -X POST 'http://localhost:9324/queue/test-123' --data-binary 'Action=SendMessage&Version=2012-11-05&MessageBody=hello%20world%20570dc50e47f4a&QueueUrl=http%3A%2F%2Flocalhost%3A9324%2Fqueue%2Ftest-123'
slobo commented 8 years ago

(and this is the log I get when running the above)

➤ java -jar -Dconfig.file=custom.conf -Dlogback.configurationFile=./logback.xml elasticmq-server-0.9.2.jar
21:24:24.999 [main] INFO  org.elasticmq.server.Main$ - Starting ElasticMQ server (0.9.2) ...
21:24:25.253 [elasticmq-akka.actor.default-dispatcher-4] INFO  akka.event.slf4j.Slf4jLogger - Slf4jLogger started
21:24:25.258 [elasticmq-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - logger log1-Slf4jLogger started
21:24:25.261 [elasticmq-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - Default Loggers started
21:24:25.319 [elasticmq-akka.actor.default-dispatcher-3] DEBUG c.t.sslconfig.akka.AkkaSSLConfig - Initializing AkkaSSLConfig extension...
21:24:25.335 [elasticmq-akka.actor.default-dispatcher-3] DEBUG c.t.sslconfig.akka.AkkaSSLConfig - hostnameVerifier: com.typesafe.sslconfig.ssl.DefaultHostnameVerifier@41f69e84
21:24:25.790 [main] INFO  o.e.rest.sqs.TheSQSRestServerBuilder - Started SQS rest server, bind address 0.0.0.0:9324, visible server address * (depends on incoming request path)
21:24:25.802 [elasticmq-akka.actor.default-dispatcher-4] DEBUG akka.io.TcpListener - Successfully bound to /0:0:0:0:0:0:0:0:9324
21:24:25.852 [elasticmq-akka.actor.default-dispatcher-4] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue QueueData(elasticsearch_index,MillisVisibilityTimeout(30000),PT0S,PT0S,2016-04-12T21:24:25.815-07:00,2016-04-12T21:24:25.841-07:00)
21:24:25.854 [elasticmq-akka.actor.default-dispatcher-4] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue QueueData(test-123,MillisVisibilityTimeout(30000),PT0S,PT0S,2016-04-12T21:24:25.842-07:00,2016-04-12T21:24:25.842-07:00)
21:24:25.855 [main] INFO  org.elasticmq.server.Main$ - === ElasticMQ server (0.9.2) started in 1114 ms ===
21:24:33.311 [elasticmq-akka.actor.default-dispatcher-2] DEBUG akka.io.TcpListener - New connection accepted
21:24:33.545 [elasticmq-akka.actor.default-dispatcher-2] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
21:24:33.550 [elasticmq-akka.actor.default-dispatcher-2] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
21:24:33.559 [elasticmq-akka.actor.default-dispatcher-4] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Sent message with id eb7a65d1-d013-4c51-a712-b8cd784a6653
21:24:33.560 [elasticmq-akka.actor.default-dispatcher-4] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Sent message with id bcf19d46-6e55-4480-8d4d-e22fbd20dead

As you see, there is one "New connection accepted" and then it looks like two actors end up handling it

slobo commented 8 years ago

(sorry if spamming, for convenience here is the log with elasticmq.debug = true)

➤ java -jar -Dconfig.file=custom.conf -Dlogback.configurationFile=./logback.xml elasticmq-server-0.9.2.jar
21:27:05.130 [main] INFO  org.elasticmq.server.Main$ - Starting ElasticMQ server (0.9.2) ...
21:27:05.384 [elasticmq-akka.actor.default-dispatcher-4] INFO  akka.event.slf4j.Slf4jLogger - Slf4jLogger started
21:27:05.391 [elasticmq-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - logger log1-Slf4jLogger started
21:27:05.394 [elasticmq-akka.actor.default-dispatcher-4] DEBUG akka.event.EventStream - Default Loggers started
21:27:05.452 [elasticmq-akka.actor.default-dispatcher-3] DEBUG c.t.sslconfig.akka.AkkaSSLConfig - Initializing AkkaSSLConfig extension...
21:27:05.467 [elasticmq-akka.actor.default-dispatcher-3] DEBUG c.t.sslconfig.akka.AkkaSSLConfig - hostnameVerifier: com.typesafe.sslconfig.ssl.DefaultHostnameVerifier@41f69e84
21:27:05.918 [main] INFO  o.e.rest.sqs.TheSQSRestServerBuilder - Started SQS rest server, bind address 0.0.0.0:9324, visible server address * (depends on incoming request path)
21:27:05.930 [elasticmq-akka.actor.default-dispatcher-4] DEBUG akka.io.TcpListener - Successfully bound to /0:0:0:0:0:0:0:0:9324
21:27:05.979 [elasticmq-akka.actor.default-dispatcher-4] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue QueueData(elasticsearch_index,MillisVisibilityTimeout(30000),PT0S,PT0S,2016-04-12T21:27:05.943-07:00,2016-04-12T21:27:05.968-07:00)
21:27:05.981 [elasticmq-akka.actor.default-dispatcher-4] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue QueueData(test-123,MillisVisibilityTimeout(30000),PT0S,PT0S,2016-04-12T21:27:05.969-07:00,2016-04-12T21:27:05.969-07:00)
21:27:05.982 [main] INFO  org.elasticmq.server.Main$ - === ElasticMQ server (0.9.2) started in 1114 ms ===
21:27:14.432 [elasticmq-akka.actor.default-dispatcher-3] DEBUG akka.io.TcpListener - New connection accepted
21:27:14.668 [elasticmq-akka.actor.default-dispatcher-3] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
21:27:14.675 [elasticmq-akka.actor.default-dispatcher-3] DEBUG o.elasticmq.actor.QueueManagerActor - Looking up queue test-123, found?: true
21:27:14.683 [elasticmq-akka.actor.default-dispatcher-4] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Sent message with id dc414b5e-ef7c-4794-9b22-5a64006b0066
21:27:14.684 [elasticmq-akka.actor.default-dispatcher-4] DEBUG org.elasticmq.actor.queue.QueueActor - test-123: Sent message with id 225e73c2-5e74-473d-b7f9-b80c57c83fc5
21:27:14.727 [elasticmq-akka.actor.default-dispatcher-3] DEBUG akka.actor.ActorSystemImpl - Response for
  Request : HttpRequest(HttpMethod(POST),http://localhost:9324/queue/test-123,List(Host: localhost:9324, Accept: */*, aws-sdk-invocation-id: cde964dbc58b36399d4937f448f0f0a5, aws-sdk-retry: 0/0, X-Amz-Date: 20160413T040326Z, authorization: AWS4-HMAC-SHA256 Credential=dummy_aws_access_key/20160413/us-east-1/sqs/aws4_request, SignedHeaders=aws-sdk-invocation-id;aws-sdk-retry;host;x-amz-date, Signature=884868bd3a224fbeed486a525562f2d7b796abce4cbd1e9bfa51da33f3bb68cf, User-Agent: aws-sdk-php/3.17.5 GuzzleHttp/6.2.0 curl/7.47.0 PHP/5.6.19),HttpEntity.Strict(application/x-www-form-urlencoded; charset=UTF-8,Action=SendMessage&Version=2012-11-05&MessageBody=hello%20world%20570dc50e47f4a&QueueUrl=http%3A%2F%2Flocalhost%3A9324%2Fqueue%2Ftest-123),HttpProtocol(HTTP/1.1))
  Response: Complete(HttpResponse(200 OK,List(),HttpEntity.Strict(text/plain; charset=UTF-8,<SendMessageResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/">
              <SendMessageResult>
                <MD5OfMessageAttributes>d41d8cd98f00b204e9800998ecf8427e</MD5OfMessageAttributes>
                <MD5OfMessageBody>01136811270b2ce017e41c3ee2e42d2d</MD5OfMessageBody>
                <MessageId>225e73c2-5e74-473d-b7f9-b80c57c83fc5</MessageId>
              </SendMessageResult>
              <ResponseMetadata>
                <RequestId>00000000-0000-0000-0000-000000000000</RequestId>
              </ResponseMetadata>
            </SendMessageResponse>),HttpProtocol(HTTP/1.1)))
adamw commented 8 years ago

0.9.3 released The problem was due to multiple sources of the queue name - here both in the URL and in the query parameters. This combined with eager evaluation of code which handled all three cases lead to duplicate messages. Now the evaluation is lazy and the problem should be fixed :)

Thanks for reporting!

slobo commented 8 years ago

wow, thanks for resolving it so quickly!