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.53k stars 193 forks source link

DeleteMessage: Invalid request: UnacceptedResponseContentTypeRejection(Set(ContentType(none/none))) #1027

Closed iGEL closed 2 months ago

iGEL commented 2 months ago

We are using elasticmq (thanks!) for testing and development and are currently in the process to migrate from the java sdk 1.0 to the clojure lib aws-api.

I noticed a new error in development. When trying to delete messages I get a Invalid request: UnacceptedResponseContentTypeRejection(Set(ContentType(none/none))). I wasn't hardly able to find any info about this exception, but as far I can see, it's not an issue with our new client or our usage with it, since the type mentions a ResponseContentType and we don't see this in production against AWS SQS. Other operations like ReceiveMessage are working fine.

I used mitmproxy to analyze the requests. Here the "good" request/response when using the java SDK 1.0 (had to change the port of the queue url to 8080 to send it to mitmproxy):

POST /000000000000/temp-local-dev-notifications.fifo HTTP/1.1
Host: localhost:9324
amz-sdk-invocation-id: 499e9e38-c287-b5f2-e46a-8477052ea3ce
amz-sdk-request: ttl=20240724T095525Z;attempt=1;max=4
amz-sdk-retry: 0/0/500
Authorization: <redacted>
Content-Type: application/x-amz-json-1.0
User-Agent: aws-sdk-java/1.12.722 Linux/6.5.0-44-generic OpenJDK_64-Bit_Server_VM/21.0.2+13-58 java/21.0.2 clojure/1.11.2 kotlin/1.9.10 vendor/Oracle_Corporation cfg/retry-mode/legacy cfg/auth-source#unknown
X-Amz-Date: 20240724T095435Z
X-Amz-Security-Token: <redacted>
X-Amz-Target: AmazonSQS.DeleteMessage
Content-Length: 175
Connection: Keep-Alive

{"QueueUrl":"http://localhost:8080/000000000000/temp-local-dev-notifications.fifo","ReceiptHandle":"ba65d750-fad8-4dd7-accd-b12fe5096067#0db46b72-7758-46e9-9328-16fb43084d7b"}

HTTP/1.1 200 OK
Server: pekko-http/1.0.1
Date: Wed, 24 Jul 2024 09:54:34 GMT
Content-Length: 0

Here the "bad" one from aws-api:

POST / HTTP/1.1
Accept-Encoding: gzip
User-Agent: Jetty/<redacted>
x-amz-date: 20240724T080725Z
x-amz-target: AmazonSQS.DeleteMessage
Content-Type: application/x-amz-json-1.0
Accept: application/json
Host: localhost:9324
x-amz-security-token: <redacted>
Authorization: <redacted>
Content-Length: 179

{"QueueUrl":"http:\/\/localhost:9324\/000000000000\/temp-local-dev-notifications.fifo","ReceiptHandle":"db79207f-af2f-4185-868c-177fdfbcea8a#f8f32507-1764-49d5-b209-5566bc9921cc"}

HTTP/1.1 400 Bad Request
Server: pekko-http/1.0.1
Date: Wed, 24 Jul 2024 08:07:25 GMT
Content-Type: application/json
Content-Length: 141

{"Message":"Invalid request: UnacceptedResponseContentTypeRejection(Set(ContentType(none/none)))","__type":"com.amazonaws.sqs#InvalidAction"}
micossow commented 2 months ago

@iGEL which version of ElasticMQ are you using? Can you include the logs from the ElasticMQ server when running the "bad" request?

iGEL commented 2 months ago

@micossow, thank you for your response.

I'm running 1.6.1, here the logs (but I didn't see anything happening when I made the request):

08:51:07.466 [main] INFO  org.elasticmq.server.Main$ - Starting ElasticMQ server (1.6.1) ...
08:51:07.482 [elasticmq-pekko.actor.default-dispatcher-6] INFO  o.a.pekko.event.slf4j.Slf4jLogger - Slf4jLogger started
08:51:07.482 [elasticmq-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.event.EventStream - logger log1-Slf4jLogger started
08:51:07.482 [elasticmq-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.event.EventStream - Default Loggers started
08:51:07.488 [main] INFO  o.e.rest.sqs.TheSQSRestServerBuilder - Metrics MBean org.elasticmq:name=Queues successfully registered
08:51:07.488 [elasticmq-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.io.TcpListener - Successfully bound to /0:0:0:0:0:0:0:0:9324
08:51:07.488 [elasticmq-pekko.actor.default-dispatcher-7] INFO  o.e.rest.sqs.TheSQSRestServerBuilder - Started SQS rest server, bind address 0.0.0.0:9324, visible server address http://localhost:9324
08:51:07.489 [elasticmq-pekko.actor.default-dispatcher-7] DEBUG org.apache.pekko.io.TcpListener - Successfully bound to /0:0:0:0:0:0:0:0:9325
08:51:07.489 [elasticmq-pekko.actor.default-dispatcher-9] INFO  o.e.r.s.TheStatisticsRestServerBuilder - Started statistics rest server, bind address 0.0.0.0:9325
08:51:07.489 [main] INFO  org.elasticmq.server.Main$ - === ElasticMQ server (1.6.1) started in 28 ms ===
08:51:28.047 [elasticmq-pekko.actor.default-dispatcher-9] DEBUG org.apache.pekko.io.TcpListener - New connection accepted
08:51:28.070 [elasticmq-pekko.actor.default-dispatcher-6] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(temp-local-dev-notifications.fifo,Some(MillisVisibilityTimeout(930000)),None,None,None,None,None,true,false,None,None,Map())
08:51:28.083 [elasticmq-pekko.actor.default-dispatcher-6] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(<redacted>,Some(MillisVisibilityTimeout(180000)),None,None,None,None,None,false,false,None,None,Map())
08:51:28.086 [elasticmq-pekko.actor.default-dispatcher-7] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(<redacted>,Some(MillisVisibilityTimeout(930000)),None,None,None,None,None,true,false,None,None,Map())
08:51:28.090 [elasticmq-pekko.actor.default-dispatcher-7] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(<redacted>,Some(MillisVisibilityTimeout(360000)),None,None,None,None,None,false,false,None,None,Map())
08:51:28.093 [elasticmq-pekko.actor.default-dispatcher-6] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(<redacted>,Some(MillisVisibilityTimeout(930000)),None,None,None,None,None,true,true,None,None,Map())
08:51:28.097 [elasticmq-pekko.actor.default-dispatcher-6] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(<redacted>,Some(MillisVisibilityTimeout(930000)),None,None,None,None,None,true,false,None,None,Map())
08:51:28.101 [elasticmq-pekko.actor.default-dispatcher-7] INFO  o.elasticmq.actor.QueueManagerActor - Creating queue CreateQueueData(<redacted>,Some(MillisVisibilityTimeout(930000)),None,None,None,None,None,true,false,None,None,Map())
08:51:29.530 [elasticmq-pekko.actor.default-dispatcher-10] DEBUG org.apache.pekko.io.TcpListener - New connection accepted
08:51:44.562 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG org.apache.pekko.io.TcpListener - New connection accepted
08:51:44.562 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG org.apache.pekko.io.TcpListener - New connection accepted
08:51:47.574 [elasticmq-pekko.actor.default-dispatcher-19] DEBUG org.apache.pekko.io.TcpListener - New connection accepted
08:51:50.585 [elasticmq-pekko.actor.default-dispatcher-11] DEBUG org.apache.pekko.io.TcpListener - New connection accepted
08:53:00.087 [Thread-1] INFO  org.elasticmq.server.Main$ - ElasticMQ server stopping ...
08:53:00.087 [elasticmq-pekko.actor.default-dispatcher-25] DEBUG org.apache.pekko.io.TcpListener - Unbinding endpoint /0:0:0:0:0:0:0:0:9325
08:53:00.087 [elasticmq-pekko.actor.default-dispatcher-25] DEBUG org.apache.pekko.io.TcpListener - Unbinding endpoint /0:0:0:0:0:0:0:0:9324
08:53:00.087 [elasticmq-pekko.actor.default-dispatcher-20] DEBUG org.apache.pekko.io.TcpListener - Unbound endpoint /0:0:0:0:0:0:0:0:9325, stopping listener
08:53:00.087 [elasticmq-pekko.actor.default-dispatcher-20] DEBUG org.apache.pekko.io.TcpListener - Unbound endpoint /0:0:0:0:0:0:0:0:9324, stopping listener
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] WARN  o.a.pekko.actor.CoordinatedShutdown - Could not addJvmShutdownHook, due to: Shutdown in progress
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] INFO  o.a.pekko.actor.CoordinatedShutdown - Running CoordinatedShutdown with reason [ActorSystemTerminateReason]
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [before-service-unbind] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [service-unbind] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [service-requests-done] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [service-stop] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [before-cluster-shutdown] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [cluster-sharding-shutdown-region] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [cluster-leave] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [cluster-exiting] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [cluster-exiting-done] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [cluster-shutdown] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [before-actor-system-terminate] with [0] tasks
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing phase [actor-system-terminate] with [1] tasks.
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-15] DEBUG o.a.pekko.actor.CoordinatedShutdown - Performing task [terminate-system] in CoordinatedShutdown phase [actor-system-terminate]
08:53:00.088 [elasticmq-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.event.EventStream - shutting down: StandardOutLogger
08:53:00.092 [Thread-1] INFO  org.elasticmq.server.Main$ - === ElasticMQ server stopped ===

I also tried with 1.6.5, but I'm getting the same error.

micossow commented 2 months ago

The issue was due to presence of Accept header in the request which Java SDK doesn't do. It should be fixed in v1.6.6 that should be available in ~1 hour.

iGEL commented 2 months ago

Awesome, thank you!