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.

Sign up for GitHub

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

Jump to bottom

DockerContrainer socat ambassador times out sporadically when no service exposed #1327

Closed
ftardif opened this issue Mar 19, 2019 · 1 comment · Fixed by #1328
Closed

DockerContrainer socat ambassador times out sporadically when no service exposed #1327

ftardif opened this issue Mar 19, 2019 · 1 comment · Fixed by #1328
Labels
resolution/awaiting-release
Milestone
1.11.0

Comments

@ftardif
Copy link
Contributor

ftardif commented Mar 19, 2019 •
edited

We are getting randomly timeout exception on the socatAmbassadorContainer internally managed by the DockerComposeContainer

java.lang.ExceptionInInitializerError at com.bell.cts.fonse.epg.sports.connector.cron.EpgSportsConnectorContextIT.<clinit>(EpgSportsConnectorContextIT.java:24) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at org.junit.runners.BlockJUnit4ClassRunner.createTest(BlockJUnit4ClassRunner.java:217) at org.junit.runners.BlockJUnit4ClassRunner$1.runReflectiveCall(BlockJUnit4ClassRunner.java:266) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.BlockJUnit4ClassRunner.methodBlock(BlockJUnit4ClassRunner.java:263) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:369) at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:275) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:239) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:160) at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:373) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:334) at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:119) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:407) Caused by: java.lang.IllegalStateException: org.testcontainers.containers.ContainerLaunchException: Container startup failed at com.bell.cts.commons.kafka.docker.BootstrappedDockerKafkaCluster.<clinit>(BootstrappedDockerKafkaCluster.java:16) ... 25 more Caused by: org.testcontainers.containers.ContainerLaunchException: Container startup failed at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:221) at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:203) at org.testcontainers.containers.DockerComposeContainer.startAmbassadorContainers(DockerComposeContainer.java:242) at org.testcontainers.containers.DockerComposeContainer.start(DockerComposeContainer.java:153) at com.bell.cts.commons.kafka.docker.DockerKafkaCluster.start(DockerKafkaCluster.java:61) at com.bell.cts.commons.kafka.docker.BootstrappedDockerKafkaCluster.<clinit>(BootstrappedDockerKafkaCluster.java:14) ... 25 more Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:83) at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:214) ... 30 more Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:286) at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:216) at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:76) ... 31 more Caused by: org.rnorth.ducttape.TimeoutException: Timeout waiting for result with exception at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:51) at org.rnorth.ducttape.unreliables.Unreliables.retryUntilTrue(Unreliables.java:95) at org.testcontainers.containers.startupcheck.StartupCheckStrategy.waitUntilStartupSuccessful(StartupCheckStrategy.java:26) at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:257) ... 33 more Caused by: java.lang.RuntimeException: Not ready yet at org.rnorth.ducttape.unreliables.Unreliables.lambda$retryUntilTrue$1(Unreliables.java:97) at org.rnorth.ducttape.unreliables.Unreliables.lambda$retryUntilSuccess$0(Unreliables.java:41) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)

The root cause is:
DockerComposeContainer#start() sporadically fails on the ambassadorSocatContainer starts when no withExposedServices has not been explicitly configured.

When looking at the docker deamon logs in debug, the problem is not that it takes more than 30s to start the socat ambassador container (default 30s from StartupCheckStrategy), but it is rather that the socat ambasador container already died because there was no port mapping registered for the ambassador through the withExposedService method!

I believe the fix should be to start the socat ambassador only if portMapping have been registered.

Note below that the socat container (without portMapping) is closed before the first GET http call from the StartupCheckStrategy
`
time="2019-03-18T20:48:19.591496847Z" level=debug msg="Calling POST /containers/create?name=testcontainers-socat-DUeN5bBT"
time="2019-03-18T20:48:19.591604222Z" level=debug msg="form data: {"Cmd":["-c",""],"Entrypoint":["/bin/sh"],"Env":[],"ExposedPorts":{},"HostConfig":{"Binds":[],"ExtraHosts":[],"Links":[],"PortBindings":{},"PublishAllPorts":true,"VolumesFrom":[]},"Image":"alpine/socat:latest","Labels":{"org.testcontainers":"true","org.testcontainers.sessionId":"3e63a3cb-35ff-4b5b-9b82-40bfc52b7147"},"Volumes":{},"name":"testcontainers-socat-DUeN5bBT"}"
time="2019-03-18T20:48:19.639222207Z" level=debug msg="Assigning addresses for endpoint testcontainers-socat-DUeN5bBT's interface on network bridge"
time="2019-03-18T20:48:19.641108935Z" level=debug msg="Assigning addresses for endpoint testcontainers-socat-DUeN5bBT's interface on network bridge"
time="2019-03-18T20:48:19.643450461Z" level=debug msg="Programming external connectivity on endpoint testcontainers-socat-DUeN5bBT (10b7e60bbd23e68039edda3fd05ff0cbd7279c5ad062b8536458e42c1f7549f0)"
time="2019-03-18T20:48:19.970708698Z" level=debug msg="Revoking external connectivity on endpoint testcontainers-socat-DUeN5bBT (10b7e60bbd23e68039edda3fd05ff0cbd7279c5ad062b8536458e42c1f7549f0)"
time="2019-03-18T20:48:20.014019239Z" level=debug msg="Releasing addresses for endpoint testcontainers-socat-DUeN5bBT's interface on network bridge"
~$ less testcontainers-socat.log
~$ grep "socat|c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25" testcontainers-socat.log
time="2019-03-18T20:48:19.591496847Z" level=debug msg="Calling POST /containers/create?name=testcontainers-socat-DUeN5bBT"
time="2019-03-18T20:48:19.591604222Z" level=debug msg="form data: {"Cmd":["-c",""],"Entrypoint":["/bin/sh"],"Env":[],"ExposedPorts":{},"HostConfig":{"Binds":[],"ExtraHosts":[],"Links":[],"PortBindings":{},"PublishAllPorts":true,"VolumesFrom":[]},"Image":"alpine/socat:latest","Labels":{"org.testcontainers":"true","org.testcontainers.sessionId":"3e63a3cb-35ff-4b5b-9b82-40bfc52b7147"},"Volumes":{},"name":"testcontainers-socat-DUeN5bBT"}"
time="2019-03-18T20:48:19.638143619Z" level=debug msg="Calling POST /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/start"
time="2019-03-18T20:48:19.639222207Z" level=debug msg="Assigning addresses for endpoint testcontainers-socat-DUeN5bBT's interface on network bridge"
time="2019-03-18T20:48:19.641108935Z" level=debug msg="Assigning addresses for endpoint testcontainers-socat-DUeN5bBT's interface on network bridge"
time="2019-03-18T20:48:19.643450461Z" level=debug msg="Programming external connectivity on endpoint testcontainers-socat-DUeN5bBT (10b7e60bbd23e68039edda3fd05ff0cbd7279c5ad062b8536458e42c1f7549f0)"
time="2019-03-18T20:48:19.644005661Z" level=debug msg="EnableService c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25 START"
time="2019-03-18T20:48:19.644019088Z" level=debug msg="EnableService c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25 DONE"
time="2019-03-18T20:48:19.649666530Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/4b6b164604aa146c58b88310bd8595f9f6146d6066ce704a4298272e6a854720/merged
time="2019-03-18T20:48:19.657999864Z" level=info msg="shim containerd-shim started" address="/containerd-shim/moby/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/shim.sock" debug=false pid=12491
time="2019-03-18T20:48:19.796491291Z" level=debug msg="sandbox set key processing took 65.956807ms for container c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25"
time="2019-03-18T20:48:19.902600084Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:19.924491871Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:19.959857514Z" level=info msg="shim reaped" id=c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25
time="2019-03-18T20:48:19.970708698Z" level=debug msg="Revoking external connectivity on endpoint testcontainers-socat-DUeN5bBT (10b7e60bbd23e68039edda3fd05ff0cbd7279c5ad062b8536458e42c1f7549f0)"
time="2019-03-18T20:48:20.014019239Z" level=debug msg="Releasing addresses for endpoint testcontainers-socat-DUeN5bBT's interface on network bridge"
time="2019-03-18T20:48:21.061600728Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:22.065671931Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:23.068358927Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:24.071148658Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:25.073734413Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:26.075165363Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:27.077666872Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:28.080023636Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:29.082449418Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:30.085029581Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:31.087780669Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:32.090251115Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:33.092665242Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:34.095263402Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:35.097510650Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:36.100284965Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:37.103051159Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:38.106247318Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:38.322603764Z" level=debug msg="Calling POST /containers/create?name=testcontainers-socat-tw81ZcNj"
time="2019-03-18T20:48:38.322718555Z" level=debug msg="form data: {"Cmd":["-c",""],"Entrypoint":["/bin/sh"],"Env":[],"ExposedPorts":{},"HostConfig":{"Binds":[],"ExtraHosts":[],"Links":[],"PortBindings":{},"PublishAllPorts":true,"VolumesFrom":[]},"Image":"alpine/socat:latest","Labels":{"org.testcontainers":"true","org.testcontainers.sessionId":"9f17bd55-b837-46f6-8de2-028b439e319e"},"Volumes":{},"name":"testcontainers-socat-tw81ZcNj"}"
time="2019-03-18T20:48:38.372890591Z" level=debug msg="Assigning addresses for endpoint testcontainers-socat-tw81ZcNj's interface on network bridge"
time="2019-03-18T20:48:38.374910433Z" level=debug msg="Assigning addresses for endpoint testcontainers-socat-tw81ZcNj's interface on network bridge"
time="2019-03-18T20:48:38.377126021Z" level=debug msg="Programming external connectivity on endpoint testcontainers-socat-tw81ZcNj (528e4c3a03cf74d0d089157d036d29b8b7d08ceecaa87abb242eb5b7442fa8d3)"
time="2019-03-18T20:48:38.668950750Z" level=debug msg="Revoking external connectivity on endpoint testcontainers-socat-tw81ZcNj (528e4c3a03cf74d0d089157d036d29b8b7d08ceecaa87abb242eb5b7442fa8d3)"
time="2019-03-18T20:48:38.708229042Z" level=debug msg="Releasing addresses for endpoint testcontainers-socat-tw81ZcNj's interface on network bridge"
time="2019-03-18T20:48:39.108661944Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:40.111024597Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:41.113940913Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:42.118159930Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:43.120623417Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:44.123226917Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:45.125752674Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:46.129800589Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:47.132107172Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:48.134441548Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:49.137014563Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/json"
time="2019-03-18T20:48:49.922990202Z" level=debug msg="Calling GET /containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25/logs?stdout=true&stderr=true"
time="2019-03-18T20:48:49.923255773Z" level=debug msg="begin logs" container=c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25 method="(*Daemon).ContainerLogs" module=daemon
time="2019-03-18T20:48:49.923276357Z" level=debug msg="end logs ()" container=c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25 method="(*Daemon).ContainerLogs" module=daemon
time="2019-03-18T20:49:00.357986729Z" level=debug msg="Calling DELETE /v1.29/containers/c93cfece0feac9ecd0e5fe3c62ba9d1ad4ca157c7c7ca6768c85d42c6a31cd25?force=1&v=1"

`
@ftardif ftardif mentioned this issue Mar 21, 2019
Merged
@bsideup bsideup mentioned this issue Mar 22, 2019
Closed
@rnorth
Copy link
Member

rnorth commented Mar 22, 2019

Releasing this in 1.11.0 🎉

@bsideup bsideup modified the milestones: next, 1.11.0 Mar 23, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
resolution/awaiting-release
Projects
None yet
Milestone
1.11.0
Development

Successfully merging a pull request may close this issue.

ISSUE-1327 start ambassador only if mapping configured ftardif/testcontainers-java
3 participants
@rnorth @ftardif @bsideup