elasticmq
elasticmq copied to clipboard
softwaremill
Binding failed
Error Message
Binding failed. Switch on DEBUG-level logging for `akka.io.TcpListener` to log the cause
Stacktrace
java.lang.RuntimeException: Binding failed. Switch on DEBUG-level logging for `akka.io.TcpListener` to log the cause.
at spray.routing.SimpleRoutingApp$$anonfun$startServer$1.apply(SimpleRoutingApp.scala:68)
at spray.routing.SimpleRoutingApp$$anonfun$startServer$1.apply(SimpleRoutingApp.scala:63)
at scala.concurrent.Future$$anonfun$flatMap$1.apply(Future.scala:251)
at scala.concurrent.Future$$anonfun$flatMap$1.apply(Future.scala:249)
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)
at akka.dispatch.BatchingExecutor$Batch$$anonfun$run$1.processBatch$1(BatchingExecutor.scala:67)
at akka.dispatch.BatchingExecutor$Batch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:82)
at akka.dispatch.BatchingExecutor$Batch$$anonfun$run$1.apply(BatchingExecutor.scala:59)
at akka.dispatch.BatchingExecutor$Batch$$anonfun$run$1.apply(BatchingExecutor.scala:59)
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72)
at akka.dispatch.BatchingExecutor$Batch.run(BatchingExecutor.scala:58)
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:41)
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:401)
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
Standard Output
329453 main INFO org.elasticmq.rest.sqs.TheSQSRestServerBuilder Started SQS rest server, bind address localhost:56781, visible server address http://localhost:9324
[WARN] [10/07/2015 19:13:31.265] [elasticmq-akka.actor.default-dispatcher-2] [akka://elasticmq/user/IO-HTTP/listener-0] Bind to localhost/127.0.0.1:56781 failed, timeout 1 second expired
[INFO] [10/07/2015 19:13:31.298] [elasticmq-akka.actor.default-dispatcher-4] [akka://elasticmq/user/IO-HTTP/listener-0] Message [akka.io.Tcp$Bound] from Actor[akka://elasticmq/system/IO-TCP/selectors/$a/0#-260055602] to Actor[akka://elasticmq/user/IO-HTTP/listener-0#-1846361151] was not delivered. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
Yes, 56781 and 9324 should be free. This behavior is a bit inconsistent. Most of the time it is successful.
It would be good to have some more logging :) Can you try running the server with -Dlogback.configurationFile=custom.xml where custom.xml is sth like this:
<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.apache.http" level="INFO"/>
<logger name="org.elasticmq" level="DEBUG"/>
<logger name="akka.io" level="DEBUG"/>
<root level="DEBUG">
<appender-ref ref="STDOUT" />
</root>
</configuration>
Ok, I've added the debug logging but it doesn't seem to add any more logging when the errors occur.
I'm also seeing this error. I either get the first error or this one. I have not seen both happen at the same time.
Error Message
Ask timed out on [Actor[akka://elasticmq/user/IO-HTTP#973654889]] after [10000 ms]
Stacktrace
akka.pattern.AskTimeoutException: Ask timed out on [Actor[akka://elasticmq/user/IO-HTTP#973654889]] after [10000 ms]
at akka.pattern.PromiseActorRef$$anonfun$1.apply$mcV$sp(AskSupport.scala:335)
at akka.actor.Scheduler$$anon$7.run(Scheduler.scala:117)
at scala.concurrent.Future$InternalCallbackExecutor$.unbatchedExecute(Future.scala:599)
at scala.concurrent.BatchingExecutor$class.execute(BatchingExecutor.scala:109)
at scala.concurrent.Future$InternalCallbackExecutor$.execute(Future.scala:597)
at akka.actor.LightArrayRevolverScheduler$TaskHolder.executeTask(Scheduler.scala:467)
at akka.actor.LightArrayRevolverScheduler$$anon$8.executeBucket$1(Scheduler.scala:419)
at akka.actor.LightArrayRevolverScheduler$$anon$8.nextTick(Scheduler.scala:423)
at akka.actor.LightArrayRevolverScheduler$$anon$8.run(Scheduler.scala:375)
at java.lang.Thread.run(Thread.java:745)
Standard Output
305787 main INFO org.elasticmq.rest.sqs.TheSQSRestServerBuilder Started SQS rest server, bind address localhost:56781, visible server address http://localhost:9324
I was also using v0.8.8. I will update to the latest and see if failures still occur.
Update: they still occur with v0.8.12
10s waiting for bind to complete is quite a long time ... is this happening when you frequently start/stop the server? Though the port should be freed quickly after being released I guess
We are using elasticmq for testing our service's features that depend on an AmazonSQS Queue. Our tests logic basically boils down to this:
- start an elasticmq SQS server
- create a queue
- run test
- put stuff in queue
- validate the application pick up sqs message
- validate expected app state
- clear messages in queue (we don't want one test's messages leaking over to other tests)
- delete the sqs queue
- stop elasticmq sqs server
Our current test suite only starts/stops one SQS server once per run of the test suite. The only thing that I think could cause a problem is if the SQS server is not shutdown correctly.
The following snippets are the logs of after shutting down the server and the implementation of the test suite. Do you see any implementation issues?
304324 elasticmq-akka.actor.default-dispatcher-2 DEBUG org.elasticmq.actor.QueueManagerActor Looking up queue test, found?: true
304325 elasticmq-akka.actor.default-dispatcher-6 INFO org.elasticmq.actor.QueueManagerActor Deleting queue test
[INFO] [10/13/2015 11:42:13.062] [elasticmq-akka.actor.default-dispatcher-2] [akka://elasticmq/user/IO-HTTP/listener-0] Unbound from localhost/127.0.0.1:56781
304375 elasticmq-akka.actor.default-dispatcher-7 ERROR org.elasticmq.rest.sqs.TheSQSRestServerBuilder$$anon$1 Exception when running routes
akka.pattern.AskTimeoutException: Ask timed out on [Actor[akka://elasticmq/user/$a/$a#-1828738721]] after [21000 ms]
at akka.pattern.PromiseActorRef$$anonfun$1.apply$mcV$sp(AskSupport.scala:334) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.Scheduler$$anon$7.run(Scheduler.scala:117) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.LightArrayRevolverScheduler$TaskHolder.run(Scheduler.scala:476) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.LightArrayRevolverScheduler$$anonfun$close$1.apply(Scheduler.scala:282) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.LightArrayRevolverScheduler$$anonfun$close$1.apply(Scheduler.scala:281) ~[akka-actor_2.11-2.3.12.jar:na]
at scala.collection.Iterator$class.foreach(Iterator.scala:742) ~[scala-library-2.11.7.jar:na]
at scala.collection.AbstractIterator.foreach(Iterator.scala:1194) ~[scala-library-2.11.7.jar:na]
at scala.collection.IterableLike$class.foreach(IterableLike.scala:72) ~[scala-library-2.11.7.jar:na]
at scala.collection.AbstractIterable.foreach(Iterable.scala:54) ~[scala-library-2.11.7.jar:na]
at akka.actor.LightArrayRevolverScheduler.close(Scheduler.scala:280) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl.stopScheduler(ActorSystem.scala:689) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$$anonfun$liftedTree2$1$1.apply$mcV$sp(ActorSystem.scala:618) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$$anonfun$liftedTree2$1$1.apply(ActorSystem.scala:618) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$$anonfun$liftedTree2$1$1.apply(ActorSystem.scala:618) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$$anon$3.run(ActorSystem.scala:642) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$run$1.runNext$1(ActorSystem.scala:809) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$run$1.apply$mcV$sp(ActorSystem.scala:812) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$run$1.apply(ActorSystem.scala:805) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$run$1.apply(ActorSystem.scala:805) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.util.ReentrantGuard.withGuard(LockUtil.scala:15) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$TerminationCallbacks.run(ActorSystem.scala:805) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$$anonfun$terminationCallbacks$1.apply(ActorSystem.scala:639) ~[akka-actor_2.11-2.3.12.jar:na]
at akka.actor.ActorSystemImpl$$anonfun$terminationCallbacks$1.apply(ActorSystem.scala:639) ~[akka-actor_2.11-2.3.12.jar:na]
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.7.jar:na]
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55) [akka-actor_2.11-2.3.12.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:91) [akka-actor_2.11-2.3.12.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91) [akka-actor_2.11-2.3.12.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91) [akka-actor_2.11-2.3.12.jar:na]
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72) [scala-library-2.11.7.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90) [akka-actor_2.11-2.3.12.jar:na]
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40) [akka-actor_2.11-2.3.12.jar:na]
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397) [akka-actor_2.11-2.3.12.jar:na]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.7.jar:na]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.7.jar:na]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.7.jar:na]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.7.jar:na]
public abstract class TestBase extends Base {
private SQSRestServer sqsRestServer;
@BeforeClass
public void beforeClass()
throws Exception {
startSQS();
}
@AfterMethod
public void afterMethod()
throws Exception {
clearSQS();
}
@AfterClass
public void afterClass()
throws Exception {
stopSQS();
}
private void startSQS() {
sqsRestServer = SQSRestServerBuilder.withPort(TestEnvironment.getSqsPort().get()).withInterface(TestEnvironment.getSqsHost().get()).start();
sqsRestServer.waitUntilStarted();
getAmazonSQS().createQueue(new CreateQueueRequest(TestEnvironment.getSqsName().get())
.withAttributes(ImmutableMap.of("VisibilityTimeout", Integer.toString(getConfiguration().getEtlConfiguration().getReceiveVisibilityTimeoutSeconds()))));
}
private void clearSQS() {
final long START_TIME = System.currentTimeMillis();
final long MIN_TIME = getConfiguration().getEtlConfiguration().getReceiveVisibilityTimeoutSeconds();
// Poll for at least a certain amount of time and keep polling if there are still messages in the queue
final Set<Message> messages = Sets.newHashSet();
while (!receiveMessage().getMessages().isEmpty() && (System.currentTimeMillis() - START_TIME) < MIN_TIME) {
messages.addAll(receiveMessage().getMessages());
}
// Delete all messages found in the queue
for (final Message message : messages) {
getAmazonSQS().deleteMessage(
getConfiguration().getAwsConfiguration().getQueueURL(),
message.getReceiptHandle());
}
}
private void stopSQS() {
getAmazonSQS().deleteQueue(getConfiguration().getAwsConfiguration().getQueueURL());
sqsRestServer.stopAndWait();
}
protected SendMessageResult sendMessage(final String body) {
return getAmazonSQS().sendMessage(
getConfiguration().getAwsConfiguration().getQueueURL(),
getGson().toJson(ImmutableMap.of("Message", body)));
}
protected ReceiveMessageResult receiveMessage() {
return getAmazonSQS().receiveMessage(getConfiguration().getAwsConfiguration().getQueueURL());
}
}
Yeah that looks correct ... btw there's a PurgeQueue method to remove all messages from a queue. I don't really have any ideas about the causes
Could you check 0.9.0-beta1? (https://s3-eu-west-1.amazonaws.com/softwaremill-public/elasticmq-server-0.9.0-beta1.jar) It uses a new HTTP backend so maybe something will change here.
Would be nice if there was a solution, I'm getting what appears the same on 0.14.
Seeing this as well, I think the server started by one test does not get shut down properly and then a later test that tries to create a new one gets Bind failed because of java.net.BindException: Address already in use
I noticed the tests in the repo mention something similar: TODO: Figure out why this intermittently isn't able to unbind cleanly
https://github.com/softwaremill/elasticmq/blob/master/rest/rest-sqs-testing-amazon-java-sdk/src/test/scala/org/elasticmq/rest/sqs/AmazonJavaSdkTestSuite.scala#L87
I do not know if its related, or if I should open another bug, but the symptoms is kind of the same, so will try here first.
But I also sometimes get an error when starting it. But for me it is related to the Mbean:
javax.management.InstanceAlreadyExistsException: org.elasticmq:name=Queues
at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
at org.elasticmq.rest.sqs.TheSQSRestServerBuilder.start(SQSRestServerBuilder.scala:246)
Looks like it happens in tests, where the server is booted up, and shutdown multiple times. I have for now worked around it, by catching the exception, waiting a second and then try again.
