Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Binding failed #61

Open
arnm opened this issue Oct 7, 2015 · 19 comments
Open

Binding failed #61

arnm opened this issue Oct 7, 2015 · 19 comments

Comments

@arnm
Copy link

arnm commented Oct 7, 2015

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
Copy link
Member

adamw commented Oct 7, 2015

I assume that port is free?

@arnm
Copy link
Author

arnm commented Oct 7, 2015

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

@adamw
Copy link
Member

adamw commented Oct 8, 2015

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
Copy link
Author

arnm commented Oct 12, 2015

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
Copy link
Author

arnm commented Oct 12, 2015

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
Copy link
Member

adamw commented Oct 13, 2015

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
Copy link
Author

arnm commented Oct 13, 2015

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

}

@adamw
Copy link
Member

adamw commented Oct 14, 2015

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
Copy link
Member

adamw commented Oct 27, 2015

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
Copy link

@adamw was this a proven fix for this?

@adamw
Copy link
Member

adamw commented Mar 23, 2016

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

@sverhagen
Copy link

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

@wigbam
Copy link
Contributor

wigbam commented Nov 28, 2018

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

@eheinen
Copy link

eheinen commented Jul 1, 2019

Same problem for 0.14.7 (Embedded ElasticMQ)

@bpoland
Copy link

bpoland commented Jul 16, 2020

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
Copy link

Same problem

@adamw
Copy link
Member

adamw commented Dec 2, 2020

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

@Kreinoee
Copy link

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
Copy link
Member

adamw commented Jan 24, 2022

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants