"Container startup failed" on mac os and private repository

[mateuszjarzyna]

Hi,

I have na issue when I'm pulling image from private repo. This issue happens only when I'm using MacOS, on Linux works fine. I'm also runing tests in Glitlab CI using docker in docker and it works fine.

I'm using Docker Desktop 2.1.0.2 (Engine: 19.03.2, Compose: 1.24.1) and

        <dependency>
            <groupId>org.testcontainers</groupId>
            <artifactId>testcontainers</artifactId>
            <version>1.12.1</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.testcontainers</groupId>
            <artifactId>jdbc</artifactId>
            <version>1.12.1</version>
            <scope>test</scope>
        </dependency>

And the stacktrace

Get https://my-company.com:4567/v2/x/y/manifests/latest: denied: access forbidden

2019-09-23 14:09:07.677  WARN 19341 --- [           main] o.t.containers.DockerComposeContainer    : Exception while pulling images, using local images if available

org.testcontainers.containers.ContainerLaunchException: Container startup failed
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:290) ~[testcontainers-1.12.0.jar:na]
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:272) ~[testcontainers-1.12.0.jar:na]
	at org.testcontainers.containers.ContainerisedDockerCompose.invoke(DockerComposeContainer.java:610) ~[testcontainers-1.12.0.jar:na]
	at org.testcontainers.containers.DockerComposeContainer.runWithCompose(DockerComposeContainer.java:230) ~[testcontainers-1.12.0.jar:na]
	at org.testcontainers.containers.DockerComposeContainer.pullImages(DockerComposeContainer.java:163) ~[testcontainers-1.12.0.jar:na]
	at org.testcontainers.containers.DockerComposeContainer.start(DockerComposeContainer.java:150) ~[testcontainers-1.12.0.jar:na]
	at com.my.company.TestContext.<clinit>(TestContext.java:47) ~[test-classes/:na]
	at java.base/java.lang.Class.forName0(Native Method) ~[na:na]
	at java.base/java.lang.Class.forName(Class.java:398) ~[na:na]
	at org.springframework.cglib.core.ReflectUtils.defineClass(ReflectUtils.java:537) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.AbstractClassGenerator.generate(AbstractClassGenerator.java:359) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.proxy.Enhancer.generate(Enhancer.java:582) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.AbstractClassGenerator$ClassLoaderData$3.apply(AbstractClassGenerator.java:106) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.AbstractClassGenerator$ClassLoaderData$3.apply(AbstractClassGenerator.java:104) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.internal.LoadingCache$2.call(LoadingCache.java:54) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
	at org.springframework.cglib.core.internal.LoadingCache.createEntry(LoadingCache.java:61) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.internal.LoadingCache.get(LoadingCache.java:34) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.AbstractClassGenerator$ClassLoaderData.get(AbstractClassGenerator.java:130) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.core.AbstractClassGenerator.create(AbstractClassGenerator.java:315) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.proxy.Enhancer.createHelper(Enhancer.java:569) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.cglib.proxy.Enhancer.createClass(Enhancer.java:416) ~[spring-core-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.annotation.ConfigurationClassEnhancer.createClass(ConfigurationClassEnhancer.java:137) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.annotation.ConfigurationClassEnhancer.enhance(ConfigurationClassEnhancer.java:109) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.annotation.ConfigurationClassPostProcessor.enhanceConfigurationClasses(ConfigurationClassPostProcessor.java:402) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.annotation.ConfigurationClassPostProcessor.postProcessBeanFactory(ConfigurationClassPostProcessor.java:253) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanFactoryPostProcessors(PostProcessorRegistrationDelegate.java:286) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanFactoryPostProcessors(PostProcessorRegistrationDelegate.java:130) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.invokeBeanFactoryPostProcessors(AbstractApplicationContext.java:691) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:528) ~[spring-context-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:142) ~[spring-boot-2.1.1.RELEASE.jar:2.1.1.RELEASE]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:775) ~[spring-boot-2.1.1.RELEASE.jar:2.1.1.RELEASE]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:397) ~[spring-boot-2.1.1.RELEASE.jar:2.1.1.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:316) ~[spring-boot-2.1.1.RELEASE.jar:2.1.1.RELEASE]
	at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:127) ~[spring-boot-test-2.1.1.RELEASE.jar:2.1.1.RELEASE]
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:99) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:117) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:108) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:118) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:83) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener.prepareTestInstance(SpringBootDependencyInjectionTestExecutionListener.java:44) ~[spring-boot-test-autoconfigure-2.1.1.RELEASE.jar:2.1.1.RELEASE]
	at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:246) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:227) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:289) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) ~[junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:291) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:246) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:97) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) ~[junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363) ~[junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:190) ~[spring-test-5.1.3.RELEASE.jar:5.1.3.RELEASE]
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137) ~[junit-4.12.jar:4.12]
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) ~[junit-rt.jar:na]
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) ~[junit-rt.jar:na]
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) ~[junit-rt.jar:na]
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) ~[junit-rt.jar:na]
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88) ~[duct-tape-1.0.8.jar:na]
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:283) ~[testcontainers-1.12.0.jar:na]
	... 61 common frames omitted
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:350) ~[testcontainers-1.12.0.jar:na]
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:285) ~[testcontainers-1.12.0.jar:na]
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81) ~[duct-tape-1.0.8.jar:na]
	... 62 common frames omitted
Caused by: java.lang.IllegalStateException: Container did not start correctly.
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:328) ~[testcontainers-1.12.0.jar:na]
	... 64 common frames omitted

I have a local copy of this image

❯ docker pull my-company.com:4567/x/y
Using default tag: latest
latest: Pulling from x/y
Digest: sha256:dcdea6de09600666551792ed6ab2bcbd9b96d08fa3cc2446d6bf184d81ffce2c
Status: Image is up to date for my-company:4567/x/y:latest
my-company.com:4567/x/y:latest

I'm logged to the repo

❯ docker login my-company.com:4567
Authenticating with existing credentials...
Login Succeeded

~
❯ cat ~/.docker/config.json

{
	"auths": {
		"my-company.com:4567": {}
	},
	"HttpHeaders": {
		"User-Agent": "Docker-Client/19.03.2 (darwin)"
	},
	"credsStore": "desktop"
}

The image I'm tring to run is a MySQL

[mateuszjarzyna]

I've found more logs, more details. Now I think that there is a problem with docker compose

2019-09-23 14:40:01.842  INFO 19763 --- [           main] o.t.d.DockerClientProviderStrategy       : Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2019-09-23 14:40:02.941  INFO 19763 --- [           main] o.t.d.UnixSocketClientProviderStrategy   : Accessing docker with local Unix socket
2019-09-23 14:40:02.941  INFO 19763 --- [           main] o.t.d.DockerClientProviderStrategy       : Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
2019-09-23 14:40:03.132  INFO 19763 --- [           main] org.testcontainers.DockerClientFactory   : Docker host IP address is localhost
2019-09-23 14:40:03.202  INFO 19763 --- [           main] org.testcontainers.DockerClientFactory   : Connected to docker: 
  Server Version: 19.03.2
  API Version: 1.40
  Operating System: Docker Desktop
  Total Memory: 1999 MB
2019-09-23 14:40:03.576  INFO 19763 --- [           main] o.t.utility.RegistryAuthLocator          : Credential helper/store (docker-credential-desktop) does not have credentials for quay.io
2019-09-23 14:40:04.472  INFO 19763 --- [           main] org.testcontainers.DockerClientFactory   : Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
        ℹ︎ Checking the system...
        ✔ Docker version should be at least 1.6.0
        ✔ Docker environment should have more than 2GB free disk space
2019-09-23 14:40:04.876  INFO 19763 --- [           main] 🐳 [docker/compose:1.8.0]                : Creating container for image: docker/compose:1.8.0
2019-09-23 14:40:05.008  INFO 19763 --- [           main] o.t.utility.RegistryAuthLocator          : Credential helper/store (docker-credential-desktop) does not have credentials for index.docker.io
2019-09-23 14:40:05.159  INFO 19763 --- [           main] o.t.utility.RegistryAuthLocator          : Credential helper/store (docker-credential-desktop) does not have credentials for index.docker.io
2019-09-23 14:40:06.846  INFO 19763 --- [           main] 🐳 [docker/compose:1.8.0]                : Starting container with ID: 44add20ba8d40554703ea7864109d1a188a26847ce1014cb1cf44cb75e0a4c9b
2019-09-23 14:40:07.666  INFO 19763 --- [           main] 🐳 [docker/compose:1.8.0]                : Container docker/compose:1.8.0 is starting: 44add20ba8d40554703ea7864109d1a188a26847ce1014cb1cf44cb75e0a4c9b
2019-09-23 14:40:18.132 ERROR 19763 --- [           main] 🐳 [docker/compose:1.8.0]                : Could not start container

java.lang.IllegalStateException: Container did not start correctly.

[stigkj]

@mateuszjarzyna I think the problem is that TestContainers cannot find the credentials for your registry. It tries to read them from the ~/.docker/config.json file, but cannot find them there. This is because on OS X the credentials are not stored in this file but placed in the Keychain.

[stigkj]

It seems I'm mistaken here. When I look closer at your log it actually tries (and most likely succeeds) to read the credentials with the docker-credential-desktop program, so as you say it seems to be another problem than auth.

[mateuszjarzyna]

Yup, there was another issue. Testcontainers each time is creating new network and don't clean up. So some times I have to execute

❯ docker network prune
WARNING! This will remove all networks not used by at least one container.
Are you sure you want to continue? [y/N] y
Deleted Networks:
lpnc1nf8fcvm_default
xisc2cayfndu_default
aumxomhr5jgh_default
dijthujvtdgl_default
...

and remove unused networks.

But the original problem is still annoying. Sill Im getting the error

2019-10-24 06:53:25.296  INFO 70707 --- [           main] 🐳 [docker/compose:1.8.0]                : Container docker/compose:1.8.0 is starting: 2aa883ed29bfca0caa15e2fafa54ca62691a4fa639798a4c48c4d5e7ab68992d
2019-10-24 06:53:33.530 ERROR 70707 --- [           main] 🐳 [docker/compose:1.8.0]                : Could not start container

java.lang.IllegalStateException: Container did not start correctly.
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:328) ~[testcontainers-1.12.2.jar:na]
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:285) ~[testcontainers-1.12.2.jar:na]
...

2019-10-24 06:53:33.570 ERROR 70707 --- [           main] 🐳 [docker/compose:1.8.0]                : Log output from the failed container:
Pulling xxx-test-elastic (docker.elastic.co/elasticsearch/elasticsearch:6.6.0)...

6.6.0: Pulling from elasticsearch/elasticsearch

Digest: sha256:e9cba8dec2df88a1af911787f05cf5200a5d9d64e4517f64deb8bafc6e96176f

Status: Image is up to date for docker.elastic.co/elasticsearch/elasticsearch:6.6.0

Pulling xxx-test-mysql (mysql:8.0.13)...

8.0.13: Pulling from library/mysql

Pulling xxx-schema-flyway (xxx:4567/xxx/xxx:latest)...

Digest: sha256:196c04e1944c5e4ea3ab86ae5f78f697cf18ee43865f25e334a6ffb1dbea81e6

Status: Image is up to date for mysql:8.0.13

Get https://xxx:4567/v2/xxx/xxx/manifests/latest: denied: access forbidden

2019-10-24 06:53:33.572  WARN 70707 --- [           main] o.t.containers.DockerComposeContainer    : Exception while pulling images, using local images if available

org.testcontainers.containers.ContainerLaunchException: Container startup failed
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:290) ~[testcontainers-1.12.2.jar:na]
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:272) ~[testcontainers-1.12.2.jar:na]
...
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:350) ~[testcontainers-1.12.2.jar:na]
...
Caused by: java.lang.IllegalStateException: Container did not start correctly.
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:328) ~[testcontainers-1.12.2.jar:na]
	... 65 common frames omitted

2019-10-24 06:53:33.575  INFO 70707 --- [           main] 🐳 [docker/compose:1.8.0]                : Creating container for image: docker/compose:1.8.0
2019-10-24 06:53:33.608  INFO 70707 --- [           main] o.t.utility.RegistryAuthLocator          : Credential helper/store (docker-credential-osxkeychain) does not have credentials for index.docker.io
2019-10-24 06:53:33.734  INFO 70707 --- [           main] 🐳 [docker/compose:1.8.0]                : Starting container with ID: e2bf0400dd89084daa5115ef2ce92f38a740b5f35d8cbb0590665e957ef7476e

And I have to manually execute docker pull ....
The file ~/.docker/config.json exist and it seems that docker container knows how to read mac os keychain because one line in the log says Credential helper/store (docker-credential-osxkeychain) does not have credentials for index.docker.io

[bsideup]

@mateuszjarzyna

FYI this sounds like #1767

Another good reason to not use Docker Compose, actually 😅

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you believe this is a mistake, please reply to this comment to keep it open. If there isn't one already, a PR to fix or at least reproduce the problem in a test case will always help us get back on track to tackle this.

[rnorth]

#2201 should resolve all authenticated pull-related problems with docker-compose

[rnorth]

Docker Compose authenticated image support was released in https://github.com/testcontainers/testcontainers-java/releases/tag/1.14.0. I believe this resolves the issue, so I'll close this ticket.