Container fails to start; no useful error reported

michael-s-grant commented 8 years ago

Hi. I'm much attracted to your way of running Docker containers; it's elegant, and vastly simpler than the equivalent in Java which I have to hand. The only problem is that it doesn't work, for me. The test example I've reduced my code to is so simple that I suspect the error may be in your code, not mine.

Here's my code, which I'm running with Scala 2.11.8 on a Mac running El Capitan:

import com.whisk.docker.{DockerContainer, DockerKit, DockerReadyChecker}

import scala.concurrent.duration._

trait KafkaDockerContainer extends DockerKit {
  override val StartContainersTimeout = 20.seconds // Was 60.seconds
  val KafkaAdvertisedHost = "192.168.99.100"
  val KafkaAdvertisedPort = 9092
  val ZookeeperDefaultPort = 2181

  lazy val kafkaContainer = DockerContainer("spotify/kafka")
    .withPorts(
      KafkaAdvertisedPort -> Some(KafkaAdvertisedPort),
      ZookeeperDefaultPort -> Some(ZookeeperDefaultPort))
    .withEnv(
      s"ADVERTISED_PORT=$KafkaAdvertisedPort",
      s"ADVERTISED_HOST=$KafkaAdvertisedHost")
    .withReadyChecker(DockerReadyChecker.LogLineContains("kafka entered RUNNING state"))

  abstract override def dockerContainers: List[DockerContainer] =
    kafkaContainer :: super.dockerContainers
}

I was using 0.8.3 of your code, but upgrading to 0.9.0-M5 also reproduces the problem.

Running docker run spotify/kafka at the command line shows the container does start, and the expected string is produced; however running the above Scala results in:

Exception in thread "main" java.lang.RuntimeException: Cannot run all required containers at com.whisk.docker.DockerKit$class.startAllOrFail(DockerKit.scala:61)

with no further explanation.

Setting logging to debug gives me, inter alia the following, which hasn't particularly shed light for me:

v14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG o.a.h.impl.execchain.MainClientExec - Executing request GET /containers/6de0e43452a10b117f3ed713dcad961b436a9185bb497f4b915318c8b071480c/logs?stdout=true&stderr=true&follow=true HTTP/1.1 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG o.a.h.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG o.a.h.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 >> GET /containers/6de0e43452a10b117f3ed713dcad961b436a9185bb497f4b915318c8b071480c/logs?stdout=true&stderr=true&follow=true HTTP/1.1 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 >> User-Agent: Jersey/2.23.1 (Apache HttpClient 4.5) 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 >> Host: 192.168.99.100:2376 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 >> Connection: Keep-Alive 14:25:58.427 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 >> Accept-Encoding: gzip,deflate 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 >> "GET /containers/6de0e43452a10b117f3ed713dcad961b436a9185bb497f4b915318c8b071480c/logs?stdout=true&stderr=true&follow=true HTTP/1.1[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 >> "User-Agent: Jersey/2.23.1 (Apache HttpClient 4.5)[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 >> "Host: 192.168.99.100:2376[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 >> "Accept-Encoding: gzip,deflate[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 >> "[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "HTTP/1.1 200 OK[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "Server: Docker/1.12.0 (linux)[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "Date: Fri, 26 Aug 2016 12:25:58 GMT[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "Content-Type: text/plain; charset=utf-8[\r][\n]" 14:25:58.428 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "Transfer-Encoding: chunked[\r][\n]" 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "[\r][\n]" 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 << HTTP/1.1 200 OK 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 << Server: Docker/1.12.0 (linux) 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 << Date: Fri, 26 Aug 2016 12:25:58 GMT 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 << Content-Type: text/plain; charset=utf-8 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.headers - http-outgoing-4 << Transfer-Encoding: chunked 14:25:58.429 [dockerjava-jaxrs-async-0] DEBUG o.a.h.impl.execchain.MainClientExec - Connection can be kept alive indefinitely 14:25:58.430 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "0[\r][\n]" 14:25:58.430 [dockerjava-jaxrs-async-0] DEBUG org.apache.http.wire - http-outgoing-4 << "[\r][\n]" 14:25:58.430 [dockerjava-jaxrs-async-0] DEBUG c.g.d.j.JerseyDockerCmdExecFactory$1 - Connection [id: 4][route: {s}->https://192.168.99.100:2376][state: O="michael."] can be kept alive indefinitely 14:25:58.430 [dockerjava-jaxrs-async-0] DEBUG c.g.d.j.JerseyDockerCmdExecFactory$1 - Connection released: [id: 4][route: {s}->https://192.168.99.100:2376][state: O="michael."][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20] 14:25:58.430 [dockerjava-jaxrs-async-0] DEBUG c.g.d.j.JerseyDockerCmdExecFactory - 9 * Client response received on thread dockerjava-jaxrs-async-0 9 < 200 9 < Content-Length: -1 9 < Content-Type: application/json;charset=utf-8 9 < Date: Fri, 26 Aug 2016 12:25:58 GMT 9 < Server: Docker/1.12.0 (linux) 9 < Transfer-Encoding: chunked

14:26:18.246 [main] ERROR test.AsyncBootstrapper$ - Exception during container initialization java.util.concurrent.TimeoutException: Futures timed out after [20 seconds] at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219) ~[scala-library-2.11.8.jar:na] at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:223) ~[scala-library-2.11.8.jar:na] at scala.concurrent.Await$$anonfun$result$1.apply(package.scala:190) ~[scala-library-2.11.8.jar:na] at scala.concurrent.BlockContext$DefaultBlockContext$.blockOn(BlockContext.scala:53) ~[scala-library-2.11.8.jar:na] at scala.concurrent.Await$.result(package.scala:190) ~[scala-library-2.11.8.jar:na] at com.whisk.docker.DockerKit$class.startAllOrFail(DockerKit.scala:53) ~[docker-testkit-core_2.11-0.9.0-M5-michael.jar:0.9.0-M5-michael]

...following which there is a DELETE request to https://192.168.99.100:2376/containers/6de0e43452a10b117f3ed713dcad961b436a9185bb497f4b915318c8b071480c?v=true&force=true and the nascent container is then deleted.

By chance, #48 appeared whilst I was in the middle of getting very confused trying to step-debug the code, so I tried including .withLogLineReceiver (LogLineReceiver (true, (s : String) => println ("*** " + s) )), with a version of your code with the changes from that PR included, to examine the container log, but nothing turned up.

Having now exhausted my ideas, and, so Google would suggest, also the wider Internet's prior experience, can I turn this over to you to investigate, please?

viktortnk commented 7 years ago

Looks like you are using docker-java implementation on MacOS. Sorry, I have different environment setup these days. I'd recommend trying Spotify-based executor, at very least in that case I might be able to reproduce your steps

akauppi commented 7 years ago

@michael-s-grant Hi, are you still having this problem?

I've got an environment similar to yours, and can maybe help. One thing that caught my eye is the val KafkaAdvertisedHost = "192.168.99.100". With macOS and docker-machine, this is often so but not necessarily always.

What do you get with:

$ docker-machine ip
192.168.99.100

michael-s-grant commented 7 years ago

@akauppi Thanks for your feedback. In response to your first question, since we needed something working back in October, I implemented a considerably more verbose and less elegant solution in Java instead. Now, we're moving towards getting Maven to run Docker containers for our system tests rather than have them started by the tests themselves, so we're less likely to be in this situation again; but it would still be good to know how to solve this problem, just in case.

And in response to your second question, the docker-machine is 192.168.99.100, in my case (though the command you suggested gives me an error "Error getting IP address: Something went wrong running an SSH command!", but this is demonstrably not critical as everything else I do to access the machine via this address, including the abovementioned Java workaround, works fine).

mdotson commented 7 years ago

@michael-s-grant I think it'd be better for you to move your example to a real test that we can just copy and paste in. The example is incomplete, since you don't have zookeeper at all, and the container will certainly die given that it can't register with zookeeper. You may have zookeeper running from outside via docker run, but it's still much easier to reproduce given a full test.

viktortnk commented 7 years ago

I've just made working example for Kafka. https://github.com/viktortnk/docker-testkit-examples Closing as there is no activity in this thread

whisklabs / docker-it-scala

Container fails to start; no useful error reported #49