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

Binding failed #61

Open arnm opened 8 years ago

arnm commented 8 years ago
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'.
adamw commented 8 years ago

I assume that port is free?

arnm commented 8 years ago

Yes, 56781 and 9324 should be free. This behavior is a bit inconsistent. Most of the time it is successful.

adamw commented 8 years ago

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>
arnm commented 8 years ago

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
arnm commented 8 years ago

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

adamw commented 8 years ago

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

arnm commented 8 years ago

We are using elasticmq for testing our service's features that depend on an AmazonSQS Queue. Our tests logic basically boils down to this:

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());
    }

}
adamw commented 8 years ago

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

adamw commented 8 years ago

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.

st9x3st9 commented 8 years ago

@adamw was this a proven fix for this?

adamw commented 8 years ago

@st9x3st9 Are you still seeing this also with 0.9.0-beta1?

sverhagen commented 5 years ago

Would be nice if there was a solution, I'm getting what appears the same on 0.14.

wigbam commented 5 years ago

Does anybody know of a solution for this? Running on 0.14.6

eheinen commented 5 years ago

Same problem for 0.14.7 (Embedded ElasticMQ)

bpoland commented 4 years ago

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

pliuchkin commented 3 years ago

Same problem

adamw commented 3 years ago

@pliuchkin which version, and how are you exactly starting elasticmq?

Kreinoee commented 2 years ago

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.

adamw commented 2 years ago

@Kreinoee I think that's a separate issue, so please open a new one :)